Bug 993516 - wicked - DHCPv6 lease committed 8 minutes after Ethernet interface is up
wicked - DHCPv6 lease committed 8 minutes after Ethernet interface is up
Status: RESOLVED DUPLICATE of bug 972471
: 975933 (view as bug list)
Classification: openSUSE
Product: openSUSE Distribution
Classification: openSUSE
Component: Network
13.2
x86-64 openSUSE 13.2
: P5 - None : Normal (vote)
: ---
Assigned To: wicked maintainers
E-mail List
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2016-08-12 13:16 UTC by Donald Curtis
Modified: 2016-11-23 17:30 UTC (History)
2 users (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments
ifconfig immediately after the KDM Greeter appeared. (976 bytes, text/plain)
2016-08-12 13:16 UTC, Donald Curtis
Details
ifconfig after the DHCPv6 lease was committed. (1.14 KB, text/plain)
2016-08-12 13:17 UTC, Donald Curtis
Details
Journal filtered for the network setup. (7.21 KB, text/plain)
2016-08-12 13:18 UTC, Donald Curtis
Details
Wireshark trace (62.33 KB, application/octet-stream)
2016-08-12 13:18 UTC, Donald Curtis
Details
ifconfig -- Leap 42.1 and Network Manager (1.41 KB, text/plain)
2016-08-12 13:36 UTC, Donald Curtis
Details
Leap 42.1 and Network Manager Journal filtered for network setup. (14.54 KB, text/plain)
2016-08-12 13:38 UTC, Donald Curtis
Details
17th August: Journal filtered for the network setup (6.82 KB, text/plain)
2016-08-17 14:13 UTC, Donald Curtis
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Donald Curtis 2016-08-12 13:16:11 UTC
Created attachment 687914 [details]
ifconfig immediately after the KDM Greeter appeared.

Bug 916956 - "Acquiring of IPv6 address is delayed" dated February 2015 through April 2016 looks almost the same but, there are comments indicating that, from the view of the originator, the issue reported there has disappeared.
-----------------------------------------------------------------
Linux 3.16.7-35-desktop openSUSE 13.2 (Harlequin) (x86_64)
wicked Version: 0.6.31-33.1
Searching the journal for the period 20th April 2016 through to now, from the time that the Ethernet interface is up until, the DHCPv6 lease is committed, mostly 7 to 9 minutes pass. There were a few examples of 3 to 4 minutes but, they're the exception.
-----------------------------------------------------------------
The DSL Router and DHCP server is an AVM FRITZ!Box 7490.
The same behaviour occurred with an AVM FRITZ!Box 7270 in use up until spring this year.
-----------------------------------------------------------------
Attached: traces from today:
 - ifconfig before and after the DHCPv6 lease was committed;
 - today's Journal -- filtered: grep -iE 'network|wicked|avahi|DHCP|v4|v6|ntp'
 - Wireshark trace of the Ethernet segment -- filtered:
   only the 13.2 machine's traffic.
Comment 1 Donald Curtis 2016-08-12 13:17:25 UTC
Created attachment 687915 [details]
ifconfig after the DHCPv6 lease was committed.
Comment 2 Donald Curtis 2016-08-12 13:18:12 UTC
Created attachment 687916 [details]
Journal filtered for the network setup.
Comment 3 Donald Curtis 2016-08-12 13:18:41 UTC
Created attachment 687917 [details]
Wireshark trace
Comment 4 Donald Curtis 2016-08-12 13:36:55 UTC
Created attachment 687923 [details]
ifconfig -- Leap 42.1 and Network Manager
Comment 5 Donald Curtis 2016-08-12 13:38:05 UTC
Created attachment 687924 [details]
Leap 42.1 and Network Manager Journal filtered for network setup.
Comment 6 Donald Curtis 2016-08-12 13:41:26 UTC
For comparison: same Ethernet segment, same DSL Router and DHCP server, but:
Leap 42.1 Laptop and Network Manager -- the WLAN is deactivated.
-----------------------------------------------------------------
The DHCPv6 lease is committed about 4 seconds after the Ethernet interface comes up.
-----------------------------------------------------------------
Attached: traces from today:
 - ifconfig -- Leap 42.1
 - today's Journal -- filtered: grep -iE 'network|avahi|DHCP|v4|v6|ntp'
Comment 7 Nirmoy Das 2016-08-17 09:54:22 UTC
Can you please try below  workaround and let me know the result.

--- Copied Mail from Marius --
This looks like 
a) there are two routers sending out an RA [missed switch security], one in managed mode, one unmanaged or 

