search

elementary / switchboard-plug-network

Switchboard Network Plug
GNU General Public License v3.0
20 stars 23 forks source link

Network settings panel keeps reconnecting wired network #326

Closed andrewdbate closed 2 years ago

andrewdbate commented 2 years ago

What Happened?

The Network settings panel keeps reconnecting to the wired network whenever the window is open.

This causes multiple issues which I describe below. I am certain the root cause of these is the same (the Network settings panel keeps reconnecting) hence opening a single ticket.

  1. You cannot disconnect from the wired network from within the Network setting panel. This is because the Network settings panel will reconnect. See the attached video:

https://user-images.githubusercontent.com/2998569/142947605-ca731945-7970-4425-8bcd-c4eb7442de29.mp4

  1. When the Network setting panel is open, you cannot disconnect from the wired network using the wingpanel. This is again because the Network settings panel will reconnect. See the attached video.

In the video: Ping is running in the background to show when the network is connected. First, I show that disconnecting from the wired network using the wingpanel works as expected (i.e., the icon shows as disconnected and ping reports the network is unreachable). Then (at the 30 sec mark) I open the Network settings panel and leave it open. Then I show that you cannot disconnect from the wired network using the wingpanel because the Network settings panel immediately reconnects again.

https://user-images.githubusercontent.com/2998569/142947621-1a8b5bd0-99d9-4967-a365-00f07fb031ce.mp4

  1. You cannot reconnect to the wired network after disabling Airplane Mode until the Network settings panel is closed. This is once again because the Network settings panel will reconnect, over and over. See attached video.

In the video: First, I show that disconnecting from the wired network using the wingpanel works as expected (i.e., the icon shows as disconnected and ping reports the network is unreachable). At 30 secs, I open the Network settings panel and then toggle on Airplane Mode. This works as expected. Then at 42 secs, I toggle off Airplane mode. The Network settings panel then keeps connecting, disconnecting, and then reconnecting again. The output from ping shows that occasionally we are briefly connected (because ping gets a reply) before the next reconnect attempt causes the network to disconnect.

At 1:08, I then close the Network settings panel, at which point the network connects permanently and no more packets are dropped.

https://user-images.githubusercontent.com/2998569/142947349-ad8672f2-fc2f-4a5c-9a82-074318e45c2c.mp4

This issue appears to be related to https://github.com/elementary/switchboard-plug-network/issues/312 (perhaps the underlying cause is the same).

Steps to Reproduce

The above videos show the steps to reproduce.

Expected Behavior

The Network settings panel should only attempt to connect to the wired network when the option is toggled or Airplane Mode is toggled off.

I would also expect the toggle shown for the wired network in the Network settings panel to be in the same state as the toggle for the wired network in the wingpanel (i.e., either both show as connected or both show as disconnected).

OS Version

6.x (Odin)

Software Version

Latest release (I have run all updates)

Log Output

Here is the output from journalctl -u NetworkManager -f after I toggle off the Airplane Mode to reconnect to the network (see item 3 above).

The relevant lines appear to be these:

Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8555] manager: NetworkManager state is now DISCONNECTING
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8563] device (ens33): disconnecting for new activation request.

It appears that the new connection/activation request is what causes the network to repeatedly drop.

Here is the log:

