Bug 987128
| Summary: | After suspend to RAM, systemd-sleep System resumed is followed by systemd Started Suspend, causing delay in NetworkManager operation | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Jan Pazdziora <jpazdziora> | ||||||
| Component: | NetworkManager | Assignee: | Dan Williams <dcbw> | ||||||
| Status: | CLOSED EOL | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||||
| Severity: | unspecified | Docs Contact: | |||||||
| Priority: | unspecified | ||||||||
| Version: | 20 | CC: | admiller, christoph.wickert, dcbw, janna.martl109, johannbg, jpazdziora, kevin, lnykryn, mschmidt, msekleta, openfred65, plautrba, rvokal, stakka, systemd-maint, vpavlin, zbyszek | ||||||
| Target Milestone: | --- | ||||||||
| Target Release: | --- | ||||||||
| Hardware: | Unspecified | ||||||||
| OS: | Unspecified | ||||||||
| Whiteboard: | |||||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||||
| Doc Text: | Story Points: | --- | |||||||
| Clone Of: | Environment: | ||||||||
| Last Closed: | 2015-06-29 12:07:07 UTC | Type: | Bug | ||||||
| Regression: | --- | Mount Type: | --- | ||||||
| Documentation: | --- | CRM: | |||||||
| Verified Versions: | Category: | --- | |||||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||
| Embargoed: | |||||||||
| Attachments: |
|
||||||||
|
Description
Jan Pazdziora
2013-07-22 18:33:57 UTC
I am not sure how NetworkManager expects to handle suspend/resume. I guess it uses a systemd sleep inhibitor. Let's reassign to NetworkManager to get any ideas. If it can be shown that systemd-logind is not sending NM the right signals, reassign back. Jan, please paste the output of "systemd-inhibit" before suspending. $ systemd-inhibit
Who: xfce4-power-manager (UID 501/adelton, PID 978/xfce4-power-man)
What: handle-power-key:handle-suspend-key:handle-hibernate-key:handle-lid-switch
Why: xfce4-power-manager handles these events
Mode: block
Who: xfce4-power-manager (UID 501/adelton, PID 1012/xfce4-power-man)
What: handle-power-key:handle-suspend-key:handle-hibernate-key:handle-lid-switch
Why: xfce4-power-manager handles these events
Mode: block
Who: root (UID 0/root, PID 549/NetworkManager)
What: sleep
Why: inhibited
Mode: delay
3 inhibitors listed.
The two power managers in that output got me suspicious so I went to Settings > Session and Startup > Session, selected (the only one) Power Manager and hit Quit Program and Save Session. After logout and even after reboot, one Power Manager (xfce4-power-manager) is started now and the resume behaves the way it did in Fedora 18. Michal, thank you for the hint that helped to resolve the issues for me. Now the question is -- which component do I put the bugzilla "after fedup from Fedora 18 to 19, two xfce4-power-manager's run"? Let's move it under xfce4-power-manager and work from there. This has nothing to do with the upgrade but with the session handling of xfce4-session. You should only use one mechanism, either autostart or session saving. I am sure this is a known problem and Kevin filed an upstream bug about it. He probably knows more. Possibly https://bugzilla.xfce.org/show_bug.cgi?id=5123 ? But I have seen no reports of it with 4.10 and thought it was fixed. ;( I spoke too fast. Having one or two Power Managers does not seem to determine the situation. Even if the systemd-inhibit lists just one xfce4-power-manager, sometimes the output in /var/log/messages is Jul 23 07:26:39 corona kernel: [ 7694.712746] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1 Jul 23 07:26:39 corona kernel: [ 7694.948491] PM: resume of devices complete after 2304.742 msecs Jul 23 07:26:39 corona kernel: [ 7695.170523] Restarting tasks ... done. Jul 23 07:26:39 corona systemd[1]: Time has been changed Jul 23 07:26:39 corona systemd-logind[551]: Lid opened. Jul 23 07:26:39 corona NetworkManager[546]: <info> (wlan1): supplicant interface state: disconnected -> inactive Jul 23 07:26:39 corona NetworkManager[546]: <info> Auto-activating connection 'my-network'. and the network is connected instantly, and sometimes the output is Jul 24 07:08:38 corona kernel: [27599.845620] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1 Jul 24 07:08:38 corona kernel: [27600.083156] PM: resume of devices complete after 2663.111 msecs Jul 24 07:08:38 corona systemd[1]: Time has been changed Jul 24 07:08:38 corona systemd-logind[551]: Lid opened. Jul 24 07:08:38 corona kernel: [27600.315382] Restarting tasks ... done. Jul 24 07:08:38 corona kernel: [27600.327839] video LNXVIDEO:00: Restoring backlight state Jul 24 07:08:38 corona systemd-sleep[12557]: System resumed. Jul 24 07:08:38 corona systemd[1]: Started Suspend. Jul 24 07:08:38 corona systemd[1]: Requested transaction contradicts existing jobs: File exists Jul 24 07:08:38 corona systemd[1]: Service sleep.target is not needed anymore. Stopping. Jul 24 07:08:38 corona systemd[1]: Stopping Sleep. Jul 24 07:08:38 corona systemd[1]: Stopped target Sleep. Jul 24 07:08:38 corona systemd[1]: Reached target Suspend. Jul 24 07:08:38 corona systemd-logind[551]: Operation finished. Jul 24 07:08:38 corona NetworkManager[546]: <info> (wlan1): supplicant interface state: disconnected -> inactive Jul 24 07:08:38 corona upowerd[750]: (upowerd:750): UPower-Linux-WARNING **: energy 70.429500 bigger than full 70.429500 Jul 24 07:08:58 corona NetworkManager[546]: <info> Auto-activating connection 'my-network'. Notice the new "Started Suspend" sequence in the second output. In this situation, the "Auto-activating connection" is always 20 seconds delayed. Moving back to systemd. I think this is misleading. "Started Suspend" is just printed after the actual systemd-sleep binary ran and finished, i.e. it will always e printed after the resume came back. NetworkManager doesn't see this messgae every (unless it scrapes the logs...). It gets a dbus signal, and should use a delay inhibitor to make this race-free. (In reply to Lennart Poettering from comment #7) > I think this is misleading. "Started Suspend" is just printed after the > actual systemd-sleep binary ran and finished, i.e. it will always e printed > after the resume came back. > > NetworkManager doesn't see this messgae every (unless it scrapes the > logs...). It gets a dbus signal, and should use a delay inhibitor to make > this race-free. NM does use a systemd inhibitor: http://cgit.freedesktop.org/NetworkManager/NetworkManager/tree/src/nm-sleep-monitor-systemd.c is that code somehow wrong? If we don't see: Jun 24 07:36:51 corona NetworkManager[624]: <info> waking up and re-enabling... in the logs, then NM isn't correctly being told to wake up. Reporter, could you run this command: sudo dbus-send --system --print-reply --dest=org.freedesktop.NetworkManager /org/freedesktop/NetworkManager org.freedesktop.NetworkManager.SetLogging string:"debug" string:"core,suspend" and then attempt to reproduce the problem, and then paste the relevant system logs in here like you did above? Thanks! Jul 26 19:17:07 corona kernel: [52745.316716] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1 Jul 26 19:17:07 corona kernel: [52745.553956] PM: resume of devices complete after 2555.435 msecs Jul 26 19:17:07 corona kernel: [52745.775272] Restarting tasks ... done. Jul 26 19:17:07 corona systemd[1]: Time has been changed Jul 26 19:17:07 corona systemd-logind[551]: Lid opened. Jul 26 19:17:07 corona kernel: [52745.791486] video LNXVIDEO:00: Restoring backlight state Jul 26 19:17:07 corona systemd-sleep[21259]: System resumed. Jul 26 19:17:07 corona systemd[1]: Started Suspend. Jul 26 19:17:07 corona systemd[1]: Requested transaction contradicts existing jobs: File exists Jul 26 19:17:07 corona systemd[1]: Service sleep.target is not needed anymore. Stopping. Jul 26 19:17:07 corona systemd[1]: Stopping Sleep. Jul 26 19:17:07 corona systemd[1]: Stopped target Sleep. Jul 26 19:17:07 corona systemd[1]: Reached target Suspend. Jul 26 19:17:07 corona systemd-logind[551]: Operation finished. Jul 26 19:17:07 corona NetworkManager[546]: <debug> [1374859027.33560] [nm-sleep-monitor-systemd.c:150] signal_cb(): Received PrepareForSleep signal: 0 Jul 26 19:17:07 corona NetworkManager[546]: <debug> [1374859027.33590] [nm-sleep-monitor-systemd.c:120] take_inhibitor(): Taking systemd sleep inhibitor Jul 26 19:17:07 corona NetworkManager[546]: <debug> [1374859027.33771] [nm-manager.c:3483] resuming_cb(): Received resuming signal Jul 26 19:17:07 corona NetworkManager[546]: <debug> [1374859027.36035] [nm-sleep-monitor-systemd.c:109] inhibit_done(): Inhibitor fd is 18 Jul 26 19:17:07 corona upowerd[750]: (upowerd:750): UPower-Linux-WARNING **: energy 70.429500 bigger than full 70.429500 Jul 26 19:17:28 corona NetworkManager[546]: <debug> [1374859048.395284] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:17:28 corona NetworkManager[546]: <debug> [1374859048.409662] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:17:28 corona NetworkManager[546]: <debug> [1374859048.410985] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:17:28 corona NetworkManager[546]: <debug> [1374859048.419115] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:17:28 corona NetworkManager[546]: <debug> [1374859048.419566] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:17:30 corona kernel: [52769.726437] wlan1: authenticate with 10:bf:48:c6:de:28 Jul 26 19:17:30 corona kernel: [52769.730878] wlan1: send auth to 10:bf:48:c6:de:28 (try 1/3) Jul 26 19:17:30 corona kernel: [52769.734805] wlan1: authenticated Jul 26 19:17:30 corona kernel: [52769.735643] wlan1: associate with 10:bf:48:c6:de:28 (try 1/3) Jul 26 19:17:30 corona kernel: [52769.744096] wlan1: RX AssocResp from 10:bf:48:c6:de:28 (capab=0x411 status=0 aid=8) Jul 26 19:17:31 corona kernel: [52769.762758] wlan1: associated Jul 26 19:17:31 corona kernel: [52769.762821] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready Jul 26 19:17:31 corona NetworkManager[546]: <debug> [1374859051.25244] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:17:31 corona NetworkManager[546]: <debug> [1374859051.29937] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan1/accept_ra' to '1' Jul 26 19:17:31 corona NetworkManager[546]: <debug> [1374859051.30202] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan1/use_tempaddr' to '0' Hmm, could you try again and also include the log messages from before the suspend attempt? It could be a problem with NM getting the PrepareForSleep(1) message that signals suspend. This is what lead to comment 9: Jul 26 19:16:14 corona systemd-logind[551]: Lid closed. Jul 26 19:16:14 corona NetworkManager[546]: <info> sleep requested (sleeping: no enabled: yes) Jul 26 19:16:14 corona kernel: [52738.702417] wlan1: deauthenticating from 10:bf:48:c6:de:28 by local choice (reason=3) Jul 26 19:16:14 corona NetworkManager[546]: <info> sleeping or disabling... Jul 26 19:16:14 corona NetworkManager[546]: <debug> [1374858974.447040] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:16:14 corona NetworkManager[546]: <debug> [1374858974.649355] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan1/accept_ra' to '0' Jul 26 19:16:14 corona NetworkManager[546]: <debug> [1374858974.649477] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan1/use_tempaddr' to '0' Jul 26 19:16:14 corona kernel: [52738.788664] cfg80211: Calling CRDA to update world regulatory domain Jul 26 19:16:14 corona avahi-daemon[552]: Withdrawing address record for 192.168.42.11 on wlan1. Jul 26 19:16:14 corona avahi-daemon[552]: Leaving mDNS multicast group on interface wlan1.IPv4 with address 192.168.42.11. Jul 26 19:16:14 corona kernel: [52738.794192] cfg80211: World regulatory domain updated: Jul 26 19:16:14 corona kernel: [52738.794197] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Jul 26 19:16:14 corona kernel: [52738.794200] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Jul 26 19:16:14 corona kernel: [52738.794203] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Jul 26 19:16:14 corona kernel: [52738.794205] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) Jul 26 19:16:14 corona kernel: [52738.794207] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Jul 26 19:16:14 corona kernel: [52738.794210] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Jul 26 19:16:14 corona kernel: [52738.794226] cfg80211: Calling CRDA for country: CZ Jul 26 19:16:14 corona avahi-daemon[552]: Interface wlan1.IPv4 no longer relevant for mDNS. Jul 26 19:16:14 corona avahi-daemon[552]: Withdrawing address record for fe80::224:d7ff:fe83:3ed0 on wlan1. Jul 26 19:16:14 corona kernel: [52738.821700] cfg80211: Regulatory domain changed to country: CZ Jul 26 19:16:14 corona kernel: [52738.821707] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Jul 26 19:16:14 corona kernel: [52738.821711] cfg80211: (2400000 KHz - 2483500 KHz @ 40000 KHz), (N/A, 2000 mBm) Jul 26 19:16:14 corona kernel: [52738.821714] cfg80211: (5150000 KHz - 5250000 KHz @ 40000 KHz), (N/A, 2301 mBm) Jul 26 19:16:14 corona kernel: [52738.821717] cfg80211: (5250000 KHz - 5350000 KHz @ 40000 KHz), (N/A, 2000 mBm) Jul 26 19:16:14 corona kernel: [52738.821719] cfg80211: (5470000 KHz - 5725000 KHz @ 40000 KHz), (N/A, 2698 mBm) Jul 26 19:16:14 corona kernel: [52738.821722] cfg80211: (57240000 KHz - 65880000 KHz @ 2160000 KHz), (N/A, 4000 mBm) Jul 26 19:16:14 corona NetworkManager[546]: <debug> [1374858974.808590] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:16:14 corona dbus-daemon[557]: dbus[557]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Jul 26 19:16:14 corona dbus-daemon[557]: dbus[557]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.nm-dispatcher.service': Unit dbus-org.freedesktop.nm-dispatcher.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.freedesktop.nm-dispatcher.service' for details. Jul 26 19:16:14 corona dbus[557]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Jul 26 19:16:14 corona dbus[557]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.nm-dispatcher.service': Unit dbus-org.freedesktop.nm-dispatcher.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.freedesktop.nm-dispatcher.service' for details. Jul 26 19:16:14 corona NetworkManager[546]: <warn> Dispatcher failed: (32) Unit dbus-org.freedesktop.nm-dispatcher.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.freedesktop.nm-dispatcher.service' for details. Jul 26 19:16:16 corona ntpd[608]: Deleting interface #36 wlan1, fe80::224:d7ff:fe83:3ed0#123, interface stats: received=0, sent=0, dropped=0, active_time=979 secs Jul 26 19:16:16 corona ntpd[608]: Deleting interface #35 wlan1, 192.168.42.11#123, interface stats: received=51, sent=61, dropped=0, active_time=979 secs Jul 26 19:16:16 corona ntpd[608]: 195.113.159.1 interface 192.168.42.11 -> (none) Jul 26 19:16:16 corona ntpd[608]: 93.185.101.74 interface 192.168.42.11 -> (none) Jul 26 19:16:16 corona ntpd[608]: 213.151.89.43 interface 192.168.42.11 -> (none) Jul 26 19:16:16 corona ntpd[608]: 81.2.233.15 interface 192.168.42.11 -> (none) Jul 26 19:16:16 corona ntpd[608]: peers refreshed Jul 26 19:16:16 corona NetworkManager[546]: <debug> [1374858976.858842] [nm-sleep-monitor-systemd.c:150] signal_cb(): Received PrepareForSleep signal: 1 Jul 26 19:16:16 corona NetworkManager[546]: <debug> [1374858976.858923] [nm-manager.c:3476] sleeping_cb(): Received sleeping signal Jul 26 19:16:16 corona NetworkManager[546]: <debug> [1374858976.858952] [nm-sleep-monitor-systemd.c:78] drop_inhibitor(): Dropping systemd sleep inhibitor Jul 26 19:16:16 corona NetworkManager[546]: <info> wake requested (sleeping: yes enabled: yes) Jul 26 19:16:16 corona NetworkManager[546]: <info> waking up and re-enabling... Jul 26 19:16:16 corona systemd[1]: Starting Sleep. Jul 26 19:16:16 corona systemd[1]: Reached target Sleep. Jul 26 19:16:16 corona systemd[1]: Starting Suspend... Jul 26 19:16:16 corona systemd-sleep[21259]: Suspending system... Jul 26 19:16:17 corona kernel: [52741.124641] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready Jul 26 19:16:17 corona kernel: [52741.127226] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S Jul 26 19:16:17 corona kernel: [52741.127448] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1 Jul 26 19:16:17 corona NetworkManager[546]: <debug> [1374858977.75059] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/eth1/accept_ra' to '0' Jul 26 19:16:17 corona NetworkManager[546]: <debug> [1374858977.75122] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/eth1/use_tempaddr' to '0' Jul 26 19:16:17 corona NetworkManager[546]: <debug> [1374858977.75831] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:16:17 corona NetworkManager[546]: <debug> [1374858977.298006] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan1/accept_ra' to '0' Jul 26 19:16:17 corona kernel: [52741.348433] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready Jul 26 19:16:17 corona NetworkManager[546]: <debug> [1374858977.298087] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan1/use_tempaddr' to '0' Jul 26 19:16:17 corona NetworkManager[546]: <debug> [1374858977.298990] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:16:17 corona NetworkManager[546]: <debug> [1374858977.320512] [nm-manager.c:596] manager_device_state_changed(): stopping connectivity checks Jul 26 19:16:17 corona NetworkManager[546]: <warn> Trying to remove a non-existant call id. Jul 26 19:16:17 corona kernel: [52740.931949] PM: Syncing filesystems ... done. Jul 26 19:17:07 corona kernel: [52742.040835] Freezing user space processes ... (elapsed 0.01 seconds) done. [ ... more kernel messages ... ] Jul 26 19:17:07 corona kernel: [52745.316716] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1 Jul 26 19:17:07 corona kernel: [52745.553956] PM: resume of devices complete after 2555.435 msecs Jul 26 19:17:07 corona kernel: [52745.775272] Restarting tasks ... done. Jul 26 19:17:07 corona systemd[1]: Time has been changed Jul 26 19:17:07 corona systemd-logind[551]: Lid opened. Do you by chance have: /usr/lib64/pm-utils/sleep.d/55NetworkManager installed and if you move that out of the way, do things start working again? (In reply to Jan Pazdziora from comment #11) > Jul 26 19:16:14 corona systemd-logind[551]: Lid closed. > Jul 26 19:16:14 corona NetworkManager[546]: <info> sleep requested > (sleeping: no enabled: yes) > Jul 26 19:16:14 corona kernel: [52738.702417] wlan1: deauthenticating from > 10:bf:48:c6:de:28 by local choice (reason=3) > Jul 26 19:16:14 corona NetworkManager[546]: <info> sleeping or disabling... Something has told NM to go to sleep; this thing is *not* systemd, it's likely pm-utils. But that's fine, however NM gets told to sleep works. > Jul 26 19:16:16 corona NetworkManager[546]: <debug> [1374858976.858842] > [nm-sleep-monitor-systemd.c:150] signal_cb(): Received PrepareForSleep > signal: 1 systemd has signalled that it's about to go to sleep. This is fine. > Jul 26 19:16:16 corona NetworkManager[546]: <debug> [1374858976.858923] > [nm-manager.c:3476] sleeping_cb(): Received sleeping signal Since we're already sleeping (see above at 19:16:14) this is a no-op and nothing else needs to happen. > Jul 26 19:16:16 corona NetworkManager[546]: <debug> [1374858976.858952] > [nm-sleep-monitor-systemd.c:78] drop_inhibitor(): Dropping systemd sleep > inhibitor This is the end of the systemd sleep request. > Jul 26 19:16:16 corona NetworkManager[546]: <info> wake requested (sleeping: > yes enabled: yes) > Jul 26 19:16:16 corona NetworkManager[546]: <info> waking up and > re-enabling... And here's the actual problem. Something *else* on the system is telling NM to wake up. That could be the pm-utils script, if pm-utils is not being run correctly... Unfortunately we can't tell what script that is, because it could be anything that requests NM to sleep/wake via D-Bus. But try moving the pm-utils script out of the way, and if that fixes things, then we'll need to figure out why pm-utils scripts are telling things to wake up when they're supposed to be telling them to suspend. (In reply to Dan Williams from comment #12) > Do you by chance have: > > /usr/lib64/pm-utils/sleep.d/55NetworkManager > > installed and if you move that out of the way, do things start working > again? Yes, I do have /usr/lib/pm-utils/sleep.d/55NetworkManager from pm-utils-1.4.1-24.fc19.i686. Moving it away did not help. Should I try to uninstall the whole pm-utils? No, just the 55NetworkManager should have been enough to test. I'll have to build you a special NetworkManager with some additional checking to see what process is actually telling NM to resume right before suspend. I'm using arch, not fedora, but I'm having this exact problem. I can reproduce it without suspending: # systemctl stop NetworkManager.service # systemctl stop wpa_supplicant.service (wait a few seconds) # systemctl start NetworkManager.service (I also stop wpa_supplicant because that seems to decrease the chance that NM automatically restarts itself immediately; this still happens sometimes though which is kind of weird.) Here is the log in a case when the delay happens: Aug 28 00:43:03 hostname NetworkManager[6556]: <info> caught signal 15, shutting down normally. Aug 28 00:43:03 hostname NetworkManager[6556]: <info> (wlan0): device state change: activated -> unmanaged (reason 'removed') [100 10 36] Aug 28 00:43:03 hostname NetworkManager[6556]: <info> (wlan0): deactivating device (reason 'removed') [36] Aug 28 00:43:03 hostname systemd[1]: Stopping Network Manager... Aug 28 00:43:03 hostname NetworkManager[6556]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 6564 Aug 28 00:43:03 hostname kernel: wlan0: deauthenticating from <...> by local choice (reason=3) Aug 28 00:43:03 hostname kernel: cfg80211: Calling CRDA to update world regulatory domain Aug 28 00:43:03 hostname NetworkManager[6556]: <info> (wlan0): cleaning up... Aug 28 00:43:03 hostname kernel: cfg80211: World regulatory domain updated: Aug 28 00:43:03 hostname kernel: cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Aug 28 00:43:03 hostname kernel: cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: Calling CRDA for country: US Aug 28 00:43:03 hostname kernel: cfg80211: Regulatory domain changed to country: US Aug 28 00:43:03 hostname kernel: cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Aug 28 00:43:03 hostname kernel: cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm) Aug 28 00:43:03 hostname kernel: cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 4000 mBm) Aug 28 00:43:03 hostname NetworkManager[6556]: <info> (wlan0): taking down device. Aug 28 00:43:03 hostname NetworkManager[6556]: <info> (eth0): device state change: unavailable -> unmanaged (reason 'removed') [20 10 36] Aug 28 00:43:03 hostname NetworkManager[6556]: <info> (eth0): cleaning up... Aug 28 00:43:03 hostname dbus[234]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Aug 28 00:43:03 hostname dbus-daemon[234]: dbus[234]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Aug 28 00:43:03 hostname systemd[1]: Starting Network Manager Script Dispatcher Service... Aug 28 00:43:03 hostname NetworkManager[6556]: <info> (eth0): taking down device. Aug 28 00:43:03 hostname dbus-daemon[234]: dbus[234]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Aug 28 00:43:03 hostname dbus[234]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Aug 28 00:43:03 hostname systemd[1]: Started Network Manager Script Dispatcher Service. Aug 28 00:43:05 hostname NetworkManager[6556]: <info> exiting (success) Aug 28 00:43:05 hostname systemd[1]: Stopped Network Manager. Aug 28 00:43:06 hostname systemd[1]: Stopping WPA supplicant... Aug 28 00:43:06 hostname wpa_supplicant[6550]: Successfully initialized wpa_supplicant Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: SME: Trying to authenticate with <...> (SSID='ESSID' freq=2437 MHz) Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: Trying to associate with <...> (SSID='ESSID' freq=2437 MHz) Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: Associated with <...> Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25 -> NAK Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=21 Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=2 subject='/C=US/O=GeoTrust Inc./CN=GeoTrust Global CA' Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=US/O=GeoTrust, Inc./CN=GeoTrust SSL CA' Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/serialNumber=... Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: WPA: Key negotiation completed with <...> [PTK=CCMP GTK=CCMP] Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-CONNECTED - Connection to <...> completed [id=0 id_str=] Aug 28 00:43:06 hostname wpa_supplicant[6550]: wlan0: CTRL-EVENT-DISCONNECTED bssid=<...> reason=3 locally_generated=1 Aug 28 00:43:06 hostname systemd[1]: Stopped WPA supplicant. Aug 28 00:43:33 hostname sudo[6625]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 00:43:33 hostname systemd[1]: Starting Network Manager... Aug 28 00:43:33 hostname NetworkManager[6628]: <info> NetworkManager (version 0.9.8.2) is starting... Aug 28 00:43:33 hostname NetworkManager[6628]: <info> Read config file /etc/NetworkManager/NetworkManager.conf Aug 28 00:43:33 hostname NetworkManager[6628]: <info> WEXT support is enabled Aug 28 00:43:34 hostname NetworkManager[6628]: <info> Loaded plugin keyfile: (c) 2007 - 2010 Red Hat, Inc. To report bugs please use the NetworkManager mailing list. Aug 28 00:43:34 hostname NetworkManager[6628]: keyfile: parsing <long list... don't want to paste here but looks OK> Aug 28 00:43:34 hostname NetworkManager[6628]: <info> monitoring kernel firmware directory '/lib/firmware'. Aug 28 00:43:34 hostname NetworkManager[6628]: <info> rfkill3: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:15.0/0000:02:00.0/ssb0:0/ieee80211/phy1/rfkill3) (driver b43) Aug 28 00:43:34 hostname NetworkManager[6628]: <info> WiFi hardware radio set enabled Aug 28 00:43:34 hostname dbus[234]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' Aug 28 00:43:34 hostname dbus[234]: [system] Activation via systemd failed for unit 'dbus-org.bluez.service': Unit dbus-org.bluez.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.bluez.service' for details. Aug 28 00:43:34 hostname NetworkManager[6628]: <info> WiFi enabled by radio killswitch; enabled by state file Aug 28 00:43:34 hostname NetworkManager[6628]: <info> WWAN enabled by radio killswitch; enabled by state file Aug 28 00:43:34 hostname NetworkManager[6628]: <info> WiMAX enabled by radio killswitch; enabled by state file Aug 28 00:43:34 hostname NetworkManager[6628]: <info> Networking is enabled by state file Aug 28 00:43:34 hostname sudo[6625]: pam_unix(sudo:session): session closed for user root Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (wlan0): using nl80211 for WiFi device control Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (wlan0): driver supports Access Point (AP) mode Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (wlan0): new 802.11 WiFi device (driver: 'b43' ifindex: 4) Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/0 Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (wlan0): bringing up device. Aug 28 00:43:34 hostname dbus-daemon[234]: dbus[234]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' Aug 28 00:43:34 hostname dbus-daemon[234]: dbus[234]: [system] Activation via systemd failed for unit 'dbus-org.bluez.service': Unit dbus-org.bluez.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.bluez.service' for details. Aug 28 00:43:34 hostname systemd[1]: Started Network Manager. Aug 28 00:43:34 hostname kernel: b43-phy1: Loading firmware version 666.2 (2011-02-23 01:15:07) Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (wlan0): preparing device. Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (wlan0): deactivating device (reason 'managed') [2] Aug 28 00:43:34 hostname kernel: IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready Aug 28 00:43:34 hostname dbus-daemon[234]: dbus[234]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service' Aug 28 00:43:34 hostname dbus[234]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service' Aug 28 00:43:34 hostname NetworkManager[6628]: <warn> failed to allocate link cache: (-10) Operation not supported Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (eth0): carrier is OFF Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (eth0): new Ethernet device (driver: 'tg3' ifindex: 2) Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/1 Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (eth0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Aug 28 00:43:34 hostname NetworkManager[6628]: <info> (eth0): bringing up device. Aug 28 00:43:34 hostname systemd[1]: Starting WPA supplicant... Aug 28 00:43:34 hostname dbus-daemon[234]: dbus[234]: [system] Successfully activated service 'fi.w1.wpa_supplicant1' Aug 28 00:43:34 hostname dbus[234]: [system] Successfully activated service 'fi.w1.wpa_supplicant1' Aug 28 00:43:34 hostname systemd[1]: Started WPA supplicant. Aug 28 00:43:35 hostname kernel: tg3 0000:03:00.0: irq 44 for MSI/MSI-X Aug 28 00:43:35 hostname NetworkManager[6628]: <info> (eth0): preparing device. Aug 28 00:43:35 hostname NetworkManager[6628]: <info> (eth0): deactivating device (reason 'managed') [2] Aug 28 00:43:35 hostname kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready Aug 28 00:43:35 hostname NetworkManager[6628]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring... Aug 28 00:43:35 hostname NetworkManager[6628]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring... Aug 28 00:43:35 hostname NetworkManager[6628]: <info> wpa_supplicant started Aug 28 00:43:35 hostname NetworkManager[6628]: <info> (wlan0) supports 4 scan SSIDs Aug 28 00:43:35 hostname NetworkManager[6628]: <warn> Trying to remove a non-existant call id. Aug 28 00:43:35 hostname NetworkManager[6628]: <info> (wlan0): supplicant interface state: starting -> ready Aug 28 00:43:35 hostname NetworkManager[6628]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42] Aug 28 00:43:35 hostname NetworkManager[6628]: <info> (wlan0): supplicant interface state: ready -> disconnected Aug 28 00:43:35 hostname NetworkManager[6628]: <info> (wlan0) supports 4 scan SSIDs Aug 28 00:43:35 hostname NetworkManager[6628]: <info> ModemManager available in the bus Aug 28 00:43:36 hostname NetworkManager[6628]: <info> (wlan0): supplicant interface state: disconnected -> inactive Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Auto-activating connection 'ESSID'. Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) starting connection 'ESSID' Aug 28 00:43:59 hostname NetworkManager[6628]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0] Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Aug 28 00:43:59 hostname NetworkManager[6628]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0/wireless): access point 'ESSID' has security, but secrets are required. Aug 28 00:43:59 hostname NetworkManager[6628]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0] Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Aug 28 00:43:59 hostname NetworkManager[6628]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0] Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Aug 28 00:43:59 hostname NetworkManager[6628]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Aug 28 00:43:59 hostname NetworkManager[6628]: <info> Activation (wlan0/wireless): connection 'ESSID' has security, and secrets exist. No new secrets needed. after which point connecting to the network works normally without issues. As you can see, there was a 23 second delay before NM decided to auto-activate my connection. But sometimes I do the same things and there is no delay; here is the log from such a case: Aug 28 00:57:54 hostname NetworkManager[6628]: <info> caught signal 15, shutting down normally. Aug 28 00:57:54 hostname NetworkManager[6628]: <info> (wlan0): device state change: activated -> unmanaged (reason 'removed') [100 10 36] Aug 28 00:57:54 hostname NetworkManager[6628]: <info> (wlan0): deactivating device (reason 'removed') [36] Aug 28 00:57:55 hostname NetworkManager[6628]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 6637 Aug 28 00:57:55 hostname kernel: wlan0: deauthenticating from <...> by local choice (reason=3) Aug 28 00:57:55 hostname kernel: cfg80211: Calling CRDA to update world regulatory domain Aug 28 00:57:55 hostname NetworkManager[6628]: <info> (wlan0): cleaning up... Aug 28 00:57:55 hostname NetworkManager[6628]: <info> (wlan0): taking down device. Aug 28 00:57:55 hostname kernel: cfg80211: World regulatory domain updated: Aug 28 00:57:55 hostname kernel: cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Aug 28 00:57:55 hostname kernel: cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: Calling CRDA for country: US Aug 28 00:57:55 hostname kernel: cfg80211: Regulatory domain changed to country: US Aug 28 00:57:55 hostname kernel: cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Aug 28 00:57:55 hostname kernel: cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm) Aug 28 00:57:55 hostname kernel: cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 4000 mBm) Aug 28 00:57:55 hostname NetworkManager[6628]: <info> (eth0): device state change: unavailable -> unmanaged (reason 'removed') [20 10 36] Aug 28 00:57:55 hostname NetworkManager[6628]: <info> (eth0): cleaning up... Aug 28 00:57:55 hostname NetworkManager[6628]: <info> (eth0): taking down device. Aug 28 00:57:55 hostname dbus-daemon[234]: dbus[234]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Aug 28 00:57:55 hostname dbus[234]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Aug 28 00:57:55 hostname systemd[1]: Starting Network Manager Script Dispatcher Service... Aug 28 00:57:55 hostname dbus-daemon[234]: dbus[234]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Aug 28 00:57:55 hostname dbus[234]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Aug 28 00:57:55 hostname systemd[1]: Started Network Manager Script Dispatcher Service. Aug 28 00:57:56 hostname NetworkManager[6628]: <info> exiting (success) Aug 28 00:57:56 hostname systemd[1]: Stopped Network Manager. Aug 28 00:57:56 hostname systemd[1]: Stopping WPA supplicant... Aug 28 00:57:56 hostname systemd[1]: Stopped WPA supplicant. Aug 28 00:57:56 hostname wpa_supplicant[6633]: Successfully initialized wpa_supplicant Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: SME: Trying to authenticate with <...> (SSID='ESSID' freq=2412 MHz) Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: Trying to associate with <...> (SSID='ESSID' freq=2412 MHz) Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: Associated with <...> Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25 -> NAK Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=21 Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=2 subject='/C=US/O=GeoTrust Inc./CN=GeoTrust Global CA' Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=US/O=GeoTrust, Inc./CN=GeoTrust SSL CA' Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='<...> Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: WPA: Key negotiation completed with <...> [PTK=CCMP GTK=CCMP] Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-CONNECTED - Connection to <...> completed [id=0 id_str=] Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: SME: Trying to authenticate with <...> (SSID='ESSID' freq=2437 MHz) Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-DISCONNECTED bssid=<...> reason=1 locally_generated=1 Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: Trying to associate with <...> (SSID='ESSID' freq=2437 MHz) Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: Associated with <...> Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: WPA: Key negotiation completed with <...> [PTK=CCMP GTK=CCMP] Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-CONNECTED - Connection to <...> completed [id=0 id_str=] Aug 28 00:57:56 hostname wpa_supplicant[6633]: wlan0: CTRL-EVENT-DISCONNECTED bssid=<...> reason=3 locally_generated=1 Aug 28 00:58:14 hostname systemd[1]: Starting Network Manager... Aug 28 00:58:14 hostname NetworkManager[7618]: <info> NetworkManager (version 0.9.8.2) is starting... Aug 28 00:58:14 hostname NetworkManager[7618]: <info> Read config file /etc/NetworkManager/NetworkManager.conf Aug 28 00:58:14 hostname NetworkManager[7618]: <info> WEXT support is enabled Aug 28 00:58:14 hostname NetworkManager[7618]: <info> Loaded plugin keyfile: (c) 2007 - 2010 Red Hat, Inc. To report bugs please use the NetworkManager mailing list. Aug 28 00:58:14 hostname NetworkManager[7618]: keyfile: parsing <long list... don't want to paste here but looks OK> Aug 28 00:58:15 hostname NetworkManager[7618]: <info> monitoring kernel firmware directory '/lib/firmware'. Aug 28 00:58:15 hostname NetworkManager[7618]: <info> rfkill3: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:15.0/0000:02:00.0/ssb0:0/ieee80211/phy1/rfkill3) (driver b43) Aug 28 00:58:15 hostname NetworkManager[7618]: <info> WiFi hardware radio set enabled Aug 28 00:58:15 hostname dbus[234]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' Aug 28 00:58:15 hostname dbus[234]: [system] Activation via systemd failed for unit 'dbus-org.bluez.service': Unit dbus-org.bluez.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.bluez.service' for details. Aug 28 00:58:15 hostname NetworkManager[7618]: <info> WiFi enabled by radio killswitch; enabled by state file Aug 28 00:58:15 hostname NetworkManager[7618]: <info> WWAN enabled by radio killswitch; enabled by state file Aug 28 00:58:15 hostname NetworkManager[7618]: <info> WiMAX enabled by radio killswitch; enabled by state file Aug 28 00:58:15 hostname NetworkManager[7618]: <info> Networking is enabled by state file Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (wlan0): using nl80211 for WiFi device control Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (wlan0): driver supports Access Point (AP) mode Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (wlan0): new 802.11 WiFi device (driver: 'b43' ifindex: 4) Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/0 Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (wlan0): bringing up device. Aug 28 00:58:15 hostname dbus-daemon[234]: dbus[234]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' Aug 28 00:58:15 hostname dbus-daemon[234]: dbus[234]: [system] Activation via systemd failed for unit 'dbus-org.bluez.service': Unit dbus-org.bluez.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.bluez.service' for details. Aug 28 00:58:15 hostname systemd[1]: Started Network Manager. Aug 28 00:58:15 hostname kernel: b43-phy1: Loading firmware version 666.2 (2011-02-23 01:15:07) Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (wlan0): preparing device. Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (wlan0): deactivating device (reason 'managed') [2] Aug 28 00:58:15 hostname kernel: IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready Aug 28 00:58:15 hostname NetworkManager[7618]: <warn> failed to allocate link cache: (-10) Operation not supported Aug 28 00:58:15 hostname dbus[234]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service' Aug 28 00:58:15 hostname dbus-daemon[234]: dbus[234]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service' Aug 28 00:58:15 hostname systemd[1]: Starting WPA supplicant... Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (eth0): carrier is OFF Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (eth0): new Ethernet device (driver: 'tg3' ifindex: 2) Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/1 Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (eth0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Aug 28 00:58:15 hostname NetworkManager[7618]: <info> (eth0): bringing up device. Aug 28 00:58:15 hostname dbus-daemon[234]: dbus[234]: [system] Successfully activated service 'fi.w1.wpa_supplicant1' Aug 28 00:58:15 hostname dbus[234]: [system] Successfully activated service 'fi.w1.wpa_supplicant1' Aug 28 00:58:15 hostname systemd[1]: Started WPA supplicant. Aug 28 00:58:15 hostname kernel: tg3 0000:03:00.0: irq 44 for MSI/MSI-X Aug 28 00:58:16 hostname NetworkManager[7618]: <info> (eth0): preparing device. Aug 28 00:58:16 hostname NetworkManager[7618]: <info> (eth0): deactivating device (reason 'managed') [2] Aug 28 00:58:16 hostname NetworkManager[7618]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring... Aug 28 00:58:16 hostname NetworkManager[7618]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring... Aug 28 00:58:16 hostname NetworkManager[7618]: <info> wpa_supplicant started Aug 28 00:58:16 hostname kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready Aug 28 00:58:16 hostname NetworkManager[7618]: <info> (wlan0) supports 4 scan SSIDs Aug 28 00:58:16 hostname NetworkManager[7618]: <warn> Trying to remove a non-existant call id. Aug 28 00:58:16 hostname NetworkManager[7618]: <info> (wlan0): supplicant interface state: starting -> ready Aug 28 00:58:16 hostname NetworkManager[7618]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42] Aug 28 00:58:16 hostname NetworkManager[7618]: <info> (wlan0): supplicant interface state: ready -> disconnected Aug 28 00:58:16 hostname NetworkManager[7618]: <info> (wlan0) supports 4 scan SSIDs Aug 28 00:58:16 hostname NetworkManager[7618]: <info> ModemManager available in the bus Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Auto-activating connection 'ESSID'. Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) starting connection 'ESSID' Aug 28 00:58:17 hostname NetworkManager[7618]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0] Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Aug 28 00:58:17 hostname NetworkManager[7618]: <info> (wlan0): supplicant interface state: disconnected -> inactive Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Aug 28 00:58:17 hostname NetworkManager[7618]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0/wireless): access point 'ESSID' has security, but secrets are required. Aug 28 00:58:17 hostname NetworkManager[7618]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0] Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Aug 28 00:58:17 hostname NetworkManager[7618]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0] Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Aug 28 00:58:17 hostname NetworkManager[7618]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Aug 28 00:58:17 hostname NetworkManager[7618]: <info> Activation (wlan0/wireless): connection 'ESSID' has security, and secrets exist. No new secrets needed. at which point it connects normally. This is really unscientific but I'm going to guess that a longer wait between stopping and restarting NM corresponds to an increased chance that there will be a delay. Also, if I run # iwlist wlan0 scan while NM is sitting around during the ~20s delay then this triggers it to start "auto-activating" my connection as soon as the scan is done. So as a temporary workaround to the original suspend problem I've thrown a bunch of "iwlist wlan0 scan" commands into /etc/acpi/handler.sh so they get executed when I resume from suspend. Not a fix, though... Janna, if you could run this from a terminal: sudo dbus-send --system --print-reply --dest=org.freedesktop.NetworkManager /org/freedesktop/NetworkManager org.freedesktop.NetworkManager.SetLogging string:"debug" string:"wifi,wifi_scan,core,hw,device,suspend" and then suspend/resume and try to reproduce the problem, and include the syslog output? That will show us more information about when NM is requesting scans, and what the results of those are. To return to normal logging you can run: sudo dbus-send --system --print-reply --dest=org.freedesktop.NetworkManager /org/freedesktop/NetworkManager org.freedesktop.NetworkManager.SetLogging string:"info" string:"" Created attachment 791456 [details]
(some of the) output of journalctl _TRANSPORT=syslog
(ESSID's and BSSID's have been removed)
Notes about my setup: I've turned off systemd's suspend on lid close functionality because it duplicates acpid's (and I like /etc/acpi/handler.sh). In that script I have it do systemctl stop NetworkManager.service (and suspend!) when the lid is closed and systemctl start NetworkManager.service when the lid is opened. If I don't do those things, NM is much faster to resume but when I move to a different location, it spends a while trying to connect to the old AP instead of scanning for new ones. I suppose I should file a different bug report for that...
Created attachment 791460 [details]
journalctl output, take 2
Here's the output when I try to do suspend the systemd/logind way -- disable acpid, turn on lid event handling in logind.conf. Same problem.
(In reply to Janna Martl from comment #20) > Created attachment 791456 [details] > (some of the) output of journalctl _TRANSPORT=syslog > > (ESSID's and BSSID's have been removed) > > Notes about my setup: I've turned off systemd's suspend on lid close > functionality because it duplicates acpid's (and I like > /etc/acpi/handler.sh). In that script I have it do systemctl stop > NetworkManager.service (and suspend!) when the lid is closed and systemctl > start NetworkManager.service when the lid is opened. If I don't do those > things, NM is much faster to resume but when I move to a different location, > it spends a while trying to connect to the old AP instead of scanning for > new ones. I suppose I should file a different bug report for that... NM needs to be told that the system is sleeping so that it can do things like throw away the scan list and get a new one on resume. It sounds like that's not happening in your acpid scripts, so instead of stopping NM and restarting it, do something like: dbus_send --system --print-reply \ --dest=org.freedesktop.NetworkManager \ /org/freedesktop/NetworkManager \ org.freedesktop.NetworkManager.Sleep boolean:true and for resume: dbus_send --system --print-reply \ --dest=org.freedesktop.NetworkManager \ /org/freedesktop/NetworkManager \ org.freedesktop.NetworkManager.Sleep boolean:false NM has some integration for systemd to do this automatically, but like you said, you've disabled that. There's also integration for 'upower', but you're likely not running that either, so you'll need the above calls to accomplish correct suspend/resume. Thanks; that solves the problem of not refreshing the list of essid's. However, it does (intermittently) still cause the delay problem I was originally reporting, as does upower (via dbus-send --system --print-reply --dest="org.freedesktop.UPower" /org/freedesktop/UPower org.freedesktop.UPower.Suspend), and as does the "pure systemd" way I submitted logs for in comment #21 (in which I don't use /etc/acpi/handler.sh at all). Apologies if I'm complicating matters by introducing my own misconfiguration problems. At least in my case, I think the issue is that scans started a few seconds after resume fail for some reason (maybe hardware/firmware reasons). (I can observe this by turning off NM, doing suspend/resume, and doing "iwlist wlan0 scan" immediately after I log in after resume.) So, NM tries to scan a couple times, it fails, and then NM increases the interval between scans to 20 seconds, which is the ~22 second lag I reported above. I own a T500 configured with only intel graphic card (internal) only, AMD card disabled, and a intel wifi card (iwlwifi module), and experiences the same issue when resuming from suspend mode (Fedora 19 Gnome 32b) Yesterday, I tried the live iso using a thumbdrive: no problem. I installed F19 Gnome to another partition: no problem (kernel 3.9.5) I updated everything (kernel up to 3.11.x): no problem. I updated the kernel to PAE version (live installer installs non-PAE kernel): no problem. ==> The only difference is that my failing F19 installation has been installed through netinstall. Tonight, I am going to make a fresh net install, in order to compare fresh live and fresh net installations ! Obviously, some packages and/or some services are missing. The interesting point is that some dbus and nm error are still shown in the logs on the good installation, with resume from suspend working ! So maybe people here are just searching for in the wrong direction. The original reporter of this bug is using Xfce. Regarding bug #968833, it seems some Xfce users have to install F19 using netinstall, because live installer fails (it happens on my hardware, see comment 42). https://bugzilla.redhat.com/show_bug.cgi?id=968833#c42 The fact that few people are experiencing this bug may be because of a net installer bug ? @Jan Pazdziora Could you please use the live cd to test if suspend and resume from suspend is working on your hardware, using live media ? No installation needed If possible, please test Xfce spin to confirm your spin on your hardware, and Gnome live, to compare with my tests ? I installed F19 Gnome i686 using netinstall on another partition. And tried many time so suspend and resume the laptop for 2 fresh installations, one done using live cd, and the other one using net installer. In fact, for both installations, resuming sometimes works, sometimes fails. Bad joy yesterday, sorry. It is weird, but the common behaviour is: - when suspending manually using "sudo pm-suspend", the system always resumes properly, and only sometimes The wifi network is lost (never comes back). First suspend/resume (from cold reboot) is always successful. - when suspending using Gnome (either after scheduled downtime, or via the menu with alternate-status-menu), it always fails. The 1st suspend/resume is ok, then system is slow but usable, but the wifi network never comes back. On the 2nd suspend/resume, the Pc remains stuck on gdm, and can't even log in. After reading many bug reports, I tried to blacklist mei_me module and adding iwlwifi to /etc/pm/config.d. Individually and this 2 settings together. It is getting me mad. Really any clue ? I resinstalled the PC, after deleting all partitions, just in case. It appears that with original kernel (3.9.5) resuming from suspend works. With uptodate kernel 3.11.4, it fails. I found bug #1020078, which is exactly the same bug, and I updated it. Just realized that my 2 previous posts were useless, with no log, in order to help you. Sorry about that. Fred My mistake, Bug #1020078 is different from this bug. this bug is about NetworkManager bug on Xfce Spin, wheras Bug #1020078 is about systemd/dbus issue on Gnome. I still have this problem. I upgraded from Fedora 17 last week to fedora 20. From reading the above, it appears that this bug migrated from fedora 19 to 20. Anyone else experiencing this problem still? I have an intel wifi card and I'm using XFCE. This message is a notice that Fedora 19 is now at end of life. Fedora has stopped maintaining and issuing updates for Fedora 19. It is Fedora's policy to close all bug reports from releases that are no longer maintained. Approximately 4 (four) weeks from now this bug will be closed as EOL if it remains open with a Fedora 'version' of '19'. 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 19 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. This message is a reminder that Fedora 20 is nearing its end of life. Approximately 4 (four) weeks from now Fedora will stop maintaining and issuing updates for Fedora 20. 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 '20'. 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 20 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. Fedora 20 changed to end-of-life (EOL) status on 2015-06-23. Fedora 20 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. |