0.7 Network-Manager requests DHCP configuration twice, gets confused and aborts the connection

[Alexander Jones]

Binary package hint: network-manager

Here is an annotated log.

Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) starting connection 'Auto lsw'
Aug 7 19:49:24 fizz NetworkManager: <info> (ath0): device state change: 3 -> 4
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) started...
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) complete.
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) starting...
Aug 7 19:49:24 fizz NetworkManager: <info> (ath0): device state change: 4 -> 5
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0/wireless): access point 'Auto lsw' has security, but secrets are required.
Aug 7 19:49:24 fizz NetworkManager: <info> (ath0): device state change: 5 -> 6
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'ssid' value 'lsw'
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'scan_ssid' value '1'
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'key_mgmt' value 'NONE'
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'auth_alg' value 'OPEN'
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) complete.
Aug 7 19:49:24 fizz NetworkManager: <info> Config: set interface ap_scan to 1
Aug 7 19:49:24 fizz NetworkManager: <info> (ath0): supplicant connection state change: 1 -> 2
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) started...
Aug 7 19:49:24 fizz NetworkManager: <info> (ath0): device state change: 6 -> 4
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) complete.
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) starting...
Aug 7 19:49:24 fizz NetworkManager: <info> (ath0): device state change: 4 -> 5
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0/wireless): connection 'Auto lsw' has security, and secrets exist. No new secrets needed.
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'ssid' value 'lsw'
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'scan_ssid' value '1'
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'key_mgmt' value 'NONE'
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'auth_alg' value 'OPEN'
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'wep_key0' value '<omitted>'
Aug 7 19:49:24 fizz NetworkManager: <info> Config: added 'wep_tx_keyidx' value '0'
Aug 7 19:49:24 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) complete.
Aug 7 19:49:24 fizz NetworkManager: <info> Config: set interface ap_scan to 1
Aug 7 19:49:24 fizz NetworkManager: <info> (ath0): supplicant connection state change: 2 -> 0
Aug 7 19:49:24 fizz NetworkManager: <info> (ath0): supplicant connection state change: 0 -> 2
Aug 7 19:49:30 fizz anacron[6045]: Anacron 2.3 started on 2008-08-07
Aug 7 19:49:30 fizz anacron[6045]: Normal exit (0 jobs run)
Aug 7 19:49:31 fizz klogd: [ 93.476716] CPU0 attaching NULL sched-domain.
Aug 7 19:49:31 fizz klogd: [ 93.476731] CPU1 attaching NULL sched-domain.
Aug 7 19:49:31 fizz klogd: [ 93.491437] CPU0 attaching sched-domain:
Aug 7 19:49:31 fizz klogd: [ 93.491450] domain 0: span 0-1
Aug 7 19:49:31 fizz klogd: [ 93.491455] groups: 0 1
Aug 7 19:49:31 fizz klogd: [ 93.491463] domain 1: span 0-1
Aug 7 19:49:31 fizz klogd: [ 93.491467] groups: 0-1
Aug 7 19:49:31 fizz klogd: [ 93.491474] CPU1 attaching sched-domain:

Aug 7 19:49:31 fizz klogd: [ 93.491478] domain 0: span 0-1
Aug 7 19:49:31 fizz klogd: [ 93.491481] groups: 1 0
Aug 7 19:49:31 fizz klogd: [ 93.491488] domain 1: span 0-1
Aug 7 19:49:31 fizz klogd: [ 93.491492] groups: 0-1
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 2 -> 3
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 3 -> 4
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 4 -> 7
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'lsw'.
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) scheduled.
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 7 -> 0
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 0 -> 4
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 4 -> 7
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'lsw'.
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) scheduled.
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 7 -> 0
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) started...
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): device state change: 5 -> 7

# Begin DHCP
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0) Beginning DHCP transaction.
Aug 7 19:49:33 fizz NetworkManager: <info> dhclient started with pid 6063
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) complete.
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) started...

