Ubuntu
network-manager package

NetworkManager fails to reconfigure the interface if the link is broken for a short time

Bug #894082 reported by Jan Zacharias on 2011-11-23

This bug affects 3 people

Affects		Status	Importance	Assigned to	Milestone
	network-manager (Ubuntu)	Triaged	Medium	Mathieu Trudel-Lapierre

Bug Description

1) The release of Ubuntu you are using: Ubuntu 11.10 (Linux raw 3.0.0-13-generic #22-Ubuntu SMP Wed Nov 2 13:27:26 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux)

2) The version of the package you are using: network-manager 0.9.1.90-0ubuntu5

3) What you expected to happen: Network-manager should behave as it does when the interruption takes longer than ~5 seconds

4) What happened instead: The connection is not re-established properly, the network-manager icon does not react to the interruption at all and the state of "connectivity" is displayed wrong!

5) How to repeat:
      Prerequisites: You have a wired network that requires authentification (802.1x), the connection is set to "Connect automatically" and the password is already stored.
      Step1: You connect the network cable, you get network access
      Step2: You disconnect the network cable
      Step3: You wait one second and connect the network cable again
      Step4: You do not get network access, wpa_supplicant is broken as well (https://bugs.launchpad.net/ubuntu/+source/wpasupplicant/+bug/610084) however network-manager could also work around this by behaving as desired

6) Syslog: (steps indicated)

