desktop-packages team mailing list archive

Thread
Date
[Bug 894082] Re: Network-Manager doesn't handle short network interruptions correctly!

To: desktop-packages@xxxxxxxxxxxxxxxxxxx
From: Jan Zacharias <894082@xxxxxxxxxxxxxxxxxx>
Date: Thu, 24 Nov 2011 12:54:38 -0000
Reply-to: Bug 894082 <894082@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
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.

-- 
You received this bug notification because you are a member of Desktop
Packages, which is subscribed to network-manager in Ubuntu.
https://bugs.launchpad.net/bugs/894082

Title:
  Network-Manager doesn't handle short network interruptions correctly!

Status in “network-manager” package in Ubuntu:
  Confirmed

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, Bremen/emailAddress=e@xxxxxxxxx/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, Bremen/emailAddress=e@xxxxxxxxx/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, Bremen/emailAddress=e@xxxxxxxxx/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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/network-manager/+bug/894082/+subscriptions
References

[Bug 894082] [NEW] Network-Manager doesn't handle short network interruptions correctly!
From: Jan Zacharias, 2011-11-23