Comment 5 for bug 1533631

Revision history for this message
TJ (tj) wrote : Re: Failed to renew DHCPv6 lease after suspend

Further debugging indicates that when the IPv6 lease file contains an expired lease as its last entry dhclient 'depreferences' it (gives it up) but doesn't go on to attempt to gain a replacement lease because NM cancels (kills) the dhclient process as a result of the 'expires' message.

NM starts "dhclient ... -6 ... -cf dhclient6-${IF}.conf ${IF}" but kills it and deletes the config file immediately although it leaves the lease file in place.

I managed to capture the .conf file by waiting for NM to close it and then making a copy before it was deleted:

sudo touch /var/lib/NetworkManager/dhclient6-${IF}.conf
inotifywait -e CLOSE_NOWRITE,CLOSE dhclient6-${IF}.conf; cp dhclient6-${IF}.conf /tmp/

I then executed dhclient in debug mode (after moving the .conf file into /etc/dhcp/ to avoid apparmor denying access to the file in /tmp/) and found that after the 'depreference' there is a delay of several minutes before dhclient requests a new lease:

$ sudo cp /tmp/dhclient6-${IF}.conf /etc/dhcp/

$ sudo /sbin/dhclient -d -6 -N -lf /var/lib/NetworkManager/dhclient6-0775a2a6-a4a1-40bf-bd85-9c3068582dbc-wlp3s0.lease -cf /etc/dhcp/dhclient6-wlp3s0.conf wlp3s0 |& tee /tmp/dhclient6.test.log

Internet Systems Consortium DHCP Client 4.3.1
Copyright 2004-2014 Internet Systems Consortium.
All rights reserved.
For info, please visit https://www.isc.org/software/dhcp/

Listening on Socket/wlp3s0
Sending on Socket/wlp3s0
PRC: Confirming active lease (INIT-REBOOT).
XMT: Forming Confirm, 0 ms elapsed.
XMT: X-- IA_NA 3b:bd:74:85
XMT: | X-- Confirm Address 2a02:8011:2007::2
XMT: V IA_NA appended.
XMT: Confirm on wlp3s0, interval 1020ms.
RCV: Reply message on wlp3s0 from fe80::ee43:f6ff:fe46:c080.
RCV: X-- Server ID: 00:03:00:01:ec:43:f6:46:c0:80
message status code Success.
PRC: Bound to lease 00:03:00:01:ec:43:f6:46:c0:80.
PRC: Rebind event scheduled in -294538 seconds, to run for 17280 seconds.
PRC: Depreference scheduled in -277258 seconds.
PRC: Expiration scheduled in -277258 seconds.
PRC: Rebinding lease on wlp3s0.
PRC: Depreference scheduled in -277258 seconds.
PRC: Expiration scheduled in -277258 seconds.
PRC: Address 2a02:8011:2007::2 depreferred.
PRC: Expiration scheduled in -277258 seconds.
PRC: Address 2a02:8011:2007::2 expired.
PRC: Bound lease is devoid of active addresses. Re-initializing.
PRC: Soliciting for leases (INIT)

... very very long delay (several minutes) ...

XMT: Forming Solicit, 0 ms elapsed.
XMT: X-- IA_NA 3b:bd:74:85
XMT: | X-- Request renew in +3600
XMT: | X-- Request rebind in +5400
XMT: Solicit on wlp3s0, interval 1080ms.
RCV: Advertise message on wlp3s0 from fe80::ee43:f6ff:fe46:c080.
RCV: X-- IA_NA 3b:bd:74:85
RCV: | X-- starts 1459366132
RCV: | X-- t1 - renew +43200
RCV: | X-- t2 - rebind +69120
RCV: | X-- [Options]
RCV: | | X-- IAADDR 2a02:8011:2007::2
RCV: | | | X-- Preferred lifetime 86400.
RCV: | | | X-- Max lifetime 86400.
RCV: X-- Server ID: 00:03:00:01:ec:43:f6:46:c0:80
RCV: Advertisement recorded.
PRC: Selecting best advertised lease.
PRC: Considering best lease.
PRC: X-- Initial candidate 00:03:00:01:ec:43:f6:46:c0:80 (s: 156, p: 0).
XMT: Forming Request, 0 ms elapsed.
XMT: X-- IA_NA 3b:bd:74:85
XMT: | X-- Requested renew +3600
XMT: | X-- Requested rebind +5400
XMT: | | X-- IAADDR 2a02:8011:2007::2
XMT: | | | X-- Preferred lifetime +7200
XMT: | | | X-- Max lifetime +7500
XMT: V IA_NA appended.
XMT: Request on wlp3s0, interval 1070ms.
RCV: Reply message on wlp3s0 from fe80::ee43:f6ff:fe46:c080.
RCV: X-- IA_NA 3b:bd:74:85
RCV: | X-- starts 1459366133
RCV: | X-- t1 - renew +43200
RCV: | X-- t2 - rebind +69120
RCV: | X-- [Options]
RCV: | | X-- IAADDR 2a02:8011:2007::2
RCV: | | | X-- Preferred lifetime 86400.
RCV: | | | X-- Max lifetime 86400.
RCV: X-- Server ID: 00:03:00:01:ec:43:f6:46:c0:80
PRC: Bound to lease 00:03:00:01:ec:43:f6:46:c0:80.
PRC: Renewal event scheduled in 43200 seconds, to run for 25920 seconds.
PRC: Depreference scheduled in 86400 seconds.
PRC: Expiration scheduled in 86400 seconds.

And it continues running.

In the Network Manager case though syslog shows that NM cancels (kills) the dhclient process when dhclient reports the 'expire' for the out-of-date lease:

Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> Activation (wlp3s0) Beginning DHCPv6 transaction (timeout in 45 seconds)
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> dhclient started with pid 22416
Mar 30 20:08:42 hephaestion dhclient: XMT: Confirm on wlp3s0, interval 940ms.
Mar 30 20:08:42 hephaestion dhclient: RCV: Reply message on wlp3s0 from fe80::ee43:f6ff:fe46:c080.
Mar 30 20:08:42 hephaestion dhclient: message status code Success.
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> valid_lft 86400
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> preferred_lft 86400
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> address 2a02:8011:2007::2
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> nameserver '2a02:8010:1:0:212:23:3:100'
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> (wlp3s0): DHCPv6 state changed unknown -> bound
Mar 30 20:08:42 hephaestion dnsmasq[2044]: setting upstream servers from DBus
Mar 30 20:08:42 hephaestion dhclient: PRC: Rebinding lease on wlp3s0.
Mar 30 20:08:42 hephaestion dnsmasq[2044]: using nameserver 10.254.1.254#53
Mar 30 20:08:42 hephaestion dnsmasq[2044]: using nameserver 10.254.0.254#53
Mar 30 20:08:42 hephaestion dnsmasq[2044]: using nameserver 2a02:8010:1:0:212:23:3:100#53
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> Writing DNS information to /sbin/resolvconf
Mar 30 20:08:42 hephaestion nm-dispatcher: Dispatching action 'dhcp6-change' for wlp3s0
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> (wlp3s0): DHCPv6 state changed bound -> unknown
Mar 30 20:08:42 hephaestion dhclient: PRC: Address 2a02:8011:2007::2 depreferred.
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> (wlp3s0): DHCPv6 state changed unknown -> expire
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> (wlp3s0): canceled DHCP transaction, DHCP client pid 22416
Mar 30 20:08:42 hephaestion NetworkManager[1506]: <info> (wlp3s0): DHCPv6 state changed expire -> done