b) a duplicate of a kernel bug [fixed in sle12-ga-update and accepted to 3.x stable kernels upstream] forgetting to send a newlink event when RA arrives and changes the AdvManaged flag.

workaround: set DHCLIENT6_MODE=managed in ifcfg file. Default is "auto" to follow advise in the RA forwarded to userspace in kernel newlink event.
------
Comment 8 Donald Curtis 2016-08-17 14:12:08 UTC
The workaround "set DHCLIENT6_MODE=managed in ifcfg file" didn't change anything (in my case).
-------------------------------------------------------------
But, taking points made by Nirmoy I checked the contents of /etc/sysconfig/network/ and made the following changes:
 - In "config" decreased WAIT_FOR_INTERFACES from '30' to '8'.
 - In "dhcp" made the following changes:
 * DHCLIENT_RELEASE_BEFORE_QUIT and DHCLIENT6_RELEASE_BEFORE_QUIT set to "yes".
 * DHCLIENT_WAIT_AT_BOOT and DHCLIENT6_WAIT_AT_BOOT decreased from '15' to '4'.

Additionally I commented out an extraneous DHCLIENT_SET_DEFAULT_ROUTE='yes' in ifcfg-enp2s0.

The DHCPv6 lease is now committed 4 seconds after the Ethernet interface is up.
And, the wicked service is now taking only 6.610s at boot.
I'll attach the filtered Journal from this boot.
 ** I'll add a comment to Bug 975933.
Comment 9 Donald Curtis 2016-08-17 14:13:35 UTC
Created attachment 688386 [details]
17th August: Journal filtered for the network setup
Comment 10 Donald Curtis 2016-08-18 09:04:39 UTC
Further investigation with this morning's boot:
--------------------------------------------------------------------
Aug 18 08:52:10 eck001 kernel: r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
Aug 18 08:52:15 eck001 systemd[1]: Started wicked network management service daemon.
Aug 18 08:52:15 eck001 systemd[1]: Started wicked network nanny service.
Aug 18 08:52:16 eck001 kernel: r8169 0000:02:00.0 enp2s0: link down
Aug 18 08:52:16 eck001 kernel: r8169 0000:02:00.0 enp2s0: link down
Aug 18 08:52:16 eck001 kernel: IPv6: ADDRCONF(NETDEV_UP): enp2s0: link is not ready
Aug 18 08:52:18 eck001 kernel: r8169 0000:02:00.0 enp2s0: link up
Aug 18 08:52:18 eck001 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0: link becomes ready
Aug 18 08:52:20 eck001 avahi-daemon[885]: New relevant interface enp2s0.IPv6 for mDNS.
Aug 18 08:52:20 eck001 avahi-daemon[885]: Registering new address record for fe80::16da:e9ff:feec:a04d on enp2s0.*.
Aug 18 08:52:22 eck001 wicked[959]: lo              up
Aug 18 08:52:22 eck001 wicked[959]: enp2s0          up
Aug 18 08:52:27 eck001 wickedd-dhcp6[953]: enp2s0: Accepting best DHCPv6 lease offer with weight 1 from server fe80::16da:e9ff:feec:a04d
Aug 18 08:52:27 eck001 wickedd-dhcp6[953]: enp2s0: Committed DHCPv6 lease
--------------------------------------------------------------------
Time between the kernel loading the driver and link up/ready: 8 s.
Time between the kernel loading the driver and systemd starting wicked: 5 s.
Time between wicked being started and acknowledging the interface as being "up": 7 s.
Time between wicked acknowledging that the interface as being "up" and the DHCPv6 lease being committed: 3 s.
--------------------------------------------------------------------
Given 8 s between the kernel loading the driver and acknowledging the link as being up/ready, the value of 8 s in config:WAIT_FOR_INTERFACES is possibly too tight -- I'll increase it to 10 s.
The values of dhcp:DHCLIENT_WAIT_AT_BOOT and dhcp:DHCLIENT6_WAIT_AT_BOOT could be increased to 5 s but, I can't see any reason to do so:
 - there seems to be only a requirement that WAIT_FOR_INTERFACES is at least double the value of the DHCP client "wait at boot" times.
