Bug 1483343 - NetworkManager-wait-online.service completes too early when device has no carrier for unusually long time
Summary: NetworkManager-wait-online.service completes too early when device has no car...
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: NetworkManager
Version: 26
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Lubomir Rintel
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-08-20 18:24 UTC by W. Michael Petullo
Modified: 2018-05-29 12:02 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-05-29 12:02:04 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
nm.log (124.96 KB, text/plain)
2017-08-31 18:14 UTC, Barry Scott
no flags Details

Description W. Michael Petullo 2017-08-20 18:24:49 UTC
Description of problem:
I use autofs along with an LDAP-based configuration, and this requires that the network is up before running. However, autofs starts before the computer's Ethernet network interface has an IP address.

Version-Release number of selected component (if applicable):
NetworkManager-1.8.2-1.fc26.x86_64
autofs-5.1.2-2.fc26.x86_64

How reproducible:
Every time

Steps to Reproduce:
Activate NetworkManager-wait-online.service and boot.

Actual results:
journalctl -b 0 reports:

Line 1246: Starting Network Manager Wait Online...
Line 1283: dhcp-init: Using DHCP client 'dhclient'
Line 1308: device (enp2s0): state changed: unmanaged -> unavailable (reason 'managed', internal state 'external')
Line 1373: Started Network Manager Wait Online.
Line 1394: enp2s0: Link is up at 100 Mbps, full duplex, flow control both
Line 1414: DHCPREQUEST on enp2s0 to 255.255.255.255 port 67
Line 1415: DHCPACK from w.x.y.z

Expected results:
I would expect the value on line 1444 ("DHCPACK") to occur before "Started Network Manager Wait Online."

Additional info:

Comment 1 W. Michael Petullo 2017-08-20 20:30:39 UTC
> I would expect the value on line 1444 ("DHCPACK") to occur before "Started
> Network Manager Wait Online."

This should read: "I would expect the value on line 1415 ("DHCPACK") ..."

Comment 2 W. Michael Petullo 2017-08-20 20:34:29 UTC
I found that replacing in /lib/systemd/system/NetworkManager-wait-online.service:

    ExecStart=/usr/bin/nm-online -s -q --timeout=30

with:

    ExecStart=/usr/bin/nm-online -q --timeout=30

(i.e., removing the "-s") fixed my problem. This begs a question: why would NetworkManager-wait-online.service merely wait for NetworkManager to start instead of waiting for the interface itself to come up? The "-s" flag does not seem to serve legacy services well, and it seems counter to what "wait-online" means.

Comment 3 Thomas Haller 2017-08-22 12:41:44 UTC
"-s" means to wait at start of NM until the configuration of interfaces is completed (settled).

There is not enough information here to say why it didn't wait. Enable level=TRACE logging in /etc/NetworkManager/NetworkManager.conf and reboot to reproduce the issue and provide logfiles. See comment about private data here: https://cgit.freedesktop.org/NetworkManager/NetworkManager/plain/contrib/fedora/rpm/NetworkManager.conf?id=master

"-s" options waits until you see in NetworkManager's logfile the message "manager: startup complete"

Note that if you enable both IPv4 + IPv6 (which is the default), and both ipv4.may-fail and ipv6.may-fail is set to TRUE (which is also the default), an interface is considered as activated when only one address family completes.

Comment 4 Barry Scott 2017-08-31 18:13:41 UTC
Here is the log showing the failure create using the command:

journalctl -b -u NetworkManager-wait-online -a -u NetworkManager -u check-dns-working >/tmp/nm.log

Comment 5 Barry Scott 2017-08-31 18:14:58 UTC
Created attachment 1320693 [details]
nm.log

The result of running:

journalctl -b -u NetworkManager-wait-online -a -u NetworkManager -u check-dns-working >/tmp/nm.log

Comment 6 Thomas Haller 2017-08-31 18:36:44 UTC
in the log you see, that the interface has no carrier. NM waits up to 5 seconds for it. Since it still has no carrier, it declares "startup complete", at [1504202080.6703]


A bit later, at [1504202081.3146], does the device get carrier and activation proceeds, but the NM-wait-online already completed.


The carrier-wait-timeout is currently hard-coded to 5 seconds. 


Why does it take so long for you?

Comment 7 Barry Scott 2017-08-31 20:18:41 UTC
Maybe the dmesg for eth will show you show thing:

[    1.280725] r8169 0000:03:00.0 eth0: RTL8168g/8111g at 0xffffbab5419b9000, 14:dd:a9:dc:52:da, XID 0c000800 IRQ 28
[    1.280726] r8169 0000:03:00.0 eth0: jumbo features [frames: 9200 bytes, tx checksumming: ko]
[    1.296844] r8169 0000:03:00.0 enp3s0: renamed from eth0
[   17.441988] IPv6: ADDRCONF(NETDEV_UP): enp3s0: link is not ready
[   17.572343] r8169 0000:03:00.0 enp3s0: link down
[   17.572344] r8169 0000:03:00.0 enp3s0: link down
[   17.572384] IPv6: ADDRCONF(NETDEV_UP): enp3s0: link is not ready
[   23.650147] r8169 0000:03:00.0 enp3s0: link up
[   23.650154] IPv6: ADDRCONF(NETDEV_CHANGE): enp3s0: link becomes ready

I am wondering if a switch setting is affecting things. I will
check and add more info.

Comment 8 Barry Scott 2017-09-07 17:50:47 UTC
I found that the on-board ethernet card was failing.

Having replaced with a intel ethernet PCIe card I see this working as you
expected.

Comment 9 Thomas Haller 2017-09-07 19:29:51 UTC
related is https://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=a17195b844742be3e01e89e2e5433b600a909ae9 and bug 1487702

In that case, we extend the timeout waiting for carrier after changing the MTU from 5 to 10 seconds.

This has no effect for the present issue, because here NM doesn't even start activating the interface as long as it's waiting for carrier. Here it's about waiting for carrier on start (before declaring startup-complete).

But it's related in the sense, that sometimes it just takes awfully long and we may need to adjust the timeout.



I don't think we want to extend the default timeout, because 5 seconds is already plenty and extending it blocks NM-wait-online for all usecase (if you boot without cable plugged in).


But probably we should make it configurable (per device)...

Comment 10 Thomas Haller 2017-11-21 14:53:46 UTC
see also https://bugzilla.redhat.com/show_bug.cgi?id=1515027#c2

Comment 12 Fedora End Of Life 2018-05-03 08:21:42 UTC
This message is a reminder that Fedora 26 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 26. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '26'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 26 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

Comment 13 Fedora End Of Life 2018-05-29 12:02:04 UTC
Fedora 26 changed to end-of-life (EOL) status on 2018-05-29. Fedora 26
is no longer maintained, which means that it will not receive any
further security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.