-- Logs begin at Wed 2021-11-10 18:29:54 UTC. --
Nov 22 23:24:05 elvm NetworkManager[597]: <info>  [1637623445.3644] manager: NetworkManager state is now CONNECTED_GLOBAL
Nov 22 23:24:09 elvm NetworkManager[597]: <info>  [1637623449.6822] manager: disable requested (sleeping: no  enabled: yes)
Nov 22 23:24:09 elvm NetworkManager[597]: <info>  [1637623449.6823] manager: NetworkManager state is now ASLEEP
Nov 22 23:24:09 elvm NetworkManager[597]: <info>  [1637623449.6832] audit: op="networking-control" arg="off" pid=3090 uid=1000 result="success"
Nov 22 23:24:09 elvm NetworkManager[597]: <info>  [1637623449.6833] device (ens33): state change: activated -> deactivating (reason 'sleeping', sys-iface-state: 'managed')
Nov 22 23:24:09 elvm NetworkManager[597]: <info>  [1637623449.7091] device (ens33): state change: deactivating -> disconnected (reason 'sleeping', sys-iface-state: 'managed')
Nov 22 23:24:09 elvm NetworkManager[597]: <info>  [1637623449.7442] dhcp4 (ens33): canceled DHCP transaction
Nov 22 23:24:09 elvm NetworkManager[597]: <info>  [1637623449.7443] dhcp4 (ens33): state changed bound -> done
Nov 22 23:24:09 elvm NetworkManager[597]: <info>  [1637623449.7480] device (ens33): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Nov 22 23:24:14 elvm NetworkManager[597]: <info>  [1637623454.7614] audit: op="connection-activate" uuid="b0785df3-ac09-3226-954f-5b05617fda80" name="Wired connection 1" pid=3090 uid=1000 result="fail" reason="Connection 'Wired connection 1' is not available on device ens33 because device is strictly unmanaged"
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.7817] manager: enable requested (sleeping: no  enabled: no)
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.7818] device (ens33): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8085] manager: NetworkManager state is now DISCONNECTED
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8098] audit: op="networking-control" arg="on" pid=3090 uid=1000 result="success"
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8104] device (ens33): carrier: link connected
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8127] device (ens33): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8199] policy: auto-activating connection 'Wired connection 1' (b0785df3-ac09-3226-954f-5b05617fda80)
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8206] device (ens33): Activation: starting connection 'Wired connection 1' (b0785df3-ac09-3226-954f-5b05617fda80)
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8208] device (ens33): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8217] manager: NetworkManager state is now CONNECTING
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8223] device (ens33): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8250] device (ens33): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8255] dhcp4 (ens33): activation: beginning transaction (timeout in 45 seconds)
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8402] dhcp4 (ens33): option dhcp_lease_time      => '1800'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8402] dhcp4 (ens33): option domain_name          => 'localdomain'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8402] dhcp4 (ens33): option domain_name_servers  => '192.168.80.2'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option expiry               => '1637625261'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option ip_address           => '192.168.80.136'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option next_server          => '192.168.80.254'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_broadcast_address => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_domain_name => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_domain_name_servers => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_domain_search => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_host_name  => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_interface_mtu => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_ms_classless_static_routes => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_nis_domain => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8403] dhcp4 (ens33): option requested_nis_servers => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option requested_ntp_servers => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option requested_rfc3442_classless_static_routes => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option requested_root_path  => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option requested_routers    => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option requested_static_routes => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option requested_subnet_mask => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option requested_time_offset => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option requested_wpad       => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option routers              => '192.168.80.2'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): option subnet_mask          => '255.255.255.0'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8404] dhcp4 (ens33): state changed unknown -> bound
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8455] device (ens33): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8552] device (ens33): state change: ip-check -> deactivating (reason 'new-activation', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8555] manager: NetworkManager state is now DISCONNECTING
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8563] device (ens33): disconnecting for new activation request.
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8564] audit: op="connection-activate" uuid="b0785df3-ac09-3226-954f-5b05617fda80" name="Wired connection 1" pid=3090 uid=1000 result="success"
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8667] device (ens33): state change: deactivating -> disconnected (reason 'new-activation', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8883] dhcp4 (ens33): canceled DHCP transaction
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8884] dhcp4 (ens33): state changed bound -> done
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8898] manager: NetworkManager state is now DISCONNECTED
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8900] device (ens33): Activation: starting connection 'Wired connection 1' (b0785df3-ac09-3226-954f-5b05617fda80)
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8911] device (ens33): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8913] manager: NetworkManager state is now CONNECTING
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8915] device (ens33): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8977] device (ens33): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.8984] dhcp4 (ens33): activation: beginning transaction (timeout in 45 seconds)
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9174] dhcp4 (ens33): option dhcp_lease_time      => '1800'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9175] dhcp4 (ens33): option domain_name          => 'localdomain'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9176] dhcp4 (ens33): option domain_name_servers  => '192.168.80.2'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9176] dhcp4 (ens33): option expiry               => '1637625261'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9176] dhcp4 (ens33): option ip_address           => '192.168.80.136'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9176] dhcp4 (ens33): option next_server          => '192.168.80.254'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9176] dhcp4 (ens33): option requested_broadcast_address => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9176] dhcp4 (ens33): option requested_domain_name => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9177] dhcp4 (ens33): option requested_domain_name_servers => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9177] dhcp4 (ens33): option requested_domain_search => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9177] dhcp4 (ens33): option requested_host_name  => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9177] dhcp4 (ens33): option requested_interface_mtu => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9177] dhcp4 (ens33): option requested_ms_classless_static_routes => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9177] dhcp4 (ens33): option requested_nis_domain => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9177] dhcp4 (ens33): option requested_nis_servers => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9177] dhcp4 (ens33): option requested_ntp_servers => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9178] dhcp4 (ens33): option requested_rfc3442_classless_static_routes => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9178] dhcp4 (ens33): option requested_root_path  => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9178] dhcp4 (ens33): option requested_routers    => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9178] dhcp4 (ens33): option requested_static_routes => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9178] dhcp4 (ens33): option requested_subnet_mask => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9178] dhcp4 (ens33): option requested_time_offset => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9178] dhcp4 (ens33): option requested_wpad       => '1'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9179] dhcp4 (ens33): option routers              => '192.168.80.2'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9179] dhcp4 (ens33): option subnet_mask          => '255.255.255.0'
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9179] dhcp4 (ens33): state changed unknown -> bound
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9227] device (ens33): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9254] device (ens33): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9273] device (ens33): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9303] manager: NetworkManager state is now CONNECTED_LOCAL
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9311] manager: NetworkManager state is now CONNECTED_SITE
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9312] policy: set 'Wired connection 1' (ens33) as default for IPv4 routing and DNS
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9320] device (ens33): Activation: successful, device activated.
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9329] device (ens33): state change: activated -> deactivating (reason 'new-activation', sys-iface-state: 'managed')
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9331] manager: NetworkManager state is now DISCONNECTING
Nov 22 23:24:21 elvm NetworkManager[597]: <info>  [1637623461.9345] device (ens33): disconnecting for new activation request.

Hardware Info

The above reproduces on multiple computers (two laptops, a desktop, and a virtual machine).