Bug 987128 - After suspend to RAM, systemd-sleep System resumed is followed by systemd Started Suspend, causing delay in NetworkManager operation
After suspend to RAM, systemd-sleep System resumed is followed by systemd Sta...
Status: CLOSED EOL
Product: Fedora
Classification: Fedora
Component: NetworkManager (Show other bugs)
20
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Dan Williams
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-07-22 14:33 EDT by Jan Pazdziora
Modified: 2015-06-29 08:07 EDT (History)
17 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-06-29 08:07:07 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)
(some of the) output of journalctl _TRANSPORT=syslog (73.39 KB, text/plain)
2013-08-28 12:08 EDT, Janna Martl
no flags Details
journalctl output, take 2 (78.44 KB, text/plain)
2013-08-28 12:31 EDT, Janna Martl
no flags Details

  None (edit)
Description Jan Pazdziora 2013-07-22 14:33:57 EDT
Description of problem:

I have Lenovo T410 that I frequently suspend to RAM by closing the lid. After I open the lid, I have to type the password to unlock the screen, and on Fedora 18, the system was back on WiFi when I unlocked the screen. On Fedora 19, it feels like ages before the NetworkManager applet (in XFCE pannel) even starts to flash the green lights signalling that it tries to connect to the network.

Checking /var/log/messages suggests that it's more like 20 seconds but on desktop, it feels like ages.

Now I understand that the culprit might be something else than systemd and that this bugzilla may change component a couple of times -- please tell me which log file to attach and I will try to provide the information.

Version-Release number of selected component (if applicable):

# rpm -q NetworkManager systemd xfce4-panel
NetworkManager-0.9.8.2-5.fc19.i686
systemd-204-9.fc19.i686
xfce4-panel-4.10.1-1.fc19.i686

How reproducible:

Deterministic (on my machine it happens after every resume).

Steps to Reproduce:
1. Have machine connected to WiFi network.
2. Use XFCE.
3. Close the lid to make machine suspend to RAM.
4. Wait until it really start to signal it has suspended (on my T410 it start flashing the moon symbol).
5. Open the lid.
6. Type password to unlock the screen.
7. Check if the network is back on or if it at least tries to connect.

Actual results:

On Fedora 19, the network is shown disconnected and it takes significant time before the machine starts to attempt to connect.

The /var/log/messages shows:

Jul 22 07:48:42 corona kernel: [34056.801810] PM: Syncing filesystems ... done.
Jul 22 20:08:30 corona kernel: [34058.085729] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jul 22 20:08:30 corona kernel: [34058.099577] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[...]
Jul 22 20:08:30 corona kernel: [34061.308012] ata1.00: configured for UDMA/100
Jul 22 20:08:30 corona kernel: [34061.308128] sd 0:0:0:0: [sda] Starting disk
Jul 22 20:08:30 corona kernel: [34061.325320] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
Jul 22 20:08:30 corona kernel: [34061.325513] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1
Jul 22 20:08:30 corona kernel: [34061.560925] PM: resume of devices complete after 2554.186 msecs
Jul 22 20:08:30 corona kernel: [34061.795439] Restarting tasks ... done.
Jul 22 20:08:30 corona systemd[1]: Time has been changed
Jul 22 20:08:30 corona systemd-logind[554]: Lid opened.
Jul 22 20:08:30 corona kernel: [34061.804681] video LNXVIDEO:00: Restoring backlight state
Jul 22 20:08:30 corona systemd-sleep[11598]: System resumed.
Jul 22 20:08:31 corona NetworkManager[549]: <info> (wlan1): supplicant interface state: disconnected -> inactive
Jul 22 20:08:31 corona systemd[1]: Started Suspend.
Jul 22 20:08:31 corona systemd[1]: Requested transaction contradicts existing jobs: File exists
Jul 22 20:08:31 corona systemd[1]: Service sleep.target is not needed anymore. Stopping.
Jul 22 20:08:31 corona systemd[1]: Stopping Sleep.
Jul 22 20:08:31 corona systemd[1]: Stopped target Sleep.
Jul 22 20:08:31 corona systemd[1]: Reached target Suspend.
Jul 22 20:08:31 corona systemd-logind[554]: Operation finished.
Jul 22 20:08:51 corona NetworkManager[549]: <info> Auto-activating connection 'my-network'.
Jul 22 20:08:51 corona NetworkManager[549]: <info> Activation (wlan1) starting connection 'my-network'
Jul 22 20:08:51 corona NetworkManager[549]: <info> (wlan1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jul 22 20:08:51 corona NetworkManager[549]: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) scheduled...

Expected results:

The connection to the network is re-established immediately after resume.

The /var/log/messages content from the time I run Fedora 18 on the same machine shows:

