Dan Williams <d...@redhat.com> writes:
> On Thu, 2017-01-05 at 22:21 +0100, Bjørn Mork wrote:
>> Dan Williams <d...@redhat.com> writes:
>>
>> > so I guess the answer is 'systemd'.
>>
>> And I am actually running systemd on this laptop, even if I am old
>> and
>> grumpy enough to whine about how it changes everything I'm familiar
>> with.
>
> Hah :) So yeah, looks like you're running systemd.
>
>> > Do you see NM log lines about "suspending" and "waking up"?
>>
>> "journalctl --unit=NetworkManager|egrep -i 'suspend|resume'" got me
>> this:
>>
>> Jan 05 20:46:05 miraculix NetworkManager[8315]:
>> <info> [1483645565.8375] manager: logging: level 'TRACE' domains
>> 'PLATFORM,RFKILL,ETHER,WIFI,BT,MB,DHCP4,DHCP6,PPP,IP4,IP6,AUTOIP4,DNS
>> ,VPN,SHARING,SUPPLICANT,AGENTS,SETTINGS,SUSPEND,CORE,DEVICE,OLPC,INFI
>> NIBAND,FIREWALL,ADSL,BOND,VLAN,BRIDGE,TEAM,CONCHECK,DCB,DISPATCH,AUDI
>> T,SYSTEMD'
>> Jan 05 20:46:22 miraculix NetworkManager[8315]: <debug>
>> [1483645582.2054] sleep-monitor-sd: received RESUME signal
>> Jan 05 20:57:31 miraculix NetworkManager[8315]: <debug>
>> [1483646251.1373] sleep-monitor-sd: received RESUME signal
>> Jan 05 22:03:36 miraculix NetworkManager[8315]: <debug>
>> [1483650216.0202] sleep-monitor-sd: received RESUME signal
>
> I'd expect to see:
>
> Jan 04 18:00:58 <info> [1483574458.1798] manager: sleep requested (sleeping:
> no enabled: yes)
> Jan 04 18:00:58 <info> [1483574458.1801] manager: sleeping...
> Jan 04 18:00:58 <info> [1483574458.1810] manager: NetworkManager state is
> now ASLEEP
> ... time passes ...
> Jan 04 20:41:57 <info> [1483584117.6135] manager: wake requested (sleeping:
> yes enabled: yes)
> Jan 04 20:41:57 <info> [1483584117.6137] manager: waking up...
> Jan 04 20:41:57 <info> [1483584117.6139] device (enp0s25): state change:
> unavailable -> unmanaged (reason 'sleeping') [20 10 37]
> Jan 04 20:41:57 <info> [1483584117.7148] device (enp0s25): state change:
> unmanaged -> unavailable (reason 'managed') [10 20 2]
> Jan 04 20:41:57 <info> [1483584117.9160] device (wlp4s0): state change:
> unmanaged -> unavailable (reason 'managed') [10 20 2]
>
> and that's logging at the Info level, so you should see that without
> jumping to TRACE level. Quite odd that you don't.
Uhm, right "sleep". That's something else :)
This is an extract of "journalctl --unit=NetworkManager|egrep -i
'sleep|resume|udev'":
Jan 05 23:17:50 miraculix NetworkManager[8315]: <debug> [1483654670.8605]
sleep-monitor-sd: received SLEEP signal
Jan 05 23:17:50 miraculix NetworkManager[8315]: <debug> [1483654670.8607]
manager: Received sleeping signal
Jan 05 23:17:50 miraculix NetworkManager[8315]: <info> [1483654670.8609]
manager: sleep requested (sleeping: no enabled: yes)
Jan 05 23:17:50 miraculix NetworkManager[8315]: <info> [1483654670.8611]
manager: sleeping...
Jan 05 23:17:50 miraculix NetworkManager[8315]: <debug> [1483654670.8617]
device[0x563f66811d30] (eth0): unmanaged: flags set to
[sleeping,!loopback,!platform-init,!user-settings=0x1/0x59/unmanaged,
set-unmanaged [sleeping=0x1], reason sleeping, transition-state)
Jan 05 23:17:50 miraculix NetworkManager[8315]: <info> [1483654670.8618]
device (eth0): state change: unavailable -> unmanaged (reason 'sleeping') [20
10 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3416]
manager: sleep: wait disconnection of device wlan0
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3417]
device[0x563f6677e000] (wlan0): queued state change to deactivating due to
sleeping (id 208432)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3417]
device[0x563f66a21f30] (nlmon0): unmanaged: flags set to
[sleeping,by-default,!loopback,!platform-init,!user-settings=0x101/0x159/unmanaged,
set-unmanaged [sleeping=0x1], reason sleeping)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3417]
device[0x563f6692f2e0] (cdc-wdm0): unmanaged: flags set to
[sleeping,!loopback,!platform-init,!user-settings=0x1/0x59/unmanaged,
set-unmanaged [sleeping=0x1], reason sleeping, transition-state)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <info> [1483654671.3418]
device (cdc-wdm0): state change: disconnected -> unmanaged (reason 'sleeping')
[30 10 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <info> [1483654671.3434]
device (wlan0): state change: activated -> deactivating (reason 'sleeping')
[100 110 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3513]
device[0x563f6677e000] (wlan0): queued state change to disconnected due to
sleeping (id 208448)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <info> [1483654671.3513]
device (wlan0): state change: deactivating -> disconnected (reason 'sleeping')
[110 30 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3523]
device[0x563f6677e000] (wlan0): deactivating device (reason 'sleeping') [37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.4391]
manager: sleep: unmanaging device wlan0
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.4392]
device[0x563f6677e000] (wlan0): unmanaged: flags set to
[sleeping,!loopback,!platform-init,!user-explicit,!user-settings=0x1/0x79/unmanaged,
set-unmanaged [sleeping=0x1], reason sleeping, transition-state)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.4392]
device[0x563f6677e000] (wlan0): queued state change to unmanaged due to
sleeping (id 208505)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <info> [1483654671.4638]
device (wlan0): state change: disconnected -> unmanaged (reason 'sleeping') [30
10 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.5829]
manager: sleep: device wlan0 is ready
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.5829]
sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.0155]
sleep-monitor-sd: received RESUME signal
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.0156]
sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 23:52:08 miraculix NetworkManager[8315]: <info> [1483656728.0158]
manager: wake requested (sleeping: yes enabled: yes)
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.0163]
device[0x563f66811d30] (eth0): unmanaged: flags set to
[!sleeping,!loopback,!platform-init,!user-settings=0x0/0x59/managed,
set-managed [sleeping=0x1], reason managed, transition-state)
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.2374]
device[0x563f6677e000] (wlan0): unmanaged: flags set to
[!sleeping,!loopback,!platform-init,!user-explicit,!user-settings=0x0/0x79/managed,
set-managed [sleeping=0x1], reason managed, transition-state)
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7797]
device[0x563f66a21f30] (nlmon0): unmanaged: flags set to
[by-default,!sleeping,!loopback,!platform-init,!user-settings=0x100/0x159/manageable,
set-managed [sleeping=0x1], reason managed)
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7804] udev
rfkill event: action 'remove' device 'rfkill26'
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7835]
sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7858] udev
rfkill event: action 'add' device 'rfkill27'
Jan 05 23:52:17 miraculix NetworkManager[8315]: <debug> [1483656737.0046]
platform-linux: UDEV event: action 'add' subsys 'net' device 'wwan0' (41);
seqnum=4507
Jan 05 23:52:17 miraculix NetworkManager[8315]: <trace> [1483656737.0046]
platform-linux: udev-add[wwan0,41]: device added
Note that 'cdc-wdm0' is going to unmanaged. 'wwan0' is not?
> Can you grep the NM journal output for "inhibit"? Perhaps it's built
> for systemd power management but that power management isn't actually
> enabled or working? You should get some hits for this in either case:
>
> _LOGW ("inhibit: failed (%s)", error->message);
> _LOGW ("inhibit: didn't get a single fd back");
> _LOGD ("inhibit: inhibitor fd is %d", self->inhibit_fd);
>
> would be possible messages.
Got the last one:
root@miraculix:/tmp# journalctl --unit=NetworkManager|egrep -i inhibit
Jan 04 18:10:22 miraculix NetworkManager[8315]: <debug> [1483549822.8534]
sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 04 18:10:31 miraculix NetworkManager[8315]: <debug> [1483549831.1536]
sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 04 18:10:31 miraculix NetworkManager[8315]: <debug> [1483549831.9598]
sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 04 18:37:17 miraculix NetworkManager[8315]: <debug> [1483551437.5307]
sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 04 18:54:53 miraculix NetworkManager[8315]: <debug> [1483552493.2074]
sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 04 18:54:53 miraculix NetworkManager[8315]: <debug> [1483552493.9648]
sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 04 19:33:06 miraculix NetworkManager[8315]: <debug> [1483554786.7031]
sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 04 20:04:01 miraculix NetworkManager[8315]: <debug> [1483556641.0917]
sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 04 20:04:01 miraculix NetworkManager[8315]: <debug> [1483556641.9009]
sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 20:46:16 miraculix NetworkManager[8315]: <debug> [1483645576.4266]
sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 20:46:22 miraculix NetworkManager[8315]: <debug> [1483645582.2054]
sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 20:46:23 miraculix NetworkManager[8315]: <debug> [1483645583.0393]
sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 20:57:21 miraculix NetworkManager[8315]: <debug> [1483646241.0498]
sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 20:57:31 miraculix NetworkManager[8315]: <debug> [1483646251.1373]
sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 20:57:31 miraculix NetworkManager[8315]: <debug> [1483646251.9211]
sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 20:58:00 miraculix NetworkManager[8315]: <debug> [1483646280.0683]
sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 22:03:36 miraculix NetworkManager[8315]: <debug> [1483650216.0202]
sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 22:03:36 miraculix NetworkManager[8315]: <debug> [1483650216.7939]
sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.5829]
sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.0156]
sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7835]
sleep-monitor-sd: inhibit: inhibitor fd is 19
Bjørn
_______________________________________________
ModemManager-devel mailing list
ModemManager-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
