GNOME Bugzilla – Bug 680596
NetworkManager cannot connect to Rialta (Guadec 2012) wifi
Last modified: 2012-07-26 22:38:55 UTC
Android ( CyanogenMod 9 rc2) can connect properly. The Wifi works, just that NetworkManager cannot connect to it. The root cause appears to be that the accesspoints are in the future. year 2148, more exactly. The lease files created by dhclient says: lease { interface "wlan0"; fixed-address 172.20.9.194; option subnet-mask 255.255.0.0; option routers 172.20.0.1; option dhcp-lease-time 4294967295; option dhcp-message-type 5; option domain-name-servers 8.8.8.8,213.60.205.173; option dhcp-server-identifier 172.20.0.3; option dhcp-renewal-time 4294967295; option dhcp-rebinding-time 4294967295; renew 6 2148/08/31 04:35:25; rebind 6 2148/08/31 04:35:25; expire 6 2148/08/31 04:35:25; } NetworkManager-gnome-0.9.4.0-9.git20120521.fc17.x86_64 NetworkManager-openconnect-0.9.4.0-7.git20120612.fc17.x86_64 NetworkManager-0.9.4.0-9.git20120521.fc17.x86_64 NetworkManager-vpnc-0.9.3.997-1.fc17.x86_64 evolution-NetworkManager-3.4.3-2.fc17.x86_64 NetworkManager-pptp-0.9.3.997-1.fc17.x86_64 NetworkManager-glib-0.9.4.0-9.git20120521.fc17.x86_64 NetworkManager-gtk-0.9.4.0-9.git20120521.fc17.x86_64 NetworkManager-openvpn-0.9.3.997-1.fc17.x86_64 Log entries: Jul 25 00:06:54 clarus NetworkManager[855]: <info> Auto-activating connection 'Auto Rialta_wifi'. Jul 25 00:06:54 clarus NetworkManager[855]: <info> Activation (wlan0) starting connection 'Auto Rialta_wifi' Jul 25 00:06:54 clarus NetworkManager[855]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0] Jul 25 00:06:54 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Jul 25 00:06:54 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Jul 25 00:06:54 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Jul 25 00:06:54 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Jul 25 00:06:54 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Jul 25 00:06:54 clarus NetworkManager[855]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Jul 25 00:06:54 clarus NetworkManager[855]: <info> Activation (wlan0/wireless): connection 'Auto Rialta_wifi' requires no security. No secrets needed. Jul 25 00:06:54 clarus NetworkManager[855]: <info> Config: added 'ssid' value 'Rialta_wifi' Jul 25 00:06:54 clarus NetworkManager[855]: <info> Config: added 'scan_ssid' value '1' Jul 25 00:06:54 clarus NetworkManager[855]: <info> Config: added 'key_mgmt' value 'NONE' Jul 25 00:06:54 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Jul 25 00:06:54 clarus NetworkManager[855]: <info> Config: set interface ap_scan to 1 Jul 25 00:06:55 clarus NetworkManager[855]: <info> (wlan0): supplicant interface state: disconnected -> scanning Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): supplicant interface state: scanning -> authenticating Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): supplicant interface state: authenticating -> associating Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): supplicant interface state: associating -> completed Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'Rialta_wifi'. Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0] Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds) Jul 25 00:06:56 clarus NetworkManager[855]: <info> dhclient started with pid 3930 Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) Beginning IP6 addrconf. Jul 25 00:06:56 clarus avahi-daemon[870]: Withdrawing address record for fe80::76e5:bff:fe86:863e on wlan0. Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. Jul 25 00:06:56 clarus dhclient[3930]: Internet Systems Consortium DHCP Client 4.2.4 Jul 25 00:06:56 clarus dhclient[3930]: Copyright 2004-2012 Internet Systems Consortium. Jul 25 00:06:56 clarus dhclient[3930]: All rights reserved. Jul 25 00:06:56 clarus dhclient[3930]: For info, please visit https://www.isc.org/software/dhcp/ Jul 25 00:06:56 clarus dhclient[3930]: Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): DHCPv4 state changed nbi -> preinit Jul 25 00:06:56 clarus dhclient[3930]: Listening on LPF/wlan0/74:e5:0b:86:86:3e Jul 25 00:06:56 clarus dhclient[3930]: Sending on LPF/wlan0/74:e5:0b:86:86:3e Jul 25 00:06:56 clarus dhclient[3930]: Sending on Socket/fallback Jul 25 00:06:56 clarus dhclient[3930]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67 (xid=0x2fa4a6ed) Jul 25 00:06:56 clarus dhclient[3930]: DHCPACK from 172.20.0.2 (xid=0x2fa4a6ed) Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): DHCPv4 state changed preinit -> reboot Jul 25 00:06:56 clarus NetworkManager[855]: <info> address 172.20.9.194 Jul 25 00:06:56 clarus NetworkManager[855]: <info> prefix 16 (255.255.0.0) Jul 25 00:06:56 clarus NetworkManager[855]: <info> gateway 172.20.0.1 Jul 25 00:06:56 clarus NetworkManager[855]: <info> nameserver '8.8.8.8' Jul 25 00:06:56 clarus NetworkManager[855]: <info> nameserver '213.60.205.173' Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Configure Commit) scheduled... Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) started... Jul 25 00:06:56 clarus dhclient[3930]: Unable to set up timer: out of range Jul 25 00:06:56 clarus dhclient[3930]: Jul 25 00:06:56 clarus dhclient[3930]: This version of ISC DHCP is based on the release available Jul 25 00:06:56 clarus dhclient[3930]: on ftp.isc.org. Features have been added and other changes Jul 25 00:06:56 clarus dhclient[3930]: have been made to the base software release in order to make Jul 25 00:06:56 clarus dhclient[3930]: it work better with this distribution. Jul 25 00:06:56 clarus dhclient[3930]: Jul 25 00:06:56 clarus dhclient[3930]: Please report for this software via the Red Hat Bugzilla site: Jul 25 00:06:56 clarus dhclient[3930]: http://bugzilla.redhat.com Jul 25 00:06:56 clarus dhclient[3930]: Jul 25 00:06:56 clarus dhclient[3930]: exiting. Jul 25 00:06:56 clarus avahi-daemon[870]: Joining mDNS multicast group on interface wlan0.IPv4 with address 172.20.9.194. Jul 25 00:06:56 clarus avahi-daemon[870]: New relevant interface wlan0.IPv4 for mDNS. Jul 25 00:06:56 clarus avahi-daemon[870]: Registering new address record for 172.20.9.194 on wlan0.IPv4. Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0] Jul 25 00:06:56 clarus NetworkManager[855]: <info> Policy set 'Auto Rialta_wifi' (wlan0) as default for IPv4 routing and DNS. Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) successful, device activated. Jul 25 00:06:56 clarus NetworkManager[855]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) complete. Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): DHCPv4 client pid 3930 exited with status 1 Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): device state change: activated -> failed (reason 'ip-config-expired') [100 120 6] Jul 25 00:06:56 clarus NetworkManager[855]: <warn> Activation (wlan0) failed for access point (Rialta_wifi) Jul 25 00:06:56 clarus NetworkManager[855]: <warn> Activation (wlan0) failed. Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0] Jul 25 00:06:56 clarus NetworkManager[855]: <info> (wlan0): deactivating device (reason 'none') [0] Jul 25 00:06:56 clarus avahi-daemon[870]: Withdrawing address record for 172.20.9.194 on wlan0. Jul 25 00:06:56 clarus avahi-daemon[870]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 172.20.9.194. And then it starts over again.
Further info for people at Guadec 2012: Check your lease. Hard config that lease IP address to your connection. (Manual IP config) via the network manager connection editor. also add gateway & DNS servers as suggested. this will let you connect to the wifi even if NetworkManager isn't allowing it.
I guess from the logs that the problem is in 'dhclient'. I don't think difference it time affects DHCP and I don't think 2148 is there because of time difference. If you look at the following options: option dhcp-renewal-time 4294967295; option dhcp-rebinding-time 4294967295; And if you use e.g. python to count the correct values: >>> datetime.datetime.now() + datetime.timedelta(0, 4294967295) datetime.datetime(2148, 9, 1, 2, 5, 56, 531976) You'll see that the computed value is perfectly correct. And the lifetime value is actually 0xffffffff. >>> 0xffffffff 4294967295 See http://tools.ietf.org/html/rfc2131#section-3.3: A client acquires a lease for a network address for a fixed period of time (which may be infinite). Throughout the protocol, times are to be represented in units of seconds. The time value of 0xffffffff is reserved to represent "infinity". My feeling is that dhclient doesn't properly handle the 'infinity' value.
Came to pretty much the same conclusion: https://twitter.com/hadessuk/status/228190508969779200 and https://bugzilla.redhat.com/show_bug.cgi?id=662254#c6
Just wanted to report: The wireless seems to work just fine for me with NetworkManager 0.9.4.0 and dhcpcd (so no dhclient)
If you'd like to use dhcpcd until this is fixed, that support is already built into NM. You can switch at runtime by editing /etc/NetworkManager/NetworkManager.conf: [main] dhcp=dhcpcd and of course installing dhcpcd.
Since it's most certainly dhclient, closing as NOTGNOME. Hadess got the word out via twitter, so I hope people at GUADEC hear via word-of-mouth that dhclient is to blame and not NetworkManager :)
It may be of interest that I couldn't reproduce this bug on F17, see also: https://bugzilla.redhat.com/show_bug.cgi?id=662254#c14
Strange, as I'm running F17 here.
Please follow up at the linked RH bug report.