---------------Step1
Nov 23 17:33:37 raw NetworkManager[7084]: <info> (eth0): carrier now ON (device state 20)
Nov 23 17:33:37 raw NetworkManager[7084]: <info> (eth0): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Auto-activating connection '192.168.0.100 dot1x'.
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Activation (eth0) starting connection '192.168.0.100 dot1x'
Nov 23 17:33:37 raw NetworkManager[7084]: <info> (eth0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Nov 23 17:33:37 raw NetworkManager[7084]: <info> (eth0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Activation (eth0/wired): connection '192.168.0.100 dot1x' requires no security. No secrets needed.
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Nov 23 17:33:37 raw kernel: [21433.047002] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
Nov 23 17:33:37 raw kernel: [21433.047769] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Nov 23 17:33:37 raw NetworkManager[7084]: <info> (eth0): supplicant interface state: starting -> ready
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Config: added 'password' value '<omitted>'
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Config: added 'key_mgmt' value 'IEEE8021X'
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Config: added 'eapol_flags' value '0'
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Config: added 'eap' value 'PEAP'
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Config: added 'fragment_size' value '1300'
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Config: added 'phase2' value 'auth=MSCHAPV2'
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Config: added 'identity' value 'username'
Nov 23 17:33:37 raw NetworkManager[7084]: <info> (eth0): supplicant interface state: ready -> inactive
Nov 23 17:33:37 raw NetworkManager[7084]: <info> Config: set interface ap_scan to 0
Nov 23 17:33:37 raw wpa_supplicant[1332]: Associated with 01:80:c2:00:00:03
Nov 23 17:33:37 raw NetworkManager[7084]: <info> (eth0): supplicant interface state: inactive -> associated
Nov 23 17:33:37 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-STARTED EAP authentication started
Nov 23 17:33:37 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Nov 23 17:33:37 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
Nov 23 17:33:37 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=DE/O=T-Systems International GmbH/OU=Trust Center Services/CN=TeleSec ServerPass CA 1'
Nov 23 17:33:37 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=DE/O=T-Systems International GmbH/OU=Trust Center Services/CN=TeleSec ServerPass CA 1'
Nov 23 17:33:37 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=DE/O=Weyland-Yutani CORP/OU=Administation/ST=Rheinland-Pfalz, Saarland, Bremen/L=Kaiserslautern, Saarbruecken, <email address hidden>/CN=radius.weyland'
Nov 23 17:33:38 raw wpa_supplicant[1332]: EAP-MSCHAPV2: Authentication succeeded
Nov 23 17:33:38 raw wpa_supplicant[1332]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
Nov 23 17:33:39 raw avahi-daemon[799]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::221:ccff:fe69:9fff.
Nov 23 17:33:39 raw avahi-daemon[799]: New relevant interface eth0.IPv6 for mDNS.
Nov 23 17:33:39 raw avahi-daemon[799]: Registering new address record for fe80::221:ccff:fe69:9fff on eth0.*.
Nov 23 17:33:42 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Nov 23 17:33:42 raw wpa_supplicant[1332]: CTRL-EVENT-CONNECTED - Connection to 01:80:c2:00:00:03 completed (auth) [id=0 id_str=]
Nov 23 17:33:42 raw NetworkManager[7084]: <info> (eth0): supplicant interface state: associated -> completed
Nov 23 17:33:42 raw NetworkManager[7084]: <info> Activation (eth0/wired) Stage 2 of 5 (Device Configure) successful.
Nov 23 17:33:42 raw NetworkManager[7084]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Nov 23 17:33:42 raw NetworkManager[7084]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Nov 23 17:33:42 raw NetworkManager[7084]: <info> (eth0): device state change: config -> ip-config (reason 'none') [50 70 0]
Nov 23 17:33:42 raw NetworkManager[7084]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Nov 23 17:33:42 raw NetworkManager[7084]: <info> Activation (eth0) Beginning IP6 addrconf.
Nov 23 17:33:42 raw avahi-daemon[799]: Withdrawing address record for fe80::221:ccff:fe69:9fff on eth0.
Nov 23 17:33:42 raw avahi-daemon[799]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::221:ccff:fe69:9fff.
Nov 23 17:33:42 raw avahi-daemon[799]: Interface eth0.IPv6 no longer relevant for mDNS.
Nov 23 17:33:42 raw NetworkManager[7084]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Nov 23 17:33:42 raw NetworkManager[7084]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started...
Nov 23 17:33:42 raw NetworkManager[7084]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Nov 23 17:33:42 raw avahi-daemon[799]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.100.
Nov 23 17:33:42 raw avahi-daemon[799]: New relevant interface eth0.IPv4 for mDNS.
Nov 23 17:33:42 raw avahi-daemon[799]: Registering new address record for 192.168.0.100 on eth0.IPv4.
Nov 23 17:33:43 raw NetworkManager[7084]: <info> (eth0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Nov 23 17:33:43 raw NetworkManager[7084]: <info> Activation (eth0) successful, device activated.
Nov 23 17:33:43 raw NetworkManager[7084]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 23 17:33:43 raw NetworkManager[7084]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
Nov 23 17:33:43 raw dbus[655]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Nov 23 17:33:43 raw dbus[655]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 23 17:33:43 raw ntpdate[7121]: Can't find host ntp.ubuntu.com: Name or service not known (-2)
Nov 23 17:33:43 raw ntpdate[7121]: no servers can be used, exiting
Nov 23 17:33:44 raw avahi-daemon[799]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::221:ccff:fe69:9fff.
Nov 23 17:33:44 raw avahi-daemon[799]: New relevant interface eth0.IPv6 for mDNS.
Nov 23 17:33:44 raw avahi-daemon[799]: Registering new address record for fe80::221:ccff:fe69:9fff on eth0.*.
Nov 23 17:33:53 raw kernel: [21448.702772] eth0: no IPv6 routers present
Nov 23 17:34:03 raw NetworkManager[7084]: <info> (eth0): IP6 addrconf timed out or failed.
Nov 23 17:34:03 raw NetworkManager[7084]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) scheduled...
Nov 23 17:34:03 raw NetworkManager[7084]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) started...
Nov 23 17:34:03 raw NetworkManager[7084]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Nov 23 17:34:03 raw NetworkManager[7084]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 23 17:34:03 raw NetworkManager[7084]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) complete.
---------------Step2
Nov 23 17:35:10 raw NetworkManager[7084]: <info> (eth0): carrier now OFF (device state 100, deferring action for 4 seconds)
Nov 23 17:35:10 raw kernel: [21525.636708] e1000e: eth0 NIC Link is Down
---------------Step3
Nov 23 17:35:13 raw NetworkManager[7084]: <info> (eth0): carrier now ON (device state 100)
Nov 23 17:35:13 raw kernel: [21529.052138] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
Nov 23 17:35:13 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-STARTED EAP authentication started
Nov 23 17:35:13 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Nov 23 17:35:13 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
Nov 23 17:35:13 raw wpa_supplicant[1332]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
---------------Step4
Nov 23 17:36:13 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Nov 23 17:36:14 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-STARTED EAP authentication started
Nov 23 17:36:14 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Nov 23 17:36:14 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
Nov 23 17:36:14 raw wpa_supplicant[1332]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
Nov 23 17:37:13 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Nov 23 17:37:15 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-STARTED EAP authentication started
Nov 23 17:37:15 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Nov 23 17:37:15 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
Nov 23 17:37:15 raw wpa_supplicant[1332]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
.
.
.

