2010-02-11: dhcpcd on openSUSE-11.2 sometime loops endless after adding wlan usb stick

Plug in wlan usb stick, connection to access point established, disconnect, connect, disconnect, connect, ....

From /var/log/messages:

Feb 11 16:24:21 linux-klms dhcpcd[14029]: wlan0: dhcpcd 3.2.3 starting
Feb 11 16:24:21 linux-klms dhcpcd[14029]: wlan0: hardware address = 00:13:49:90:c9:bc
Feb 11 16:24:21 linux-klms dhcpcd[14029]: wlan0: broadcasting for a lease
Feb 11 16:24:41 linux-klms dhcpcd[14029]: wlan0: timed out
Feb 11 16:24:41 linux-klms dhcpcd[14029]: wlan0: trying to use old lease in `/var/lib/dhcpcd/dhcpcd-wlan0.info'
Feb 11 16:24:41 linux-klms dhcpcd[14029]: wlan0: adding IP address 192.168.2.100/24
Feb 11 16:24:41 linux-klms dhcpcd[14029]: wlan0: adding default route via 192.168.2.1 metric 0
Feb 11 16:24:44 linux-klms dhcpcd[14029]: wlan0: Failed to lookup hostname via DNS: Name or service not known
Feb 11 16:24:44 linux-klms dhcpcd[15526]: wlan0: renewing lease of 192.168.2.100
Feb 11 16:24:44 linux-klms dhcpcd[15526]: wlan0: lost lease, attemping to rebind
Feb 11 16:24:44 linux-klms dhcpcd[15526]: wlan0: lost lease
Feb 11 16:24:44 linux-klms dhcpcd[15526]: wlan0: removing default route via 192.168.2.1 metric 0
Feb 11 16:24:44 linux-klms dhcpcd[15526]: wlan0: removing IP address 192.168.2.100/24
Feb 11 16:24:44 linux-klms dhcpcd[14029]: wlan0: exiting
Feb 11 16:24:45 linux-klms dhcpcd[15526]: wlan0: trying to use old lease in `/var/lib/dhcpcd/dhcpcd-wlan0.info'
Feb 11 16:24:45 linux-klms dhcpcd[15526]: wlan0: adding IP address 192.168.2.100/24
Feb 11 16:24:45 linux-klms dhcpcd[15526]: wlan0: adding default route via 192.168.2.1 metric 0
Feb 11 16:24:47 linux-klms dhcpcd[15526]: wlan0: Failed to lookup hostname via DNS: Name or service not known
Feb 11 16:24:47 linux-klms dhcpcd[15526]: wlan0: renewing lease of 192.168.2.100
Feb 11 16:24:47 linux-klms dhcpcd[15526]: wlan0: lost lease, attemping to rebind
Feb 11 16:24:47 linux-klms dhcpcd[15526]: wlan0: lost lease
Feb 11 16:24:47 linux-klms dhcpcd[15526]: wlan0: removing default route via 192.168.2.1 metric 0
Feb 11 16:24:47 linux-klms dhcpcd[15526]: wlan0: removing IP address 192.168.2.100/24
Feb 11 16:24:47 linux-klms dhcpcd[15526]: wlan0: trying to use old lease in `/var/lib/dhcpcd/dhcpcd-wlan0.info'
....
The problem seems to be using the old lease from stored file, try to renewing the lease and immediately the message 'lost lease'.

The access point 'Vodafone DSL-EasyBox 802' (Firmware Version:20.02.221, DHCP lease time set to 'forever') sends the following DHCP ACK:

Internet Protocol, Src: 192.168.2.1 (192.168.2.1), Dst: 255.255.255.255 (255.255.255.255)
User Datagram Protocol, Src Port: bootps (67), Dst Port: bootpc (68)
Bootstrap Protocol
    Message type: Boot Reply (2)
    Client IP address: 0.0.0.0 (0.0.0.0)
    Your (client) IP address: 192.168.2.100 (192.168.2.100)
    Next server IP address: 192.168.2.1 (192.168.2.1)
    Relay agent IP address: 0.0.0.0 (0.0.0.0)
    Client MAC address: ZyxelCom_90:c9:bc (00:13:49:90:c9:bc)
    Client hardware address padding: 00000000000000000000
    Server host name not given
    Boot file name not given
    Magic cookie: (OK)
    Option: (t=53,l=1) DHCP Message Type = DHCP ACK
    Option: (t=54,l=4) DHCP Server Identifier = 192.168.2.1
    Option: (t=51,l=4) IP Address Lease Time = infinity
        Option: (51) IP Address Lease Time
        Length: 4
        Value: FFFFFFFF
    Option: (t=1,l=4) Subnet Mask = 255.255.255.0
    Option: (t=3,l=4) Router = 192.168.2.1
    Option: (t=6,l=4) Domain Name Server = 192.168.2.1
    End Option
    Padding
Note the value '0xffffffff' (infinity) for the option 'IP Address Lease Time'.

This lease time is handled in 'handle_dhcp()' (dhcpcd-3.2.3/client.c:line904-905):

 904         } else if (dhcp->leasetime == (unsigned) -1) {
 905                 dhcp->renewaltime = dhcp->rebindtime = dhcp->leasetime;
and the same value is set for leasetime, renewaltime and rebindtime and saved to info file '/var/lib/dhcpcd/dhcpcd-wlan0.info' (0xffffffff is '4294967295'):
DHCPSIADDR='192.168.2.1'
IPADDR='192.168.2.100'
NETMASK='255.255.255.0'
NETWORK='192.168.2.0'
BROADCAST='192.168.2.255'
ROUTES=''
GATEWAYS='192.168.2.1'
DNSSERVERS='192.168.2.1'
DHCPSID='192.168.2.1'
LEASEDFROM='1265907910'
LEASETIME='4294967295'
RENEWALTIME='4294967295'
REBINDTIME='4294967295'
INTERFACE='wlan0'
CLASSID='dhcpcd 3.2.3'
CLIENTID='01:00:13:49:90:c9:bc'
DHCPCHADDR='00:13:49:90:c9:bc'
After restart the values are taken from the previously stored info file and a renewing via DHCP is started which immmediately fails because of a calculated timeout value of 0 (because of the same value for LEASETIME, RENEWALTIME and REBINDTIME, in case of a finite leasetime value renewaltime is calculated as '0.5 * leasetime' and rebindtime as '0.875 * leasetime').

The following patch (dhcpcd-3.2.3-set_default_timeout.diff fixed the problem for me:

--- dhcpcd-3.2.3_patched_suse/client.c  2010-02-11 14:48:54.000000000 +0100
+++ dhcpcd-3.2.3/client.c       2010-02-11 16:47:22.000000000 +0100
@@ -746,6 +746,10 @@
                        do_socket (state, SOCKET_OPEN);
                        _send_message (state, DHCP_REQUEST, options);
                        state->timeout = dhcp->rebindtime - dhcp->renewaltime;
+                       if (state->timeout == 0) {
+                               logger (LOG_INFO, "renewing lease of %s set default timeout", inet_ntoa(dhcp->address));
+                               state->timeout = DEFAULT_TIMEOUT;
+                       }
                        state->state = STATE_REBINDING;
                        break;
                case STATE_REBINDING:
@@ -757,6 +761,10 @@
                        dhcp->serveraddress.s_addr = 0;
                        _send_message (state, DHCP_REQUEST, options);
                        state->timeout = dhcp->leasetime - dhcp->rebindtime;
+                       if (state->timeout == 0) {
+                               logger (LOG_INFO, "rebind lease set default timeout", inet_ntoa(dhcp->address));
+                               state->timeout = DEFAULT_TIMEOUT;
+                       }
                        state->state = STATE_REQUESTING;
                        break;
                case STATE_REQUESTING:
In case of renewing or rebind the calculated timeout (from the values rebindtime minus renewaltime or leasetime minus rebindtime) value is tested against 0 and set to DEFAULT_TIMEOUT (20 seconds) and logging message printed.

From /var/log/messages with patch applied to dhcpcd:

Feb 11 16:35:30 linux-klms dhcpcd[22479]: wlan0: dhcpcd 3.2.3 starting
Feb 11 16:35:30 linux-klms dhcpcd[22479]: wlan0: hardware address = 00:13:49:90:c9:bc
Feb 11 16:35:30 linux-klms dhcpcd[22479]: wlan0: broadcasting for a lease
Feb 11 16:35:50 linux-klms dhcpcd[22479]: wlan0: timed out
Feb 11 16:35:50 linux-klms dhcpcd[22479]: wlan0: trying to use old lease in `/var/lib/dhcpcd/dhcpcd-wlan0.info'
Feb 11 16:35:50 linux-klms dhcpcd[22479]: wlan0: adding IP address 192.168.2.100/24
Feb 11 16:35:50 linux-klms dhcpcd[22479]: wlan0: adding default route via 192.168.2.1 metric 0
Feb 11 16:35:57 linux-klms dhcpcd[22479]: wlan0: Failed to lookup hostname via DNS: Name or service not known
Feb 11 16:35:57 linux-klms dhcpcd[23814]: wlan0: renewing lease of 192.168.2.100
Feb 11 16:35:57 linux-klms dhcpcd[23814]: wlan0: renewing lease of 192.168.2.100 set default timeout
Feb 11 16:35:57 linux-klms dhcpcd[22479]: wlan0: exiting
Feb 11 16:35:57 linux-klms dhcpcd[23814]: wlan0: leased 192.168.2.100 for infinity
Feb 11 16:35:57 linux-klms dhcpcd[23814]: wlan0: adding IP address 192.168.2.100/24
Feb 11 16:35:57 linux-klms dhcpcd[23814]: wlan0: adding default route via 192.168.2.1 metric 0
Note the line with 'renewing lease of 192.168.2.100 set default timeout'.

Reported to openSUSE/Novell Bugzilla https://bugzilla.novell.com/show_bug.cgi?id=579438.


<< back to projects page