--------------------------------------------------------------------
One point that should maybe not be overlooked is that, the AVM FRITZ!Box 7490 DSL Router (and possibly other AVM models as well) seems to need the DHCP clients to sign off (release) before the DHCP client shuts down.
--------------------------------------------------------------------
Does this "wicked tuning" procedure need to be documented?
Comment 11 Marius Tomaschewski 2016-11-23 17:07:16 UTC
(In reply to Donald Curtis from comment #10)
> Further investigation with this morning's boot:
> --------------------------------------------------------------------
> Aug 18 08:52:10 eck001 kernel: r8169 Gigabit Ethernet driver 2.3LK-NAPI
> loaded
> Aug 18 08:52:15 eck001 systemd[1]: Started wicked network management service
> daemon.
> Aug 18 08:52:15 eck001 systemd[1]: Started wicked network nanny service.
> Aug 18 08:52:16 eck001 kernel: r8169 0000:02:00.0 enp2s0: link down
> Aug 18 08:52:16 eck001 kernel: r8169 0000:02:00.0 enp2s0: link down
> Aug 18 08:52:16 eck001 kernel: IPv6: ADDRCONF(NETDEV_UP): enp2s0: link is
> not ready

this is from "ip link set up enp2s0", the kernel starts to detect carrier.

> Aug 18 08:52:18 eck001 kernel: r8169 0000:02:00.0 enp2s0: link up

carrier detected.

> Aug 18 08:52:18 eck001 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0: link
> becomes ready

the kernel assigns fe80:: address to the device marked it tentative (not yet usable) and starts preforms duplicate address detection (sends probe packet
and waits 1sec for duplicate reports).
once fe80:: is detected to be unique, the kernel joins multicast groups using
it and sends out RS (RA request) to the IPv6 router, which responds with RA
that contains info if to use dhcp6 and in which mode (managed address or
info-only).

Even wickedd-dhcp6 gets the request earlier, it waits until fe80:: address
becomes ready (it is using it to send packages to dhcp server).

Further, in DHCLIENT6_MODE=auto, it waits also for the router RA to provide
the mode (managed or info) setting. wickedd* does not listen for the RA directly: to be consistent with the info kernel provides, it is using the
kernel device flags and events emitted by the kernel when RA arrives and
has been processed [when it does not forget it ... bug 972471 comment 65).

Once the mode is given (by RA or setting), it starts sending dhcp6 packets
as ipv6 multicasts from fe80::... to the ff02::1:2 all-dhcp-servers-and-relays
address.

(When the RA contains a /64 prefix with autonomous=true, kernel assigns an
 $prefix:$EUI64 (on ethernet, EUI64 is mac based suffix same to fe80::EUI64)
 and if privacy extensions are enabled, also $prefix:$random and preforms
 duplicate address detection for it/them same as for fe80 address.
 Further, the kernel also sets the ipv6 default route to the ipv6 router).

> Aug 18 08:52:20 eck001 avahi-daemon[885]: New relevant interface enp2s0.IPv6
> for mDNS.
> Aug 18 08:52:20 eck001 avahi-daemon[885]: Registering new address record for
> fe80::16da:e9ff:feec:a04d on enp2s0.*.
> Aug 18 08:52:22 eck001 wicked[959]: lo              up
> Aug 18 08:52:22 eck001 wicked[959]: enp2s0          up

WAIT_FOR_INTERFACES alias "wicked ifup --timeout xxx eth0" is over and
ifup reports. When there is dhcp4 _or_ dhcp6 lease (BOOTPROTO=dhcp case)
it reports "up" for success. The other lease will arrive later and will
be processed in background.

> Aug 18 08:52:27 eck001 wickedd-dhcp6[953]: enp2s0: Accepting best DHCPv6
> lease offer with weight 1 from server fe80::16da:e9ff:feec:a04d

wickedd-dhcp6 received a response from dhcp6 server and accepts (request
or not rapid-commit)

> Aug 18 08:52:27 eck001 wickedd-dhcp6[953]: enp2s0: Committed DHCPv6 lease

and commits it (=sends to wickedd to apply). wickedd is applying it
and waiting until the address starts to be usable (non-tentative)
and sends addrconf-up event ->nanny->ifup to continue and report
lease as granted (if ifup is still waiting for it).

In this case, the lease is applied after ifup returned already due to
a short WAIT_FOR_INTERFACES.

> --------------------------------------------------------------------
> Time between the kernel loading the driver and link up/ready: 8 s.
> Time between the kernel loading the driver and systemd starting wicked: 5 s.
> Time between wicked being started and acknowledging the interface as being
> "up": 7 s.
> Time between wicked acknowledging that the interface as being "up" and the
> DHCPv6 lease being committed: 3 s.

1 secs is needed for duplicate address detection per address (fe80 + dhcp
address -> 2sec) + time for RA and dhcp msg exchange and applying it.

> --------------------------------------------------------------------
> Given 8 s between the kernel loading the driver and acknowledging the link
> as being up/ready, the value of 8 s in config:WAIT_FOR_INTERFACES is
> possibly too tight -- I'll increase it to 10 s.

It depends on the driver nic how long the carrier detection/link up needs.
It is basically the LOWER_UP flag visible in "ip a s". Except of this,
some nics report carrier, but still need some time before they start to
forward packets at all.

> The values of dhcp:DHCLIENT_WAIT_AT_BOOT and dhcp:DHCLIENT6_WAIT_AT_BOOT
> could be increased to 5 s but, I can't see any reason to do so:
>  - there seems to be only a requirement that WAIT_FOR_INTERFACES is at least
> double the value of the DHCP client "wait at boot" times.

Something like this, yes. WAIT_FOR_INTERFACES is how long "ifup" waits
before it returns status. DHCLIENT*_WAIT_AT_BOOT how long we wait before
we say "currently can't get a lease" aka defer and continue in background
while it also causes ifup to stop waiting for the lease (inside of the
timeout specified via WAIT_FOR_INTERFACES).

We cannot change the defaults / timings by default, because they depend
on the NIC hardware and also on the network, router, switch, ...

> --------------------------------------------------------------------
> One point that should maybe not be overlooked is that, the AVM FRITZ!Box
> 7490 DSL Router (and possibly other AVM models as well) seems to need the
> DHCP clients to sign off (release) before the DHCP client shuts down.

Well, we cannot change defaults without a feature request, so it has
to remain as it is I fear. Documenting it somewhere would make sense.

> --------------------------------------------------------------------
> Does this "wicked tuning" procedure need to be documented?

This would be a good thing!

There is a wicked portal at https://en.opensuse.org/Portal:Wicked
and we could also add https://github.com/openSUSE/wicked/wiki and
look how to sync them...

See also https://github.com/openSUSE/wicked/blob/master/doc/FAQ.txt
Comment 12 Marius Tomaschewski 2016-11-23 17:18:49 UTC
(In reply to Donald Curtis from comment #0)
> Created attachment 687914 [details]
> ifconfig immediately after the KDM Greeter appeared.
> 
> Bug 916956 - "Acquiring of IPv6 address is delayed" dated February 2015
> through April 2016 looks almost the same but, there are comments indicating
> that, from the view of the originator, the issue reported there has
> disappeared.

I've made kernel fixes upstream, but they have been still not applied
or released.

> -----------------------------------------------------------------
> Linux 3.16.7-35-desktop openSUSE 13.2 (Harlequin) (x86_64)
> wicked Version: 0.6.31-33.1
> Searching the journal for the period 20th April 2016 through to now, from
> the time that the Ethernet interface is up until, the DHCPv6 lease is
> committed, mostly 7 to 9 minutes pass. There were a few examples of 3 to 4
> minutes but, they're the exception.

When this happens (kernel does not forward the RA settings to userspace due
to some timings in the RA set to 0 [unspecified / no special preference]),
you can always set DHCLIENT6_MODE=managed or info to not wait for IPv6 RA.

See the "see also" bug list in bug 972471 or bug 972471 comment 65.

Please try out if wicked 0.6.39, where I've fixed/improved the workaround
for the missed kernel events (13.2 update request in progress) works better.

You can find most recent wicked version RPMs also:

http://download.opensuse.org/repositories/network:/wicked:/factory/openSUSE_13.2_Update/

I don't see anything new in this bug report, except of the attempts to
tune the wait times [which work for you, but would cause too much trouble
with other hardware].

*** This bug has been marked as a duplicate of bug 972471 ***
Comment 13 Marius Tomaschewski 2016-11-23 17:30:07 UTC
*** Bug 975933 has been marked as a duplicate of this bug. ***