NetworkManager reports disconnect/reconnect many times a day

Sat Dec 5 19:55:10 UTC 2020

** Reply to message from Paul Smith <paul at mad-scientist.net> on Sat, 05 Dec
2020 13:53:05 -0500

> I am seeing a behavior of NetworkManager where it reports that it is
> disconnecting for a few seconds then reconnecting, multiple times a day
> (once every few hours).  However, it's not ACTUALLY disconnected.
> 
> I'm using Ubuntu 20.04.
> 
> I have a WIRED connection; this is not wifi.
> 
> My little LAN icon on the control panel goes to a "?" then comes back,
> and my Spotify app goes dim then comes back.
> 
> I do a lot of remote work, including a VPN and SSH to remote systems,
> and at no time do I notice any lag in typing etc. even when the above
> happens.  So, in some ways this is not a real problem (and in fact I've
> lived with it for quite a while).
> 
> But, a bunch of our wireless devices DO lose connection multiple times
> a day although I can't say if it's the same times or not.  I don't know
> if this is related: it obviously could be completely different things
> but I thought I'd start with the simpler-to-debug problem.
> 
> I enabled DEBUG logging for NetworkManager and whenever this happens I
> get output like this in journalctl:
> 
> Dec 05 05:55:01 NetworkManager[968]: <debug> [1607165701.8724] connectivity:
> (enx106530e29458,IPv4,38386) start request to
> 'http://connectivity-check.ubuntu.com/' (try resolving
> 'connectivity-check.ubuntu.com' using systemd-resolved)
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.7958] connectivity:
> (enx106530e29458,IPv4,38386) check completed: LIMITED; timeout
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.7959]
> device[7d9e8e19a7fc97e0] (enx106530e29458): connectivity state changed from
> FULL to LIMITED
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.7963] manager: connectivity checking indicates LIMITED
> Dec 05 05:55:21 NetworkManager[968]: <info>  [1607165721.7964] manager:
> NetworkManager state is now CONNECTED_SITE
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.7974] dispatcher:
> (760) dispatching action 'connectivity-change'
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.7980]
> device[7d9e8e19a7fc97e0] (enx106530e29458): ip4-config: update (commit=1,
> new-config=0x55e94d2649c0)
> 
> then there's a bunch of debug about state change then I see:
> 
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.8005] dns-mgr:
> (device_ip_config_changed): no DNS changes to commit (0)
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.8006] connectivity:
> (enx106530e29458,IPv4,38393) start request to
> 'http://connectivity-check.ubuntu.com/' (try resolving
> 'connectivity-check.ubuntu.com' using systemd-resolved)
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.8007]
> device[7d9e8e19a7fc97e0] (enx106530e29458): ip4-config: update (commit=0,
> new-config=0x55e94d2649c0)
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.8294] dispatcher:
> (760) /etc/NetworkManager/dispatcher.d/01-ifupdown succeeded
> Dec 05 05:55:21 NetworkManager[968]: <debug> [1607165721.8294] dispatcher:
> (760) /etc/NetworkManager/dispatcher.d/99-disable-wireless-when-wired succeeded
> Dec 05 05:55:22 NetworkManager[968]: <debug> [1607165722.7972] connectivity:
> (enx106530e29458,IPv4,38394) start request to
> 'http://connectivity-check.ubuntu.com/' (try resolving
> 'connectivity-check.ubuntu.com' using systemd-resolved)
> Dec 05 05:55:23 NetworkManager[968]: <debug> [1607165723.1788] connectivity:
> (enx106530e29458,IPv4,38394) check completed: FULL; status header found
> Dec 05 05:55:23 NetworkManager[968]: <debug> [1607165723.1789]
> device[7d9e8e19a7fc97e0] (enx106530e29458): connectivity state changed from
> LIMITED to FULL
> Dec 05 05:55:23 NetworkManager[968]: <debug> [1607165723.1791] manager: connectivity checking indicates FULL
> Dec 05 05:55:23 NetworkManager[968]: <info>  [1607165723.1791] manager:
> NetworkManager state is now CONNECTED_GLOBAL
> Dec 05 05:55:23 NetworkManager[968]: <debug> [1607165723.1796] dispatcher:
> (761) dispatching action 'connectivity-change'
> 
> and my icon shows connected again.
> 
> It looks like checks to connectivity-check.ubuntu.com sometimes fail.
>  I don't know if that's because my network is not allowing new
> connections or something weird like that (as I said I haven't noticed
> any hangs while typing in remote sessions), or if there's a DNS issue,
> or if this Ubuntu server is too busy and doesn't always respond, or
> what it is.
> 
> Has anyone else noticed this?  If you run:
> 
>   journalct --unit NetworkManager --since yesterday
> 
> do you see the CONNECTED_SITE / CONNECTED_GLOBAL messages (these are
> the only ones printed at "INFO" level which is the default log level)
> appear randomly / not when you expect your network connection to go
> down?  If lots of people are seeing it then it's most likely an Ubuntu
> server problem.
> 
> Does anyone know if there's a way to get more details from
> NetworkManager about exactly what kind of failure it detected?  Does
> "timedout" mean a 408 timeout?  A 504 timeout?  Something else?
> 

The only network problem I have seen is my email application retrieves email
every 5 minutes and very occassionally it fails to retrieve the email, 5
minutes later it does retrieve the email.

Here is what I see in my journal, shortly followed by the CONNECTED_GLOBAL. 
(the computer is powered down at night)

robert at MARS:~$ journalctl --unit NetworkManager --since yesterday | grep
CONNECTED_SITE
Dec 04 08:29:43 MARS NetworkManager[1019]: <info>  [1607099383.1578] manager:
NetworkManager state is now CONNECTED_SITE
Dec 04 08:45:02 MARS NetworkManager[1019]: <info>  [1607100302.9002] manager:
NetworkManager state is now CONNECTED_SITE
Dec 04 08:50:23 MARS NetworkManager[1019]: <info>  [1607100623.9001] manager:
NetworkManager state is now CONNECTED_SITE
Dec 04 09:05:44 MARS NetworkManager[1019]: <info>  [1607101544.9001] manager:
NetworkManager state is now CONNECTED_SITE
Dec 04 18:56:04 MARS NetworkManager[1019]: <info>  [1607136964.8995] manager:
NetworkManager state is now CONNECTED_SITE
Dec 04 21:21:25 MARS NetworkManager[1019]: <info>  [1607145685.9024] manager:
NetworkManager state is now CONNECTED_SITE
Dec 04 23:01:45 MARS NetworkManager[1019]: <info>  [1607151705.8997] manager:
NetworkManager state is now CONNECTED_SITE
Dec 05 07:42:25 MARS NetworkManager[1007]: <info>  [1607182945.6846] manager:
NetworkManager state is now CONNECTED_SITE
Dec 05 09:22:46 MARS NetworkManager[1007]: <info>  [1607188966.6567] manager:
NetworkManager state is now CONNECTED_SITE
Dec 05 09:38:06 MARS NetworkManager[1007]: <info>  [1607189886.6569] manager:
NetworkManager state is now CONNECTED_SITE
Dec 05 10:38:41 MARS NetworkManager[974]: <info>  [1607193521.7140] manager:
NetworkManager state is now CONNECTED_SITE
Dec 05 11:29:02 MARS NetworkManager[974]: <info>  [1607196542.6839] manager:
NetworkManager state is now CONNECTED_SITE

-- 
Robert Blair

My choices in life were either to be a piano player in a whore house or a politician. And to tell the truth, there's hardly any difference!  -- Harry Truman