knetworkmanager can't acquire dhcp address on wep network

[Michael Blakeley]

Binary package hint: knetworkmanager

NB - this might well be a networkmanager issue, rather than knetworkmanager. But since I don't see an existing bug that seems relevant, I'm guessing that it's specific to knetworkmanager.

I have an hp compaq nc6400 with an Intel 3945 wifi card. When trying to connect to a WEP network using knetworkmanager, I always see dhcp timeouts. When using iwconfig and ifup from the command-line, though, I don't have any problems getting a dhcp address.

$ lspci | grep 3945
10:00.0 Network controller: Intel Corporation PRO/Wireless 3945ABG Network Connection (rev 02)
$ uname -a
Linux mblakele-lt 2.6.22-11-generic #1 SMP Fri Sep 7 04:31:16 GMT 2007 x86_64 GNU/Linux
$ apt-show-versions | grep network | grep manager
network-manager/gutsy uptodate 0.6.5-0ubuntu11
network-manager-kde/gutsy uptodate 1:0.2ubuntu1-0ubuntu4
knetworkmanager/gutsy uptodate 1:0.2ubuntu1-0ubuntu4
$ grep eth1 /etc/network/interfaces
#auto eth1
#iface eth1 inet dhcp
#iface eth1 inet static

Here's what I see in my syslog:

Sep 15 09:43:33 mblakele-lt NetworkManager: <debug> [1189874613.360681] nm_device_802_11_wireless_get_activation_ap(): Forcing AP 'blakeley'
Sep 15 09:43:33 mblakele-lt NetworkManager: <info> User Switch: /org/freedesktop/NetworkManager/Devices/eth1 / blakeley
Sep 15 09:43:33 mblakele-lt NetworkManager: <info> Deactivating device eth1.
Sep 15 09:43:33 mblakele-lt dhclient: There is already a pid file /var/run/dhclient.eth1.pid with pid 3233
Sep 15 09:43:33 mblakele-lt dhclient: killed old client process, removed PID file
Sep 15 09:43:33 mblakele-lt dhclient: DHCPRELEASE on eth1 to 10.0.1.1 port 67
Sep 15 09:43:33 mblakele-lt avahi-daemon[6187]: Withdrawing address record for 10.0.1.102 on eth1.
Sep 15 09:43:33 mblakele-lt avahi-daemon[6187]: Leaving mDNS multicast group on interface eth1.IPv4 with address 10.0.1.102.
Sep 15 09:43:33 mblakele-lt avahi-daemon[6187]: Interface eth1.IPv4 no longer relevant for mDNS.
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> SUP: sending command 'DISABLE_NETWORK 0'
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> SUP: sending command 'AP_SCAN 0'
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> SUP: sending command 'TERMINATE'
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:34 mblakele-lt avahi-daemon[6187]: Withdrawing address record for fe80::218:deff:fe31:f9d7 on eth1.
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> Device eth1 activation scheduled...
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> Activation (eth1) started...
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled...
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started...
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled...
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete.
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting...
Sep 15 09:43:34 mblakele-lt NetworkManager: <info> Activation (eth1/wireless): access point 'blakeley' is encrypted, and a key exists. No new key needed.
Sep 15 09:43:35 mblakele-lt NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (0/10).
Sep 15 09:43:35 mblakele-lt NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (1/10).
Sep 15 09:43:35 mblakele-lt NetworkManager: <info> SUP: sending command 'INTERFACE_ADD eth1^I^Iwext^I/var/run/wpa_supplicant6^I'
Sep 15 09:43:35 mblakele-lt kernel: [ 88.677976] ADDRCONF(NETDEV_UP): eth1: link is not ready
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> supplicant_init() - connect to device ctrl socket (3/10).
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: sending command 'AP_SCAN 1'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: sending command 'ADD_NETWORK'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: response was '0'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 ssid 626c616b656c6579'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 key_mgmt NONE'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 wep_key0 <key>'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 wep_tx_keyidx 0'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: sending command 'ENABLE_NETWORK 0'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> SUP: response was 'OK'
Sep 15 09:43:36 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) complete.
Sep 15 09:43:37 mblakele-lt NetworkManager: <info> Activation (eth1/wireless) Stage 2 of 5 (Device Configure) successful. Connected to access point 'blakeley'.
Sep 15 09:43:37 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) scheduled.
Sep 15 09:43:37 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) started...
Sep 15 09:43:37 mblakele-lt kernel: [ 89.498644] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Sep 15 09:43:38 mblakele-lt NetworkManager: <info> Activation (eth1) Beginning DHCP transaction.
Sep 15 09:43:38 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) complete.
Sep 15 09:43:38 mblakele-lt NetworkManager: <info> DHCP daemon state is now 12 (successfully started) for interface eth1
Sep 15 09:43:38 mblakele-lt dhclient: There is already a pid file /var/run/dhclient.eth1.pid with pid 1
Sep 15 09:43:39 mblakele-lt avahi-daemon[6187]: Registering new address record for fe80::218:deff:fe31:f9d7 on eth1.*.