7) Syslog: (steps indicated): How it behaves (and should behave in any cases) if the cable is pulled for more than ~5 seconds:

---------------Step1
Nov 23 18:08:22 raw NetworkManager[7643]: <info> (eth0): carrier now ON (device state 20)
Nov 23 18:08:22 raw NetworkManager[7643]: <info> (eth0): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Auto-activating connection '192.168.0.100 dot1x'.
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Activation (eth0) starting connection '192.168.0.100 dot1x'
Nov 23 18:08:22 raw NetworkManager[7643]: <info> (eth0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 23 18:08:22 raw kernel: [23514.746461] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
Nov 23 18:08:22 raw kernel: [23514.747231] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Nov 23 18:08:22 raw NetworkManager[7643]: <info> (eth0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Activation (eth0/wired): connection '192.168.0.100 dot1x' requires no security. No secrets needed.
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Nov 23 18:08:22 raw NetworkManager[7643]: <info> (eth0): supplicant interface state: starting -> ready
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Config: added 'password' value '<omitted>'
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Config: added 'key_mgmt' value 'IEEE8021X'
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Config: added 'eapol_flags' value '0'
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Config: added 'eap' value 'PEAP'
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Config: added 'fragment_size' value '1300'
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Config: added 'phase2' value 'auth=MSCHAPV2'
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Config: added 'identity' value 'username'
Nov 23 18:08:22 raw NetworkManager[7643]: <info> (eth0): supplicant interface state: ready -> inactive
Nov 23 18:08:22 raw NetworkManager[7643]: <info> Config: set interface ap_scan to 0
Nov 23 18:08:22 raw wpa_supplicant[1332]: Associated with 01:80:c2:00:00:03
Nov 23 18:08:22 raw NetworkManager[7643]: <info> (eth0): supplicant interface state: inactive -> associated
Nov 23 18:08:22 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-STARTED EAP authentication started
Nov 23 18:08:22 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Nov 23 18:08:22 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
Nov 23 18:08:22 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=DE/O=T-Systems International GmbH/OU=Trust Center Services/CN=TeleSec ServerPass CA 1'
Nov 23 18:08:22 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=DE/O=T-Systems International GmbH/OU=Trust Center Services/CN=TeleSec ServerPass CA 1'
Nov 23 18:08:22 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=DE/O=Weyland-Yutani CORP/OU=Administation/ST=Rheinland-Pfalz, Saarland, Bremen/L=Kaiserslautern, Saarbruecken, <email address hidden>/CN=radius.weyland'
Nov 23 18:08:23 raw wpa_supplicant[1332]: EAP-MSCHAPV2: Authentication succeeded
Nov 23 18:08:23 raw wpa_supplicant[1332]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
Nov 23 18:08:24 raw avahi-daemon[799]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::221:ccff:fe69:9fff.
Nov 23 18:08:24 raw avahi-daemon[799]: New relevant interface eth0.IPv6 for mDNS.
Nov 23 18:08:24 raw avahi-daemon[799]: Registering new address record for fe80::221:ccff:fe69:9fff on eth0.*.
Nov 23 18:08:27 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Nov 23 18:08:27 raw wpa_supplicant[1332]: CTRL-EVENT-CONNECTED - Connection to 01:80:c2:00:00:03 completed (auth) [id=0 id_str=]
Nov 23 18:08:27 raw NetworkManager[7643]: <info> (eth0): supplicant interface state: associated -> completed
Nov 23 18:08:27 raw NetworkManager[7643]: <info> Activation (eth0/wired) Stage 2 of 5 (Device Configure) successful.
Nov 23 18:08:27 raw NetworkManager[7643]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Nov 23 18:08:27 raw NetworkManager[7643]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Nov 23 18:08:27 raw NetworkManager[7643]: <info> (eth0): device state change: config -> ip-config (reason 'none') [50 70 0]
Nov 23 18:08:27 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Nov 23 18:08:27 raw NetworkManager[7643]: <info> Activation (eth0) Beginning IP6 addrconf.
Nov 23 18:08:27 raw avahi-daemon[799]: Withdrawing address record for fe80::221:ccff:fe69:9fff on eth0.
Nov 23 18:08:27 raw avahi-daemon[799]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::221:ccff:fe69:9fff.
Nov 23 18:08:27 raw avahi-daemon[799]: Interface eth0.IPv6 no longer relevant for mDNS.
Nov 23 18:08:27 raw NetworkManager[7643]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Nov 23 18:08:27 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started...
Nov 23 18:08:27 raw NetworkManager[7643]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Nov 23 18:08:27 raw avahi-daemon[799]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.100.
Nov 23 18:08:27 raw avahi-daemon[799]: New relevant interface eth0.IPv4 for mDNS.
Nov 23 18:08:27 raw avahi-daemon[799]: Registering new address record for 192.168.0.100 on eth0.IPv4.
Nov 23 18:08:28 raw NetworkManager[7643]: <info> (eth0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Nov 23 18:08:28 raw NetworkManager[7643]: <info> Activation (eth0) successful, device activated.
Nov 23 18:08:28 raw NetworkManager[7643]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 23 18:08:28 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
Nov 23 18:08:28 raw dbus[655]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Nov 23 18:08:28 raw dbus[655]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 23 18:08:28 raw ntpdate[7677]: Can't find host ntp.ubuntu.com: Name or service not known (-2)
Nov 23 18:08:28 raw ntpdate[7677]: no servers can be used, exiting
Nov 23 18:08:29 raw avahi-daemon[799]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::221:ccff:fe69:9fff.
Nov 23 18:08:29 raw avahi-daemon[799]: New relevant interface eth0.IPv6 for mDNS.
Nov 23 18:08:29 raw avahi-daemon[799]: Registering new address record for fe80::221:ccff:fe69:9fff on eth0.*.
Nov 23 18:08:38 raw kernel: [23530.949386] eth0: no IPv6 routers present
Nov 23 18:08:48 raw NetworkManager[7643]: <info> (eth0): IP6 addrconf timed out or failed.
Nov 23 18:08:48 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) scheduled...
Nov 23 18:08:48 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) started...
Nov 23 18:08:48 raw NetworkManager[7643]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Nov 23 18:08:48 raw NetworkManager[7643]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 23 18:08:48 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) complete.
---------------Step2
Nov 23 18:09:29 raw NetworkManager[7643]: <info> (eth0): carrier now OFF (device state 100, deferring action for 4 seconds)
Nov 23 18:09:29 raw kernel: [23581.766202] e1000e: eth0 NIC Link is Down
Nov 23 18:09:33 raw NetworkManager[7643]: <info> (eth0): device state change: activated -> unavailable (reason 'carrier-changed') [100 20 40]
Nov 23 18:09:33 raw NetworkManager[7643]: <info> (eth0): deactivating device (reason 'carrier-changed') [40]
Nov 23 18:09:33 raw avahi-daemon[799]: Withdrawing address record for 192.168.0.100 on eth0.
Nov 23 18:09:33 raw avahi-daemon[799]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.0.100.
Nov 23 18:09:33 raw avahi-daemon[799]: Interface eth0.IPv4 no longer relevant for mDNS.
Nov 23 18:09:33 raw dbus[655]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Nov 23 18:09:33 raw dbus[655]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
---------------Step3
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): carrier now ON (device state 20)
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Auto-activating connection '192.168.0.100 dot1x'.
Nov 23 18:09:39 raw kernel: [23592.127293] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) starting connection '192.168.0.100 dot1x'
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0/wired): connection '192.168.0.100 dot1x' has security, but secrets are required.
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): device state change: config -> need-auth (reason 'none') [50 60 0]
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0/wired): connection '192.168.0.100 dot1x' requires no security. No secrets needed.
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): supplicant interface state: starting -> ready
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Config: added 'password' value '<omitted>'
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Config: added 'key_mgmt' value 'IEEE8021X'
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Config: added 'eapol_flags' value '0'
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Config: added 'eap' value 'PEAP'
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Config: added 'fragment_size' value '1300'
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Config: added 'phase2' value 'auth=MSCHAPV2'
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Config: added 'identity' value 'username'
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): supplicant interface state: ready -> inactive
Nov 23 18:09:39 raw NetworkManager[7643]: <info> Config: set interface ap_scan to 0
Nov 23 18:09:39 raw wpa_supplicant[1332]: Associated with 01:80:c2:00:00:03
Nov 23 18:09:39 raw NetworkManager[7643]: <info> (eth0): supplicant interface state: inactive -> associated
Nov 23 18:09:39 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-STARTED EAP authentication started
Nov 23 18:09:39 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Nov 23 18:09:39 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
Nov 23 18:09:40 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=DE/O=T-Systems International GmbH/OU=Trust Center Services/CN=TeleSec ServerPass CA 1'
Nov 23 18:09:40 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=DE/O=T-Systems International GmbH/OU=Trust Center Services/CN=TeleSec ServerPass CA 1'
Nov 23 18:09:40 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=DE/O=Weyland-Yutani CORP/OU=Administation/ST=Rheinland-Pfalz, Saarland, Bremen/L=Kaiserslautern, Saarbruecken, <email address hidden>/CN=radius.weyland'
Nov 23 18:09:41 raw wpa_supplicant[1332]: EAP-MSCHAPV2: Authentication succeeded
Nov 23 18:09:41 raw wpa_supplicant[1332]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
Nov 23 18:09:45 raw wpa_supplicant[1332]: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Nov 23 18:09:45 raw wpa_supplicant[1332]: CTRL-EVENT-CONNECTED - Connection to 01:80:c2:00:00:03 completed (auth) [id=0 id_str=]
Nov 23 18:09:45 raw NetworkManager[7643]: <info> (eth0): supplicant interface state: associated -> completed
Nov 23 18:09:45 raw NetworkManager[7643]: <info> Activation (eth0/wired) Stage 2 of 5 (Device Configure) successful.
Nov 23 18:09:45 raw NetworkManager[7643]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Nov 23 18:09:45 raw NetworkManager[7643]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Nov 23 18:09:45 raw NetworkManager[7643]: <info> (eth0): device state change: config -> ip-config (reason 'none') [50 70 0]
Nov 23 18:09:45 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Nov 23 18:09:45 raw NetworkManager[7643]: <info> Activation (eth0) Beginning IP6 addrconf.
Nov 23 18:09:45 raw avahi-daemon[799]: Withdrawing address record for fe80::221:ccff:fe69:9fff on eth0.
Nov 23 18:09:45 raw avahi-daemon[799]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::221:ccff:fe69:9fff.
Nov 23 18:09:45 raw avahi-daemon[799]: Interface eth0.IPv6 no longer relevant for mDNS.
Nov 23 18:09:45 raw NetworkManager[7643]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Nov 23 18:09:45 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started...
Nov 23 18:09:45 raw NetworkManager[7643]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Nov 23 18:09:45 raw avahi-daemon[799]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.100.
Nov 23 18:09:45 raw avahi-daemon[799]: New relevant interface eth0.IPv4 for mDNS.
Nov 23 18:09:45 raw avahi-daemon[799]: Registering new address record for 192.168.0.100 on eth0.IPv4.
Nov 23 18:09:46 raw NetworkManager[7643]: <info> (eth0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Nov 23 18:09:46 raw NetworkManager[7643]: <info> Activation (eth0) successful, device activated.
Nov 23 18:09:46 raw NetworkManager[7643]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 23 18:09:46 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
Nov 23 18:09:46 raw dbus[655]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Nov 23 18:09:46 raw dbus[655]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 23 18:09:46 raw ntpdate[7735]: Can't find host ntp.ubuntu.com: Name or service not known (-2)
Nov 23 18:09:46 raw ntpdate[7735]: no servers can be used, exiting
Nov 23 18:09:47 raw avahi-daemon[799]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::221:ccff:fe69:9fff.
Nov 23 18:09:47 raw avahi-daemon[799]: New relevant interface eth0.IPv6 for mDNS.
Nov 23 18:09:47 raw avahi-daemon[799]: Registering new address record for fe80::221:ccff:fe69:9fff on eth0.*.
Nov 23 18:09:56 raw kernel: [23608.458006] eth0: no IPv6 routers present
Nov 23 18:10:05 raw NetworkManager[7643]: <info> (eth0): IP6 addrconf timed out or failed.
Nov 23 18:10:05 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) scheduled...
Nov 23 18:10:05 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) started...
Nov 23 18:10:05 raw NetworkManager[7643]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Nov 23 18:10:05 raw NetworkManager[7643]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 23 18:10:05 raw NetworkManager[7643]: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Timeout) complete.

