Bug 1183321 - [enh] only block startup for specific connections
Summary: [enh] only block startup for specific connections
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: NetworkManager
Version: 21
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: 2015-01-18 15:53 UTC by lionghostshop
Modified: 2015-12-02 17:07 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-12-02 07:35:41 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
systemd-analyze plot result (112.65 KB, image/svg+xml)
2015-01-19 01:15 UTC, lionghostshop
no flags Details
journalctl -u NetworkManager -b 0 (377.59 KB, text/plain)
2015-01-21 14:36 UTC, lionghostshop
no flags Details
boot time graph by systemd-analyze plot (99.80 KB, image/png)
2015-01-22 14:47 UTC, lionghostshop
no flags Details


Links
System ID Private Priority Status Summary Last Updated
GNOME Bugzilla 700651 0 None None None Never

Description lionghostshop 2015-01-18 15:53:07 UTC
Description of problem:


Version-Release number of selected component (if applicable):
NetworkManager-0.9.10.1-1.4.20150115git.fc21.x86_64

How reproducible:


Steps to Reproduce:
1. Update to NetworkManager-0.9.10.1-1.4.20150115git.fc21.x86_64
2. Reboot


Actual results:
Booting is very slow. Note I am using SSD and it used to be very fast. 
   31.461s NetworkManager-wait-online.service
          1.497s plymouth-start.service
          1.355s systemd-udev-settle.service
           900ms lvm2-monitor.service
           667ms lvm2-pvscan@8:2.service
           378ms firewalld.service
           310ms plymouth-quit-wait.service
           288ms vboxdrv.service
           276ms NetworkManager.service
           210ms home-leo-huge.mount
           168ms dmraid-activation.service
           144ms accounts-daemon.service
           138ms packagekit.service
           124ms cups.service
           122ms libvirtd.service
           110ms systemd-hostnamed.service
            96ms lm_sensors.service
            85ms chronyd.service
            78ms systemd-localed.service
            75ms home-leo-msata.mount
            73ms rtkit-daemon.service
            70ms netcf-transaction.service
            69ms home.mount
            69ms mcelog.service
            69ms nfs-config.service
            69ms gssproxy.service
            67ms avahi-daemon.service
            64ms systemd-vconsole-setup.service
            63ms rsyslog.service
            59ms udisks2.service
            42ms systemd-binfmt.service
            37ms var-lib-nfs-rpc_pipefs.mount
            35ms systemd-udevd.service
            34ms systemd-fsck-root.service
            29ms auditd.service
            28ms proc-fs-nfsd.mount
            28ms polkit.service
            24ms dev-mapper-fedora\x2dswap.swap
            22ms systemd-logind.service
            19ms gdm.service
            18ms colord.service
            17ms wpa_supplicant.service
            17ms user
            15ms systemd-udev-trigger.service
            14ms systemd-tmpfiles-setup-dev.service
            13ms proc-sys-fs-binfmt_misc.mount
            13ms plymouth-read-write.service
            12ms systemd-fsck@dev-disk-by\x2duuid-97be306e\x2d352d\x2d4397\x2da6fb\x2da6116a1c45c7.service
            11ms fedora-readonly.service
            10ms systemd-journald.service
             8ms systemd-sysctl.service
             8ms upower.service
             8ms rpc-statd-notify.service


Expected results:
 Boot less than 8 seconds

Additional info:
The output of systemctl is

● NetworkManager-wait-online.service                                                        loaded failed failed    Network Manager Wait Online

I also attach the output of journalctl.

Comment 1 lionghostshop 2015-01-19 01:15:57 UTC
Created attachment 981267 [details]
systemd-analyze plot result

Comment 2 Thomas Haller 2015-01-21 10:32:11 UTC
Can you attach the logfile of NetworkManager with DEBUG log enabled?

You enable debug logging by editing /etc/NetworkManager/NetworkManager.conf:

[logging]
level=DEBUG
domains=ALL


Then reboot, and get the output of `journalctl -u NetworkManager -b 0`


Thank you

Comment 3 lionghostshop 2015-01-21 14:36:32 UTC
Created attachment 982350 [details]
journalctl -u NetworkManager -b 0

Comment 4 Thomas Haller 2015-01-21 17:48:16 UTC
NetworkManger-wait-online waits until your wifi is connected, which takes a while in your case.

Since it is not (yet) configurable for which interfaces to wait during NetworkManger-wait-online, startup is blocked waiting until the initial connection attempt completes.