# AGAIN?
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0) Beginning DHCP transaction.
Aug 7 19:49:33 fizz NetworkManager: <info> dhclient started with pid 6066
Aug 7 19:49:33 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) complete.
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 0 -> 4
Aug 7 19:49:33 fizz NetworkManager: <info> (ath0): supplicant connection state change: 4 -> 7
Aug 7 19:49:33 fizz dhclient: Internet Systems Consortium DHCP Client V3.1.1
Aug 7 19:49:33 fizz dhclient: Copyright 2004-2008 Internet Systems Consortium.
Aug 7 19:49:33 fizz dhclient: All rights reserved.
Aug 7 19:49:33 fizz dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Aug 7 19:49:33 fizz dhclient:
Aug 7 19:49:33 fizz dhclient: wifi0: unknown hardware address type 801
Aug 7 19:49:33 fizz dhclient: Internet Systems Consortium DHCP Client V3.1.1
Aug 7 19:49:33 fizz dhclient: Copyright 2004-2008 Internet Systems Consortium.
Aug 7 19:49:33 fizz dhclient: All rights reserved.
Aug 7 19:49:33 fizz dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Aug 7 19:49:33 fizz dhclient:
Aug 7 19:49:33 fizz dhclient: wifi0: unknown hardware address type 801
Aug 7 19:49:34 fizz NetworkManager: <WARN> nm_dhcp_manager_handle_event(): Received DHCP event from unexpected PID 6063 (expected 6066)
Aug 7 19:49:34 fizz dhclient: wifi0: unknown hardware address type 801
Aug 7 19:49:34 fizz dhclient: wifi0: unknown hardware address type 801
Aug 7 19:49:34 fizz NetworkManager: <info> DHCP: device ath0 state changed (null) -> preinit
Aug 7 19:49:34 fizz dhclient: Listening on LPF/ath0/00:1c:b3:c6:b7:69
Aug 7 19:49:34 fizz dhclient: Sending on LPF/ath0/00:1c:b3:c6:b7:69
Aug 7 19:49:34 fizz dhclient: Sending on Socket/fallback
Aug 7 19:49:34 fizz dhclient: Listening on LPF/ath0/00:1c:b3:c6:b7:69
Aug 7 19:49:34 fizz dhclient: Sending on LPF/ath0/00:1c:b3:c6:b7:69
Aug 7 19:49:34 fizz dhclient: Sending on Socket/fallback
Aug 7 19:49:38 fizz dhclient: DHCPDISCOVER on ath0 to 255.255.255.255 port 67 interval 4
Aug 7 19:49:38 fizz dhclient: DHCPDISCOVER on ath0 to 255.255.255.255 port 67 interval 4
Aug 7 19:49:38 fizz dhclient: DHCPOFFER of 192.168.0.5 from 192.168.0.1
Aug 7 19:49:38 fizz dhclient: DHCPREQUEST of 192.168.0.5 on ath0 to 255.255.255.255 port 67
Aug 7 19:49:38 fizz dhclient: DHCPOFFER of 192.168.0.5 from 192.168.0.1
Aug 7 19:49:38 fizz dhclient: DHCPREQUEST of 192.168.0.5 on ath0 to 255.255.255.255 port 67
Aug 7 19:49:38 fizz dhclient: DHCPACK of 192.168.0.5 from 192.168.0.1
Aug 7 19:49:38 fizz dhclient: DHCPACK of 192.168.0.5 from 192.168.0.1
Aug 7 19:49:38 fizz NetworkManager: <WARN> nm_dhcp_manager_handle_event(): Received DHCP event from unexpected PID 6063 (expected 6066)
Aug 7 19:49:38 fizz dhclient: bound to 192.168.0.5 -- renewal in 2147483648 seconds.
Aug 7 19:49:38 fizz dhclient: bound to 192.168.0.5 -- renewal in 2147483648 seconds.
Aug 7 19:50:18 fizz NetworkManager: <info> Device 'ath0' DHCP transaction took too long (>45s), stopping it.
Aug 7 19:50:18 fizz NetworkManager: <info> ath0: canceled DHCP transaction, dhcp client pid 6066
Aug 7 19:50:18 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Timeout) scheduled...
Aug 7 19:50:18 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Timeout) started...
Aug 7 19:50:18 fizz NetworkManager: <info> Activation (ath0/wireless): could not get IP configuration for connection 'Auto lsw'.
Aug 7 19:50:18 fizz NetworkManager: <info> (ath0): device state change: 7 -> 6
Aug 7 19:50:18 fizz NetworkManager: <info> Activation (ath0/wireless): asking for new secrets
Aug 7 19:50:18 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Timeout) complete.

# At this point nm-applet packs in and asks me for my WEP key again. Hitting OK makes it work.

ProblemType: Bug
Architecture: amd64
DistroRelease: Ubuntu 8.10
NonfreeKernelModules: ath_hal
Package: network-manager 0.7~~svn20080720t224551+eni1-0ubuntu1
ProcEnviron:
 PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/home/username/.local/bin
 LANG=en_GB.UTF-8
 SHELL=/bin/bash
SourcePackage: network-manager
Uname: Linux 2.6.26-5-generic x86_64

[Alexander Sack (asac)]

can you reproduce that after a reboot? do you have more than one NetworkManager process running at that time?

[Alexander Jones (alex-weej)]

Now it won't even connect after i hit OK to try again.

Probably a different bug, but I'm losing track of how many different bugs I'm hitting here so this'll do.

[Alexander Sack (asac)]

i never could reproduce this. one idea would be that you have some hooks in /etc/network/if-*.d/ that run dhclient; or something else that runs dhclient when a network device is upped.

If you still see this reopen and subscribe me directly.

(btw, sorry for the radar droppage)

[Nick Maynard (nick-maynard)]

I still get this bizarre behaviour, though with a slight variation.

I get a connection OK, but about a minute or so later, the interface gets another lease from a dhclient that NM started, but nevertheless doesn't regard as a belonging to it (unrecognised PID). NM then *stops* the interface.

Really, this is just paranoid. Never mind the fact that NM's starting up multiple dhclient processes - why on earth should NM kill the connection dead when a new lease arrives/is refreshed?

[Nick Maynard (nick-maynard)]

Better wording... why not accept a lease whereever it arrives from? What seems to be happening is that NM *ignores* the provided lease because it's mistakenly waiting for a lease from a different PID. Things then time out.

Easy workaround: just accept the lease.

Fix: track them PIDs correctly.