See original description

Tags:

Jan Zacharias (janz) on 2011-11-23

description:

updated

Revision history for this message

Steve Thunder (s-thunder) wrote on 2011-11-24:

I can confirm this bug, it's quite annoying and not limited to 802.1x (I dont't even know exactly what that is).
Where I work we have several networks and to switch between them I need to plug my network cord into a different network socket.

So I have my "main" network set to connect automatically and the others need to be selected manually.
When I worked on one of the "other" networks and want to change back to the "main" network I need to
wait for some seconds until networkmanager "recognizes" the unplug. Else networkmanager won't do the
autoconnect to the "main" network and still "thinks" that it's connected to the old network and hence does not
change any of the IP settings and stuff.

Revision history for this message

Launchpad Janitor (janitor) wrote on 2011-11-24:

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in network-manager (Ubuntu):
status:	New → Confirmed

Revision history for this message

Jan Zacharias (janz) wrote on 2011-11-24:

I think this bug was meant as a "feature":

NetworkManager[7084]: <info> (eth0): carrier now OFF (device state 100, deferring action for 4 seconds)

So I quickly checked with the sources of network manager and set_carrier function in nm-device-ethernet.c in deed
has a HARDCODED timeout of four seconds:

priv->carrier_action_defer_id = g_timeout_add_seconds (4, carrier_action_defer_cb, self);