Sep 15 09:43:39 mblakele-lt NetworkManager: <info> DHCP daemon state is now 1 (starting) for interface eth1
Sep 15 09:43:41 mblakele-lt dhclient: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 7
Sep 15 09:43:48 mblakele-lt dhclient: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 15
Sep 15 09:43:48 mblakele-lt kernel: [ 92.594741] eth1: no IPv6 routers present
Sep 15 09:44:03 mblakele-lt dhclient: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 9
Sep 15 09:44:12 mblakele-lt dhclient: No DHCPOFFERS received.
Sep 15 09:44:12 mblakele-lt NetworkManager: <info> DHCP daemon state is now 9 (fail) for interface eth1
Sep 15 09:44:12 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Timeout) scheduled...
Sep 15 09:44:12 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Timeout) started...
Sep 15 09:44:12 mblakele-lt NetworkManager: <debug> [1189874652.030530] real_act_stage4_ip_config_timeout(): Activation (eth1/wireless): could not get IP configuration info for 'blakeley', asking for new key.
Sep 15 09:44:12 mblakele-lt NetworkManager: <info> Activation (eth1) New wireless user key requested for network 'blakeley'.
Sep 15 09:44:12 mblakele-lt NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Timeout) complete.
Sep 15 09:44:12 mblakele-lt dhcdbd: Unrequested down ?:3
Sep 15 09:44:12 mblakele-lt NetworkManager: <info> DHCP daemon state is now 14 (normal exit) for interface eth1
Sep 15 09:44:30 mblakele-lt NetworkManager: <WARN> nm_dbus_get_user_key_for_network_cb(): nm_dbus_get_user_key_for_network_cb(): dbus returned an error. (org.freedesktop.NetworkManagerInfo.GetKeyError) org.freedesktop.NetworkManagerInfo.GetKeyError
Sep 15 09:44:30 mblakele-lt NetworkManager: <info> Activation (eth1) failure scheduled...
Sep 15 09:44:30 mblakele-lt NetworkManager: <info> Activation (eth1) failed for access point (blakeley)
Sep 15 09:44:30 mblakele-lt NetworkManager: <info> Activation (eth1) failed.
Sep 15 09:44:30 mblakele-lt NetworkManager: <info> Deactivating device eth1.

At this point, knetworkmanager asks me for a new key for the AP. That is just plain wrong - the existing key is fine, and iwconfig agrees that eth1 is associated with the AP. Here's what I see if I check iwconfig while knetworkmanager is waiting for that dhcp response:

$ iwconfig eth1
eth1 IEEE 802.11g ESSID:"blakeley"
          Mode:Managed Frequency:2.432 GHz Access Point: 00:0F:66:9D:EE:CE
          Bit Rate:24 Mb/s Tx-Power:15 dBm
          Retry limit:15 RTS thr:off Fragment thr:off
          Power Management:on
          Link Quality=77/100 Signal level=-64 dBm Noise level=-65 dBm
          Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
          Tx excessive retries:0 Invalid misc:313 Missed beacon:0

So I wish knetworkmanager were smart enough to know the difference between failing to associate and a dhcp failure....

But let's ignore that for now. If I use ifup from the command-line, the same wifi AP works fine, and gives me a dhcp address immediately:
$ grep eth1 /etc/network/interfaces
#auto eth1
iface eth1 inet dhcp
#iface eth1 inet static

$ sudo iwconfig eth1 essid "blakeley" key $KEY && sudo ifup eth1
There is already a pid file /var/run/dhclient.eth1.pid with pid 9888
killed old client process, removed PID file
Internet Systems Consortium DHCP Client V3.0.5
Copyright 2004-2006 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/

Listening on LPF/eth1/00:18:de:31:f9:d7
Sending on LPF/eth1/00:18:de:31:f9:d7
Sending on Socket/fallback
DHCPRELEASE on eth1 to 10.0.1.1 port 67
There is already a pid file /var/run/dhclient.eth1.pid with pid 1
Internet Systems Consortium DHCP Client V3.0.5
Copyright 2004-2006 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/

Listening on LPF/eth1/00:18:de:31:f9:d7
Sending on LPF/eth1/00:18:de:31:f9:d7
Sending on Socket/fallback
DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 3
DHCPOFFER from 10.0.1.1
DHCPREQUEST on eth1 to 255.255.255.255 port 67
DHCPACK from 10.0.1.1
bound to 10.0.1.102 -- renewal in 19502 seconds.

$ iwconfig eth1; ifconfig eth1
eth1 IEEE 802.11g ESSID:"blakeley"
          Mode:Managed Frequency:2.432 GHz Access Point: 00:0F:66:9D:EE:CE
          Bit Rate:48 Mb/s Tx-Power:15 dBm
          Retry limit:15 RTS thr:off Fragment thr:off
          Power Management:on
          Link Quality=72/100 Signal level=-63 dBm Noise level=-71 dBm
          Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
          Tx excessive retries:0 Invalid misc:412 Missed beacon:0