See also: http://www.freedesktop.org/wiki/Software/systemd/NetworkTarget/


Note that network-online depends on NetworkManager-wait-online. But you get only delays for serices that depend on network-online. So, does this actually affect you?

If you don't want to wait for network to be fully configured, you should just `systemctl disable NetworkManager-wait-online` and "network-online" will complete together with "network"

Comment 5 lionghostshop 2015-01-22 04:45:55 UTC
I have tried systemctl disable NetworkManager-wait-online and network-online. It seems it still starts on each boot. I don't understand why it cannot be disabled. 
The booting used to be very fast (within 7 seconds). Now it became so slow. I think it should be some problem with the software.

Comment 6 Pavel Šimerda (pavlix) 2015-01-22 11:08:32 UTC
(In reply to Thomas Haller from comment #4)
> Since it is not (yet) configurable for which interfaces to wait during
> NetworkManger-wait-online, startup is blocked waiting until the initial
> connection attempt completes.

It would be if my original suggestion was implemented (see attached closed upstream bug report).

> If you don't want to wait for network to be fully configured, you should
> just `systemctl disable NetworkManager-wait-online`

This is no longer the case since:

https://bugzilla.gnome.org/show_bug.cgi?id=728965

(In reply to lionghostshop from comment #5)
> I have tried systemctl disable NetworkManager-wait-online and
> network-online. It seems it still starts on each boot. I don't understand
> why it cannot be disabled. 

It is actually pulled in by services that need it. You can check the individual services that pull in network-online.target whether they actually need it. You can no longer disable it the classic way as it's not a classic service/target.

Comment 7 lionghostshop 2015-01-22 11:45:53 UTC
I did not find any service that pull network-online.target as shown below. Any other way to check the dependency if I miss something?


[leo@thinkpad-leo ~]$ find /usr/lib/systemd/system/ -name network-online*
/usr/lib/systemd/system/network-online.target
/usr/lib/systemd/system/network-online.target.wants

Comment 8 Pavel Šimerda (pavlix) 2015-01-22 12:04:22 UTC
(In reply to lionghostshop from comment #7)
> I did not find any service that pull network-online.target as shown below.
> Any other way to check the dependency if I miss something?

Not sure, just tried this and I don't see anything on my system (not even Fedora, though).

# systemctl list-dependencies --reverse network-online.target
network-online.target

> [leo@thinkpad-leo ~]$ find /usr/lib/systemd/system/ -name network-online*
> /usr/lib/systemd/system/network-online.target
> /usr/lib/systemd/system/network-online.target.wants

# find /usr/lib/systemd /etc/systemd -name 'network-online*'
/usr/lib/systemd/system/network-online.target.wants
/usr/lib/systemd/system/network-online.target

Slightly more carefully constructed command, same results, please try it as it shows data from /etc.

Comment 9 Pavel Šimerda (pavlix) 2015-01-22 12:05:28 UTC
Also, as the result:

# systemctl status network-online.target
● network-online.target - Network is Online
   Loaded: loaded (/usr/lib64/systemd/system/network-online.target; static)
   Active: inactive (dead)
     Docs: man:systemd.special(7)
           http://www.freedesktop.org/wiki/Software/systemd/NetworkTarget

Comment 10 Pavel Šimerda (pavlix) 2015-01-22 12:11:23 UTC
(In reply to Pavel Šimerda (pavlix) from comment #8)
> # systemctl list-dependencies --reverse network-online.target
> network-online.target

# systemctl list-dependencies --reverse NetworkManager-wait-online
NetworkManager-wait-online.service
● └─network-online.target

This one's better. You need to ask for the actual service, not for the target, just in case there's some direct dependency which is perfectly possible.

Comment 11 lionghostshop 2015-01-22 13:35:19 UTC
[leo@thinkpad-leo ~]$ systemctl list-dependencies --reverse NetworkManager-wait-online
NetworkManager-wait-online.service
● └─network-online.target
●   ├─network.service
●   └─rpc-statd-notify.service
[leo@thinkpad-leo ~]$  find /usr/lib/systemd /etc/systemd -name 'network-online*'
/usr/lib/systemd/system/network-online.target
/usr/lib/systemd/system/network-online.target.wants


[leo@thinkpad-leo ~]$ systemctl list-dependencies --reverse network-online.target
network-online.target
● ├─network.service
● └─rpc-statd-notify.service

[leo@thinkpad-leo ~]$ systemctl status network-online.target
● network-online.target - Network is Online
   Loaded: loaded (/usr/lib/systemd/system/network-online.target; static)
   Active: active since Thu 2015-01-22 19:38:12 HKT; 1h 53min ago
     Docs: man:systemd.special(7)
           http://www.freedesktop.org/wiki/Software/systemd/NetworkTarget

I didn't find any service wants NetworkManager-wait-online.service.

Comment 12 lionghostshop 2015-01-22 13:56:59 UTC
Sorry, I misunderstood the graph. Does it means that network-online.target pulls NetworkManager-wait-online.service and another two services pulls network-online.target.

[leo@thinkpad-leo ~]$ systemctl status network.service
● network.service - LSB: Bring up/down networking
   Loaded: loaded (/etc/rc.d/init.d/network)
   Active: inactive (dead)
[leo@thinkpad-leo ~]$ systemctl status rpc-statd-notify.service
● rpc-statd-notify.service - Notify NFS peers of a restart
   Loaded: loaded (/usr/lib/systemd/system/rpc-statd-notify.service; static)
   Active: inactive (dead) since Thu 2015-01-22 19:38:12 HKT; 2h 14min ago
  Process: 1486 ExecStart=/usr/sbin/sm-notify $SMNOTIFYARGS (code=exited, status=0/SUCCESS)

I compare the result with my another SDD laptop, which boots fast and has the same system. It also has network-online.target active while NetworkManager-wait-online.service took 190ms. The current laptop used to boot fast as well and it became slow recent few days.

Comment 13 lionghostshop 2015-01-22 14:47:18 UTC
Created attachment 982853 [details]
boot time graph by systemd-analyze plot

It seems that wpa_supplicant.service took very long time. Is it a bug of it?

Comment 14 lionghostshop 2015-01-22 14:48:51 UTC
The complete graph can be found in the attachment called "systemd-analyze plot result"

Comment 15 Pavel Šimerda (pavlix) 2015-01-22 19:39:02 UTC
(In reply to lionghostshop from comment #11)
> [leo@thinkpad-leo ~]$ systemctl list-dependencies --reverse
> NetworkManager-wait-online
> NetworkManager-wait-online.service
> ● └─network-online.target

So far so good.

> ●   ├─network.service

Ah, you're using network.service. That's important and the information that it pulls in network-online.target is even more so.

The network.service should by no means pull in network-online.target. It should only be pulled in by services that *need* it, not by services that *provide* it. But that's not a NetworkManager issue. Will add Lukáš and Michal to Cc as this is closely related to our work on the semantics of $network in initscripts.

> ●   └─rpc-statd-notify.service

The service requests to wait for a fully configured network. But if you're not running this service, you can just ignore it.

My best guess is that we still need to improve the LSB $network dependency handling in the systemd initscript translator.

Comment 16 Pavel Šimerda (pavlix) 2015-01-22 19:41:34 UTC
In my opinion for your exact case, disabling the network.service would do the job.

# systemctl disable network
# reboot

NetworkManager handles your connections anyway.

Comment 17 lionghostshop 2015-01-23 02:07:10 UTC
I did 
 systemctl disable network
 reboot
Then, the boot is still slow

I got 
       15.181s NetworkManager-wait-online.service
         10.473s cups.service
          1.472s plymouth-start.service
          1.325s systemd-udev-settle.service
           379ms lvm2-monitor.service
           366ms firewalld.service
           292ms vboxdrv.service
           264ms plymouth-quit-wait.service
           228ms NetworkManager.service
           187ms lvm2-pvscan@8:2.service
           162ms dmraid-activation.service
           158ms home-leo-huge.mount
           149ms accounts-daemon.service
           101ms systemd-hostnamed.service
            96ms systemd-localed.service
            94ms lm_sensors.service

Comment 18 Michal Sekletar 2015-01-23 08:49:02 UTC
If I remember correctly $network LSB facility now translates to network-online.target, such dependency should be visible from listing of dependencies.

In this case it doesn't look like that some initscript (or other service for that matter) is pulling it in. However NetworkManager-wait-online.service maybe pulled to boot transaction not by dependency in the beginning rather is added later dynamically after we started initial transaction.

If you mask NetworkManager-wait-online.service add "debug" to kernel command line then from output of "journalctl -b" it should be possible to find out from which process originates request for starting wait-online and to which services that process belongs to.

Comment 19 lionghostshop 2015-01-23 08:58:26 UTC
I am curious why NetworkManager-wait-online.service takes little time on my other fedora computers. Right now, only my thinkpad T400 is slow. It was fast before. Above discussion focuses on why NetworkManager-wait-online.service is pulled. Any way to find out why it becomes slow. 
See my attached file "boot time graph by systemd-analyze plot", it also shows that wpa_supplicant is slow. Is it a bug of it?

Comment 20 Dan Williams 2015-01-29 20:11:13 UTC
NM-wait-online.service will wait for NetworkManager to declare that a connection is available and that the machine is "online".  That is done by waiting for all "autoconnect" connections to be connected, or to fail, when NM starts up.

If you look at the logs, NM starts here:

Jan 21 22:33:59 thinkpad-leo NetworkManager[1053]: <info>  NetworkManager (version 0.9.10.1-1.4.20150115git.fc21) is starting...

and NM declares startup complete here:

Jan 21 22:34:15 thinkpad-leo NetworkManager[1053]: <info>  Activation (wlp4s0) successful, device activated.
Jan 21 22:34:15 thinkpad-leo NetworkManager[1053]: <info>  startup complete

The timeline is:

0: NM starts
+1: NM starts em1
+2: NM starts PPPoE on em1
+3: wifi scan finds "Fedora Linux Wifi 1" SSID and NM begins to connect
+7: WiFi is finally associated
+7: PPPoE server finally responds, PPPoE/em1 configured and ready
+7: First DHCP request is sent over WiFi, no reply
+15: Second DHCP request is sent and gets a reply
+15: WiFi finally configured

So it's taken 15 seconds to connect the wifi, which is why nm-online has taken a long time to allow startup to proceed.

network-wait-online is a "big hammer" and is not very nuanced.  Usually services that need connectivity should only rely on the connectivity they need, instead of some generic notion of "hey I'm connected".  In systems with multiple interfaces and network configurations, some people want *everything* connected and some people want *one* thing connected, and the best thing to do is just make the service that actually cares, care.

Comment 21 Dan Williams 2015-01-29 20:12:58 UTC
I don't really think this is an NM problem, the services are all working as designed.  If the WiFi isn't actually required at startup, then maybe it could be marked !autoconnect so that it doesn't get considered for network-wait-online.

Comment 22 Thomas Haller 2015-01-29 20:17:42 UTC
networkd's wait-online supports (multiple) --interface options to specify which interfaces to wait for [1]. That might be a useful and nice feature...

OTOH, waiting for NM-wait-online is not encouraged, so it might not be worth investing in such a feature.


[1] http://www.freedesktop.org/software/systemd/man/systemd-networkd-wait-online.service.html

Comment 23 lionghostshop 2015-01-30 02:29:36 UTC
Any way to make my system back to old fast boot?

Comment 24 Ilja Sekler 2015-02-22 19:08:59 UTC
(In reply to lionghostshop from comment #23)
> Any way to make my system back to old fast boot?

If you can do without nfs-utils like me, uninstalling the package will remove rpc-statd-notify.service. In case it was the only one that pulled in the network-online.target and NetworkManager-wait-online.service, this will bring lightning-fast boot times back in an orderly way for now.

Comment 25 lionghostshop 2015-02-23 01:30:17 UTC
It works. Now, it takes 7 seconds to boot. Thanks.

Comment 26 Pavel Šimerda (pavlix) 2015-02-23 07:50:21 UTC
(In reply to Michal Sekletar from comment #18)
> In this case it doesn't look like that some initscript (or other service for
> that matter) is pulling it in.

Does it mean my analysis in comment #15 was wrong?

Comment 27 lionghostshop 2015-02-23 07:54:39 UTC
rpc-statd-notify.service was running. it was pulled by  nfs-utils, I think

Comment 28 Michael J Gruber 2015-02-26 10:02:21 UTC
I use autofs with nfs and made the same observation about boot times.

Now, the question is: systemd's big selling point is delayed service activation. Why does the boot have to wait for autofs/nfs.service start completion if no autofs mount is used?

So, while it is clear that autofs/nfs need network-online it is not clear at all why the boot should be delayed - those services should be started on demand, shouldn't they?

(I disabled autofs/nfs now since I use them rarely, but starting them manually when I need them is a poor workaround.)

Comment 29 Fedora Admin XMLRPC Client 2015-08-18 14:58:30 UTC
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Comment 30 Fedora End Of Life 2015-11-04 10:47:32 UTC
This message is a reminder that Fedora 21 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 21. 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 '21'.

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 21 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 31 Fedora End Of Life 2015-12-02 07:35:46 UTC
Fedora 21 changed to end-of-life (EOL) status on 2015-12-01. Fedora 21 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.