Jun 23 22:27:44 corona kernel: [79914.979790] PM: Syncing filesystems ... done.
Jun 24 07:36:51 corona kernel: [79915.096719] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jun 24 07:36:51 corona kernel: [79915.109272] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[...]
Jun 24 07:36:51 corona kernel: [79918.304296] ata1.00: configured for UDMA/100
Jun 24 07:36:51 corona kernel: [79918.304528] sd 0:0:0:0: [sda] Starting disk
Jun 24 07:36:51 corona kernel: [79918.326632] PM: resume of devices complete after 2286.476 msecs
Jun 24 07:36:51 corona systemd[1]: Time has been changed
Jun 24 07:36:51 corona kernel: [79918.438649] Restarting tasks ... done.
Jun 24 07:36:51 corona systemd-logind[619]: Lid opened.
Jun 24 07:36:51 corona kernel: [79918.450291] video LNXVIDEO:00: Restoring backlight state
Jun 24 07:36:51 corona dbus-daemon[623]: dbus[623]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Jun 24 07:36:51 corona dbus[623]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Jun 24 07:36:51 corona NetworkManager[624]: <info> wake requested (sleeping: yes  enabled: yes)
Jun 24 07:36:51 corona NetworkManager[624]: <info> waking up and re-enabling...
Jun 24 07:36:51 corona NetworkManager[624]: <info> (eth1): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jun 24 07:36:51 corona NetworkManager[624]: <info> (eth1): bringing up device.
Jun 24 07:36:51 corona dbus-daemon[623]: dbus[623]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Jun 24 07:36:51 corona dbus[623]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Jun 24 07:36:51 corona kernel: [79918.765879] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
Jun 24 07:36:51 corona NetworkManager[624]: <info> (eth1): preparing device.
Jun 24 07:36:51 corona NetworkManager[624]: <info> (eth1): deactivating device (reason 'managed') [2]
Jun 24 07:36:51 corona kernel: [79918.768830] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
Jun 24 07:36:51 corona kernel: [79918.769031] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1
Jun 24 07:36:51 corona NetworkManager[624]: <info> (wlan1): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jun 24 07:36:51 corona NetworkManager[624]: <info> (wlan1): bringing up device.
Jun 24 07:36:52 corona kernel: [79919.008021] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
Jun 24 07:36:52 corona NetworkManager[624]: <info> (wlan1): preparing device.
Jun 24 07:36:52 corona NetworkManager[624]: <info> (wlan1): deactivating device (reason 'managed') [2]
Jun 24 07:36:52 corona NetworkManager[624]: <info> (wlan1) supports 5 scan SSIDs
Jun 24 07:36:52 corona NetworkManager[624]: <info> (wlan1): supplicant interface state: starting -> ready
Jun 24 07:36:52 corona NetworkManager[624]: <info> (wlan1): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Jun 24 07:36:52 corona NetworkManager[624]: <warn> Trying to remove a non-existant call id.
Jun 24 07:36:52 corona NetworkManager[624]: <info> (wlan1): supplicant interface state: ready -> inactive
Jun 24 07:36:52 corona NetworkManager[624]: <info> (wlan1) supports 5 scan SSIDs
Jun 24 07:36:54 corona NetworkManager[624]: <info> Auto-activating connection 'my-network'.
Jun 24 07:36:54 corona NetworkManager[624]: <info> Activation (wlan1) starting connection 'my-network'
Jun 24 07:36:54 corona NetworkManager[624]: <info> (wlan1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jun 24 07:36:54 corona NetworkManager[624]: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) scheduled...

Additional info:

Note how on Fedora 18, the

<info> wake requested (sleeping: yes  enabled: yes)

happens the same second the kernel says

LNXVIDEO:00: Restoring backlight state

while on Fedora 19 there is something about

Started Suspend.

and it takes 20 seconds before NetworkManager starts to signal that it is doing something.
Comment 1 Michal Schmidt 2013-07-22 14:51:33 EDT
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.
Comment 2 Jan Pazdziora 2013-07-22 15:21:25 EDT
$ 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.
Comment 3 Jan Pazdziora 2013-07-22 15:35:38 EDT
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.
Comment 4 Christoph Wickert 2013-07-22 16:49:37 EDT
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.
Comment 5 Kevin Fenzi 2013-07-22 18:02:39 EDT
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. ;(
Comment 6 Jan Pazdziora 2013-07-24 01:17:06 EDT
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.
Comment 7 Lennart Poettering 2013-07-25 15:38:05 EDT
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.
Comment 8 Dan Williams 2013-07-25 16:33:26 EDT
(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!
Comment 9 Jan Pazdziora 2013-07-26 13:21:48 EDT
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'
Comment 10 Dan Williams 2013-07-26 13:31:23 EDT
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.
Comment 11 Jan Pazdziora 2013-07-26 14:32:47 EDT
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.
Comment 12 Dan Williams 2013-07-26 16:35:10 EDT
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?
Comment 13 Dan Williams 2013-07-26 16:53:00 EDT
(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.
Comment 14 Jan Pazdziora 2013-07-27 03:06:31 EDT
(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.
Comment 15 Jan Pazdziora 2013-07-27 03:08:16 EDT
Should I try to uninstall the whole pm-utils?
Comment 16 Dan Williams 2013-07-28 11:40:07 EDT
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.
Comment 17 Janna Martl 2013-08-28 01:23:50 EDT
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.
Comment 18 Janna Martl 2013-08-28 01:33:19 EDT
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...
Comment 19 Dan Williams 2013-08-28 08:39:19 EDT
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:""
Comment 20 Janna Martl 2013-08-28 12:08:03 EDT
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...
Comment 21 Janna Martl 2013-08-28 12:31:23 EDT
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.
Comment 22 Dan Williams 2013-08-28 13:13:00 EDT
(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.
Comment 23 Janna Martl 2013-08-28 17:13:16 EDT
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.
Comment 24 Janna Martl 2013-10-15 03:04:54 EDT
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.
Comment 25 openfred 2013-10-17 11:31:04 EDT
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 ?
Comment 26 openfred 2013-10-18 04:05:08 EDT
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 ?
Comment 27 openfred 2013-10-19 14:14:29 EDT
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
Comment 28 openfred 2013-10-22 03:21:58 EDT
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.
Comment 29 froggy 2013-12-25 08:00:26 EST
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.
Comment 30 Fedora End Of Life 2015-01-09 14:03:18 EST
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.
Comment 31 Fedora End Of Life 2015-05-29 05:12:42 EDT
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.
Comment 32 Fedora End Of Life 2015-06-29 08:07:07 EDT
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.

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