Maybe someone from the nm-developers can comment on the necessity of this delay.

The comparison with WinXP/Vista/7 and OSX (all Version) shows that their implementation does not introduce a delay
and even a very brief network interruption results in functional re-establishment of the network connectivity.

This timeout prevents the use of common snmp port-restart actions where the port is put in shutdown mode for a split second
to clear err-disabled flags or to force 802.1x re-authentification after a change of vlan membership for a specific device/user.

Revision history for this message

Thomas Hood (jdthood) wrote on 2012-07-22:

The delay is still there in network-manager-0.9.6.0~git201207161259.00297f4, now in the file "nm-device-wired.c":

static void
set_carrier (NMDeviceWired *self,
             const gboolean carrier,
             const gboolean defer_action)
{
[...]
        if (defer_action)
                priv->carrier_action_defer_id = g_timeout_add_seconds (4, carrier_action_defer_cb, self);
        else
                carrier_action_defer_cb (self);
}

summary:

- Network-Manager doesn't handle short network interruptions correctly!
+ NetworkManager fails to reconfigure the interface if the link is broken
+ for a short time

Thomas Hood (jdthood) on 2012-07-24

tags:

added: precise
removed: 802.1x cisco interruption network-manager no peap shut shutdown supplicant wpa wpasupplicant

Mathieu Trudel-Lapierre (cyphermox) on 2012-08-02

Changed in network-manager (Ubuntu):
status:	Confirmed → Triaged
importance:	Undecided → Medium

B Bobo (yout-bobo123) on 2013-06-04

tags:

added: network-manager saucy

Revision history for this message

Mathieu Trudel-Lapierre (cyphermox) wrote on 2013-10-04:

Jan,

Would you be in a position to file this bug upstream? It would be useful if the upstream developers could look at it and decide whether that delay is still required.

I think it used to be that this delay was added to avoid invalidating the connections when one mistakenly disconnects a cable; but it seems like it's counter-productive and indeed would break other features for things like 802.1x. Perhaps the deferring should just be disabled for 802.1x, which is another possibility?

I'll take a look at the code for this as soon as I have a bit of time (no promises though).

Changed in network-manager (Ubuntu):
assignee:	nobody → Mathieu Trudel-Lapierre (mathieu-tl)

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.

Ubuntunetwork-manager package

NetworkManager fails to reconfigure the interface if the link is broken for a short time

Bug Description

Other bug subscribers

Remote bug watches

Ubuntu
network-manager package