Bug 1270025 - Connecting to wireless network is too slow.
Connecting to wireless network is too slow.
Status: CLOSED EOL
Product: Fedora
Classification: Fedora
Component: NetworkManager (Show other bugs)
22
x86_64 Linux
unspecified Severity unspecified
: ---
: ---
Assigned To: Lubomir Rintel
Fedora Extras Quality Assurance
:
: 1270179 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-10-08 16:23 EDT by Peter Hostačný
Modified: 2016-07-31 21:06 EDT (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-07-19 14:09:38 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
/var/log/messages (8.98 KB, text/plain)
2015-10-08 16:23 EDT, Peter Hostačný
no flags Details
/var/log/messages with NetworkManager set to debug log level (84.04 KB, text/plain)
2015-10-09 12:11 EDT, Kieran Clancy
no flags Details
/var/log/messages (debug log level) (29.11 KB, text/plain)
2015-10-12 15:58 EDT, Peter Hostačný
no flags Details

  None (edit)
Description Peter Hostačný 2015-10-08 16:23:37 EDT
Created attachment 1081096 [details]
/var/log/messages

Description of problem:
I have a problem with NetworkManager. Connecting to wireless network takes very long time. I am sure that it is not problem with network. I found the delay is between these two lines (complete log message from NetworkManager is in atachment):
Oct  8 21:33:26 scr4bble NetworkManager[1010]: <info>  (wlp3s0): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
Oct  8 21:34:46 scr4bble NetworkManager[1010]: <info>  (wlp3s0): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
Do you know, where is the problem ? I have updated my fedora from F19 to F22 through fedup (I think it occured after this update, but I am not sure).

Output from dmesg contains:
[Oct  8 21:33:27 2015] IPv6: wlp3s0: IPv6 duplicate address fe80::8256:f2ff:fe70:9085 detected!

Version-Release number of selected component (if applicable):
NetworkManager-1.0.6-6.fc22.x86_64
wpa_supplicant-2.4-4.fc22.x86_64

How reproducible:


Steps to Reproduce:
1. Connect to wireless network - using GUI.
2.
3.

Actual results:
Connecting to network takes more than 1 minute.

Expected results:
Connect to network in few seconds.

Additional info:
Attachment created by "sudo cat /var/log/messages | grep Network | tail -n 100"
Comment 1 Dan Williams 2015-10-09 10:01:37 EDT
Could you run "sudo nmcli g log level debug" and then reproduce the problem, and attach the output again?  Thanks!

"sudo nmcli g log level info" will get logging back to normal.
Comment 2 Dan Williams 2015-10-09 10:06:25 EDT
*** Bug 1270179 has been marked as a duplicate of this bug. ***
Comment 3 Kieran Clancy 2015-10-09 12:11 EDT
Created attachment 1081386 [details]
/var/log/messages with NetworkManager set to debug log level

egrep -v '(gnome-session|gdm|dleyna|audit-|geoclue|dbus|luetooth|bluez)' /var/log/messages

system starts resume at 02:27:52
interace p3p1 comes up at 02:27:54
DHCPACK received at 02:27:55
resolv.conf updated at 02:28:50 (nearly 1 minute later)

As an aside, I notice that NM is requesting http://fedoraproject.org/static/hotspot.txt not once but four times. (A packet log confirms this.) Is this normal?
Comment 4 Peter Hostačný 2015-10-12 15:58 EDT
Created attachment 1082103 [details]
/var/log/messages (debug log level)

Here is the output.
Attachment created by "sudo cat /var/log/messages | grep Network" with debug log level.
Comment 5 Dimitris 2015-10-16 15:27:19 EDT
I think I have the same problem here, on F22.  This started happening recently, as in about a month ago.

My steps to reproduce and a pointer to (a possible path to) the root cause:

- Boot machine.  By the time I log in to GNOME the network has already connected.  I *think* there is no delay here but due to the time it takes to get into the session, it could be that the delay is just masked.

- Disconnect from Wifi.  Either by turning Wifi off then on, or by using the "disconnect wifi" extension:
  https://extensions.gnome.org/extension/904/disconnect-wifi/
  or by turning Wifi off.

- systemctl status nm-dispatcher shows it "Dispatching action 'up'"

- Reconnect, either by the "reconnect to <network name> option offered by the extension or by turning wifi back on and re-selecting the network.

- Underlying connection comes up pretty quickly, verified by pinging a machine on the internet - but only if it resolves through /etc/hosts.  The local dnsmasq is not resolving queries yet.  Route is set up properly too.

- In the journal I see nm-dispatcher doing this several times, in 1-minute intervals:

Oct 16 12:11:11 gaspode nm-dispatcher[8375]: Dispatching action 'down' for wls1
Oct 16 12:12:11 gaspode nm-dispatcher[8375]: Dispatching action 'pre-up' for wls1

- Eventually, it manages to dispatch "up" and I have full connectivity (DNS working, icon shows connected, dbus presumably tells applications that we're connected).

I can work around the delay by:

sudo systemctl restart NetworkManager-dispatcher.service

but that's hardly elegant.
Comment 6 Kieran Clancy 2015-10-21 09:20:19 EDT
I may have made some progress with this issue. I noticed that after resuming, this process was running:
root     25848 25826  0 23:42 ?        00:00:00 /bin/sh /etc/NetworkManager/dispatcher.d/10-sendmail p3p1 down

My understanding is that this would have been started before suspending, but it continues to run once the computer resumes.

Anyway, editing /etc/NetworkManager/dispatcher.d/10-sendmail and commenting it out removes the delay on bringing the interface back up, at least for me.

I don't use this machine to send local mail, so I'm not too worried about the side-effects of this, but it would still be good to have a proper solution.
Comment 7 Dimitris 2015-10-23 01:14:49 EDT
the /etc/NetworkManager/dispatcher.d/10-sendmail file is provided by the sendmail package.  I disabled the sendmail service (sudo systemctl disable sendmail.service) and stopped it (sudo systemctl stop sendmail.service) and this seems to have fixed this issue.

I don't know whether the underlying bug (connection taking too long to indicate it's up) is still a NetworkManager or sendmail problem.  It does seem to be a egression however, as I don't remember seeing this till relatively recently - some time after I had upgraded to F22.
Comment 8 Jacobo Aragunde 2015-11-13 03:45:14 EST
Same problem here, network had been working properly until some weeks ago. FWIW, happens both with wired and wireless networks.

Disabling the sendmail service works around the issue for me too.
Comment 9 Dan Williams 2015-11-13 13:09:52 EST
(In reply to Kieran Clancy from comment #3)
> Created attachment 1081386 [details]
> /var/log/messages with NetworkManager set to debug log level
> 
> egrep -v '(gnome-session|gdm|dleyna|audit-|geoclue|dbus|luetooth|bluez)'
> /var/log/messages
> 
> system starts resume at 02:27:52
> interace p3p1 comes up at 02:27:54
> DHCPACK received at 02:27:55
> resolv.conf updated at 02:28:50 (nearly 1 minute later)

The dispatcher must serialize the actions for a particular connection to ensure that scripts don't trip over each other.  And it appears that there are still actions pending from the suspend action that didn't get completed before suspend, that are blocking the resume "pre-up" script.  Which is the cause of the large delay...

The solution probably lies both with long-running dispatcher scripts (which they shouldn't do) and probably blocking suspend until the scripts are done (which ensures that you know what's actually causing the wait).
Comment 10 Fedora End Of Life 2016-07-19 14:09:38 EDT
Fedora 22 changed to end-of-life (EOL) status on 2016-07-19. Fedora 22 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.