eth1 Link encap:Ethernet HWaddr 00:18:DE:31:F9:D7
          inet addr:10.0.1.102 Bcast:10.0.1.255 Mask:255.255.255.0
          inet6 addr: fe80::218:deff:fe31:f9d7/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
          RX packets:11 errors:11 dropped:423 overruns:0 frame:0
          TX packets:22 errors:0 dropped:9 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:409570 (399.9 KB) TX bytes:90808 (88.6 KB)
          Interrupt:17 Base address:0x8000 Memory:e4000000-e4000fff
$ ping -c 2 google.com
PING google.com (64.233.187.99) 56(84) bytes of data.
64 bytes from jc-in-f99.google.com (64.233.187.99): icmp_seq=1 ttl=242 time=97.0 ms
64 bytes from jc-in-f99.google.com (64.233.187.99): icmp_seq=2 ttl=242 time=95.4 ms

--- google.com ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 95.486/96.283/97.081/0.855 ms

So... my key works, and my dhcp server works. But it seems like knetworkmanager has some difficulty getting the sequence of operations right. One difference I noticed is that ifup always seems to kill off any existing dhclient pid, while knetworkmanager seems to try to reuse the existing dhclient pid.

Workaround: use iwconfig and ifup from the command-line, instead of knetworkmanager.

[Michael Blakeley (mike+ubuntu)]

WPA (enterprise) works fine, too. This is another data point showing that there's no real dhcp problem: more likely a wep-specific issue.

[Peter Matulis (petermatulis)]

I have seen the exact same behaviour on Ubuntu 7.10 with the same card:

0c:00.0 Network controller: Intel Corporation PRO/Wireless 3945ABG Network Connection (rev 02)

Not sure if the particular combination of access point and network card in a WEP scenario can be the cause.

Access point is Netgear Rangemax WPN824v2

[DrSpirograph (kubuntu-drspirograph)]

I can confirm this with a Broadcom adapter in Hardy:
# cat /etc/issue
Ubuntu 8.04 \n \l

# lspci | grep Wireless
06:06.0 Network controller: Broadcom Corporation BCM4318 [AirForce One 54g] 802.11g Wireless LAN Controller (rev 02)

Because of the difficulty in getting this card to work in previous releases, I (and by the looks of the forums many others) take this to mean that the wireless driver is not working - took me sometime to hone in on the real cause and how easy it was to fix.

So if this can't be fixed immediately, maybe the Hardwares Drivers Manager could display a notice about this bug or something so people know how to work around?

[scoobymad555 (scoobymad555)]

hmmm .... seem to be having the same problem on a customer site of mine too ..... they're running eepc's with xandros though?!
using dhclient for the dhcp and iface for managing the hardware interface. From checking the logs, iface does kill existing pid files here but i still seem to get the problem.

running an onboard atheros wireless card connecting to a buffallo access point with wep

I'm seeing exactly the same log entries as above.

One thing i did stumble across was ...... connect the device to the network via a hard-wired connection first so it collects an address then disconnect it and try the wireless connection. It picks up a different address as you'd expect but seems to then connect fine with the couple of machines i've tried here.

I'm no debugger by any means but it seems to be a definite issue with the dhcp acknowledgement or a handshake problem through the encryption maybe?

Perhaps this is a slightly more widespread issue than first thought given that i'm seeing it with xandros? I also run my laptop on ubuntu hardy with an intel pro and i think i'm getting the same problem on that aswell but to be fair, my builds not exactly stable so take that bit with a pinch of salt :)

[scoobymad555 (scoobymad555)]

thinking about it, also had the problem with the new hp10ag access points too ...... sent them back to hp on the grounds of faulty firmware not handling encryption properly ...... ooops ...... sorry hp! :) lol!

[scoobymad555 (scoobymad555)]

can now confirm this as a problem on Hardy also ........ exact same issues as above. Using Gnome, with nm-applet 0.6.6 and dhclient connecting with an intel pro chipset to a bt voyager access point running WEP 128bit.

Initial problem appears to be with the encryption key being sent since nm-applet just repeatedly failed to connect to the access point and on the rare occasion it did show a connection no traffic successfully passed - couldn't even ping the access point when i forced my local config to static address.

"iwconfig eth1 essid {network name} key s:{passphrase}" (sudo) was good enough to get me connected to the access point.

at this point a static config then works fine but switching nm-applet to dhcp fails to pull an address and defaults to 169. dhclient run at cli seemed to be unable to pull an address aswell. Tried killing off the pid files (backups made) but made no difference. Still got dhcp request timeouts.

tried using ifup & ifdown and also tried using the script in etc/init.d to restart networking but none seemed to make any difference on my system.

Installed dhcpcd client to try out which worked.

"dhcpcd eth1" (also sudo)

will also try this / suitable variant on the xandros systems i've been seeing trouble with aswell to see if it works.

[Daniel T Chen (crimsun)]

Is this symptom still reproducible in 8.10 RC or later?

[Jonathan Thomas (echidnaman)]

We are closing this bug report because it lacks the information we need to investigate the problem, as described in the previous comments. Please reopen it if you can give us the missing information, and don't hesitate to submit bug reports in the future. To reopen the bug report you can click on the current status, under the Status column, and change the Status back to "New". Thanks again!