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
--
You received this bug notification because you are a member of Desktop
Packages, which is subscribed to network-manager in Ubuntu.
https://bugs.launchpad.net/bugs/1533631
Title:
Failed to renew DHCPv6 lease after suspend
Status in isc-dhcp package in Ubuntu:
Triaged
Status in network-manager package in Ubuntu:
Confirmed
Bug description:
After fixing IPv6 address assignment (#1469346), IPv6 works fine until
sleep. On wake up ubuntu fails to renew its IPv6 lease:
Jan 13 10:47:47 ubuntu dhclient: PRC: Renewing lease on wlp3s0.
Jan 13 10:47:47 ubuntu dhclient: PRC: Rebinding lease on wlp3s0.
Jan 13 10:47:47 ubuntu dhclient: XMT: Rebind on wlp3s0, interval 9890ms.
Jan 13 10:47:47 ubuntu NetworkManager[796]: <info> (wlp3s0): DHCPv6 state
changed bound -> unknown
Jan 13 10:47:47 ubuntu dhclient: PRC: Address 2a02:xxxx:xxxx:xxxx::b44
depreferred.
Jan 13 10:47:47 ubuntu NetworkManager[796]: <info> (wlp3s0): DHCPv6 state
changed unknown -> expire
Jan 13 10:47:47 ubuntu NetworkManager[796]: <info> (wlp3s0): canceled DHCP
transaction, DHCP client pid 1170
Jan 13 10:47:47 ubuntu NetworkManager[796]: <info> (wlp3s0): DHCPv6 state
changed expire -> done
I'm not sure that it's solely NetworkManager issue (dhclient could
also be affected).
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/isc-dhcp/+bug/1533631/+subscriptions
--
Mailing list: https://launchpad.net/~desktop-packages
Post to : desktop-packages@lists.launchpad.net
Unsubscribe : https://launchpad.net/~desktop-packages
More help : https://help.launchpad.net/ListHelp
