Assertion in nm-device-modem.c
Hello,
I have a setup where I manipulate heavily a GSM usb key (this modem) in a stress test when I activate several connections that have purposely a wrong APN settings (to test our controlling service which is responsible to monitor connections and try all connections profile it have). From time to time after a modem hangup, there is an assertion in nm-wwan-modem.c.
I use a cross compile NetworkManager (1.42.6) with ModemManager (1.20.6) on an ARM based linux.
Below is sequence in debug mode:
Jun 23 14:19:59.434578 tap-0000E564 NetworkManager[1921]: Modem hangup
Jun 23 14:19:59.435867 tap-0000E564 NetworkManager[1921]: Connection terminated.
Jun 23 14:19:59.438958 tap-0000E564 NetworkManager[1236]: <info> device (ttyUSB2): state change: config -> failed (reason 'ppp-disconnect', sys-iface-state: 'managed')
Jun 23 14:19:59.439088 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (2): 'in-state-change'
Jun 23 14:19:59.441177 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6366c402864514b0]: set state deactivated (was activating)
Jun 23 14:19:59.442136 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6366c402864514b0]: check-master-ready: not signalling (state deactivated, no master)
Jun 23 14:19:59.442215 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (1): 'activation-251'
Jun 23 14:19:59.445091 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): ip4: set state none (was pending, reason: ip-state-clear)
Jun 23 14:19:59.445167 tap-0000E564 NetworkManager[1236]: <warn> device (ttyUSB2): Activation: failed for connection 'Wrong_Configuration1'
Jun 23 14:19:59.445229 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (2): 'queued-state-change-disconnected'
Jun 23 14:19:59.445298 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): queue-state[disconnected, reason:none, id:18580]: queue state change
Jun 23 14:19:59.445358 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (1): 'in-state-change'
Jun 23 14:19:59.447520 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): queue-state[disconnected, reason:none, id:18580]: change state
Jun 23 14:19:59.447584 tap-0000E564 NetworkManager[1236]: <info> device (ttyUSB2): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Jun 23 14:19:59.447636 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (2): 'in-state-change'
Jun 23 14:19:59.447687 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): deactivating device (reason 'none') [0]
Jun 23 14:19:59.448344 tap-0000E564 NetworkManager[1236]: <debug> global-tracker: sync routing-rule
Jun 23 14:19:59.454096 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (3): 'autoactivate'
Jun 23 14:19:59.454281 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (2): 'in-state-change'
Jun 23 14:19:59.454343 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (1): 'queued-state-change-disconnected'
Jun 23 14:19:59.454700 tap-0000E564 NetworkManager[1236]: <debug> platform: (ppp0) signal: link removed: 249: ppp0 <NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 ppp* init driver ppp rx:0,0 tx:0,0
Jun 23 14:19:59.458811 tap-0000E564 NetworkManager[1236]: <debug> platform: (eth0) signal: address 4 changed: 192.168.19.129/24 brd 192.168.19.255 lft 2362sec pref 2362sec lifetime 1267-31[3598,3598] dev 2 flags noprefixroute src kernel
Jun 23 14:19:59.460852 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (0): 'autoactivate'
Jun 23 14:19:59.461668 tap-0000E564 NetworkManager[1236]: <debug> device[733f76f8dd8c9d7e] (ppp0): unrealize (ifindex 249)
Jun 23 14:19:59.462429 tap-0000E564 NetworkManager[1236]: <debug> device[733f76f8dd8c9d7e] (ppp0): ifindex: set ifindex 0 (old-l3cfg: 2ea0bc2844b6d4f4)
Jun 23 14:19:59.473282 tap-0000E564 NetworkManager[1236]: <debug> device[733f76f8dd8c9d7e] (ppp0): unmanaged: flags set to [platform-init,external-down,!sleeping,!user-settings=0x104/0x115/unmanaged/unrealized], set-unmanaged [platform-init=0x4])
Jun 23 14:19:59.473461 tap-0000E564 NetworkManager[1236]: <debug> device[733f76f8dd8c9d7e] (ppp0): unmanaged: flags set to [platform-init,!sleeping,!user-settings=0x4/0x15/unmanaged/unrealized], forget [user-explicit,user-udev,external-down,is-slave=0x388])
Jun 23 14:19:59.473520 tap-0000E564 NetworkManager[1236]: <debug> device[733f76f8dd8c9d7e] (ppp0): state change: unmanaged -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
Jun 23 14:19:59.473644 tap-0000E564 NetworkManager[1236]: <debug> manager: (ppp0): removing device (managed 0, wol 0)
Jun 23 14:19:59.478647 tap-0000E564 NetworkManager[1236]: <debug> device[733f76f8dd8c9d7e] (ppp0): disposing
Jun 23 14:19:59.478975 tap-0000E564 NetworkManager[1236]: <debug> device[733f76f8dd8c9d7e] (ppp0): finalize(): NMDevicePpp
Jun 23 14:19:59.480184 tap-0000E564 NetworkManager[1236]: <debug> platform-linux: UDEV event: action 'remove' subsys 'net' device 'ppp0' (249); seqnum=3116
Jun 23 14:19:59.480256 tap-0000E564 NetworkManager[1236]: <debug> platform-linux: udev-remove: IFINDEX=249
Jun 23 14:19:59.631111 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6829396946994d3c]: set device "ttyUSB2" [0xaaab1f431030]
Jun 23 14:19:59.631252 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (1): 'activation-252'
Jun 23 14:19:59.636750 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6829396946994d3c]: constructed (NMActRequest, version-id 252, type managed)
Jun 23 14:19:59.647151 tap-0000E564 NetworkManager[1236]: <info> device (ttyUSB2): Activation: starting connection 'Wrong_Configuration2' (7369424a-214c-4ec4-a94d-704598354e70)
Jun 23 14:19:59.647305 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): activation-stage: schedule activate_stage1_device_prepare
Jun 23 14:19:59.648828 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (2): 'recheck-available'
Jun 23 14:19:59.649545 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): activation-stage: invoke activate_stage1_device_prepare
Jun 23 14:19:59.649609 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): ip4: set state pending (was none, reason: stage1)
Jun 23 14:19:59.650642 tap-0000E564 NetworkManager[1236]: <info> device (ttyUSB2): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jun 23 14:19:59.650704 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (3): 'in-state-change'
Jun 23 14:19:59.661323 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6829396946994d3c]: set state activating (was unknown)
Jun 23 14:19:59.664343 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6829396946994d3c]: check-master-ready: not signalling (state activating, no master)
Jun 23 14:19:59.664761 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (2): 'in-state-change'
Jun 23 14:19:59.669126 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (1): 'recheck-available'
Jun 23 14:20:00.514095 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6366c402864514b0]: disposing
Jun 23 14:20:00.606442 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (2): 'recheck-available'
Jun 23 14:20:00.606727 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (1): 'recheck-available'
Jun 23 14:20:00.711038 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (2): 'recheck-available'
Jun 23 14:20:00.711367 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (1): 'recheck-available'
Jun 23 14:20:00.866137 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (2): 'recheck-available'
Jun 23 14:20:00.910845 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (1): 'recheck-available'
Jun 23 14:20:00.919656 tap-0000E564 NetworkManager[1236]: <info> device (ttyUSB2): state change: prepare -> deactivating (reason 'connection-removed', sys-iface-state: 'managed')
Jun 23 14:20:00.919761 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): add_pending_action (2): 'in-state-change'
Jun 23 14:20:00.925835 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6829396946994d3c]: set state deactivating (was activating)
Jun 23 14:20:01.111670 tap-0000E564 NetworkManager[1236]: **
Jun 23 14:20:01.111670 tap-0000E564 NetworkManager[1236]: nm:ERROR:../NetworkManager-1.42.6/src/core/devices/wwan/nm-device-modem.c:80:<unknown-fcn>: assertion failed: (<dropped>)
Jun 23 14:20:01.111670 tap-0000E564 NetworkManager[1236]: Bail out! nm:ERROR:../NetworkManager-1.42.6/src/core/devices/wwan/nm-device-modem.c:80:<unknown-fcn>: assertion failed: (<dropped>)
Jun 23 14:20:00.935126 tap-0000E564 NetworkManager[1236]: <debug> active-connection[6829396946994d3c]: check-master-ready: not signalling (state deactivating, no master)
Jun 23 14:20:00.935302 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (1): 'activation-252'
Jun 23 14:20:00.935456 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): ip4: set state none (was pending, reason: ip-state-clear)
Jun 23 14:20:00.938322 tap-0000E564 NetworkManager[1236]: <debug> device[d9c2a42bf94933e9] (ttyUSB2): remove_pending_action (0): 'in-state-change'
Jun 23 14:20:04.610680 tap-0000E564 NetworkManager[1948]: <info> NetworkManager (version 1.42.6) is starting... (after a restart, boot:2ffc49a0-4119-4432-9f53-e1949f9f79cb)
Jun 23 14:20:04.610773 tap-0000E564 NetworkManager[1948]: <info> Read config: /etc/NetworkManager/NetworkManager.conf
Note that I manage to reproduce with main branch of NM (NM 1.43.10 at the time) but didn't manage to reproduce it with NM 1.40.10. Since the problem doesn't appear to be systematic, there must be a timing issue somewhere.
Anybody have insights on what would go wrong here ? Is the assert could be safely replace by a g_return_if_fail
?
Thanks in advance.