On Sat, 2017-04-15 at 13:11 +0100, Colin Helliwell wrote: > I have NM setup with ModemManager and GSM modem, and can bring up the > connection. But when I enable a SIM PIN lock, the first 'nmcli conn > up' from reboot fails. > I can see that the modem is being unlocked ok, and is indeed > registered afterwards. And a retry of the 'conn up' also works. > I wonder if there's some sequence/timing issue on the first time, > when the modem has to be brought out of locked state. (I leave the > enabling to NM/MM; with the PIN in the NM connection settings). > > NM log is below. I *think* the point at which it goes awry is > indicated by the > 'enabling' --> 'disabled' (reason: unknown) @ 12:51:37 > Unable to spot at the MM end of things [these logs omitted here] > what's triggering this change. Could it just be a timeout? (circa > 20secs)
Can you grab MM debug logs for this sequence too? I can't see what it would be from the NM side, maybe having both together would help. Dan > > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8252] agent-manager: req[0x1c4e918, :1.9/nmcli- > connect/0]: requesting permissions > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8283] agent-manager: req[0x1c4e918, :1.9/nmcli- > connect/0]: agent registered > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8367] policy: re-enabling autoconnect for all connections > with failed secrets > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8477] active-connection[0x1c3bdd0]: set device "ttyMux1" > [0x1c3e3b0] > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8500] device[0x1c3e3b0] (ttyMux1): add_pending_action > (1): 'activation-0x1c3bdd0' > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8583] active-connection[0x1c3bdd0]: constructed > (NMActRequest, version-id 2, type managed) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8611] device[0x1c3e3b0] (ttyMux1): add_pending_action > (2): 'autoactivate' > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8634] device[0x1c3e3b0] (ttyMux1): remove_pending_action > (1): 'autoactivate' > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8645] device[0x1c3e3b0] (ttyMux1): unmanaged: flags set > to [!sleeping,!loopback,!platform-init,!user-explicit,!user- > settings=0x0/0x79/managed], set-managed [user-explicit=0x20], reason > user-requested) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257074.8820] device (ttyMux1): Activation: starting > connection 'Vodafone' (e0f97177-2f8e-4ed4-9942-7b4e499397cc) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8845] device[0x1c3e3b0] (ttyMux1): activation-stage: > schedule activate_stage1_device_prepare,2 (id 204) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.8903] create NMAuditManager singleton (0x75300ec0) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257074.8926] audit: op="connection-activate" > uuid="e0f97177-2f8e-4ed4-9942-7b4e499397cc" name="Vodafone" pid=1383 > uid=0 result="success" > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9030] device[0x1c3e3b0] (ttyMux1): activation-stage: > invoke activate_stage1_device_prepare,2 (id 204) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257074.9036] device (ttyMux1): state change: > disconnected -> prepare (reason 'none') [30 40 0] > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9105] active-connection[0x1c3bdd0]: set state activating > (was unknown) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9164] active-connection[0x1c3bdd0]: check-master-ready: > not signalling (state activating, no master) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9216] Secrets requested for connection > /org/freedesktop/NetworkManager/Settings/2 (Vodafone/gsm) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9219] agent-manager: req[0x1c4e918, :1.9/nmcli- > connect/0]: agent allowed for secrets request > [0x1c5ca18/"Vodafone"/"gsm"] > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9222] settings-connection[0x75302fa0,e0f97177-2f8e-4ed4- > 9942-7b4e499397cc]: (gsm:0x1c5ca18) secrets requested flags 0x5 hints > 'pin' > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257074.9224] device (ttyMux1): state change: prepare -> > need-auth (reason 'none') [40 60 0] > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9358] device[0x1c3e3b0] (ttyMux1): activation-stage: > complete activate_stage1_device_prepare,2 (id 204) > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9606] agent-manager: ([0x1c5ca18/"Vodafone"/"gsm"]) > system settings secrets sufficient > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9669] settings-connection[0x75302fa0,e0f97177-2f8e-4ed4- > 9942-7b4e499397cc]: (gsm:0x1c4d880) existing secrets returned > Apr 15 12:51:14 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257074.9691] settings-connection[0x75302fa0,e0f97177-2f8e-4ed4- > 9942-7b4e499397cc]: (gsm:0x1c4d880) secrets request completed > Apr 15 12:51:15 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257075.0033] settings-connection[0x75302fa0,e0f97177-2f8e-4ed4- > 9942-7b4e499397cc]: (gsm:0x1c4d880) new agent secrets processed > Apr 15 12:51:15 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257075.0084] device[0x1c3e3b0] (ttyMux1): activation-stage: > schedule activate_stage1_device_prepare,2 (id 219) > Apr 15 12:51:15 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257075.0744] device[0x1c3e3b0] (ttyMux1): activation-stage: > invoke activate_stage1_device_prepare,2 (id 219) > Apr 15 12:51:15 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257075.0770] device (ttyMux1): state change: need-auth > -> prepare (reason 'none') [60 40 0] > Apr 15 12:51:15 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257075.0902] device[0x1c3e3b0] (ttyMux1): activation-stage: > complete activate_stage1_device_prepare,2 (id 219) > Apr 15 12:51:34 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257094.8482] (ttyMux1): modem state changed, 'locked' -- > > 'disabled' (reason: unknown) > Apr 15 12:51:34 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257094.8492] (ttyMux1): modem state changed, 'disabled' > --> 'enabling' (reason: user preference) > Apr 15 12:51:34 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257094.8494] device[0x1c3e3b0] (ttyMux1): add_pending_action > (2): 'recheck-available' > Apr 15 12:51:34 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257094.8516] modem-broadband[ttyMux1]: launching connection with > ip type 'ipv4' (try 1) > Apr 15 12:51:34 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257094.8530] device[0x1c3e3b0] (ttyMux1): remove_pending_action > (1): 'recheck-available' > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257097.0123] (ttyMux1): modem state changed, 'enabling' > --> 'disabled' (reason: unknown) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257097.0125] device (ttyMux1): state change: prepare -> > disconnected (reason 'user-requested') [40 30 39] > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0128] device[0x1c3e3b0] (ttyMux1): deactivating device > (reason 'user-requested') [39] > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0130] firewall: [0x1bd8900,remove*:"ttyMux1"]: firewall > zone remove ttyMux1:default (not running, simulate success) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0132] firewall: [0x1bd8900,remove*:"ttyMux1"]: complete: > drop request simulating success > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0134] device[0x1c3e3b0] (ttyMux1): remove_pending_action > (1): 'dhcp6' not pending (expected) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0140] device[0x1c3e3b0] (ttyMux1): remove_pending_action > (1): 'autoconf6' not pending (expected) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0143] platform-linux: sysctl: failed to open > '/proc/sys/net/ipv6/conf/ttyMux1/disable_ipv6': (2) No such file or > directory > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0145] platform-linux: sysctl: failed to open > '/proc/sys/net/ipv6/conf/ttyMux1/accept_ra': (2) No such file or > directory > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0148] platform-linux: sysctl: failed to open > '/proc/sys/net/ipv6/conf/ttyMux1/use_tempaddr': (2) No such file or > directory > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0150] modem-broadband[ttyMux1]: notifying ModemManager > about the modem disconnection > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0182] device[0x1c3e3b0] (ttyMux1): ip4-config: update > (commit=1, routes-full-sync=1, new-config=(nil)) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0184] device[0x1c3e3b0] (ttyMux1): ip6-config: update > (commit=1, routes-full-sync=1, new-config=(nil)) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0297] active-connection[0x1c3bdd0]: set state deactivated > (was activating) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0378] active-connection[0x1c3bdd0]: check-master-ready: > not signalling (state deactivated, no master) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0380] device[0x1c3e3b0] (ttyMux1): remove_pending_action > (0): 'activation-0x1c3bdd0' > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0386] modem-broadband[ttyMux1]: notifying ModemManager > about the modem disconnection > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0446] dns-mgr: (update_routing_and_dns): queueing DNS > updates (1) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0450] dns-mgr: (update_routing_and_dns): DNS > configuration did not change > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0452] dns-mgr: (update_routing_and_dns): no DNS changes > to commit (0) > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0454] device[0x1c3e3b0] (ttyMux1): add_pending_action > (1): 'autoactivate' > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0872] active-connection[0x1c3bdd0]: disposing > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0899] device[0x1c3e3b0] (ttyMux1): remove_pending_action > (0): 'autoactivate' > Apr 15 12:51:37 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257097.0905] agent-manager: req[0x1c4e918, :1.9/nmcli- > connect/0]: agent unregistered or disappeared > Apr 15 12:51:38 wg2xx-tx6s NetworkManager[1154]: > <info> [1492257098.3988] (ttyMux1): modem state changed, 'disabled' > --> 'registered' (reason: unknown) > Apr 15 12:51:38 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257098.3991] device[0x1c3e3b0] (ttyMux1): add_pending_action > (1): 'recheck-available' > Apr 15 12:51:38 wg2xx-tx6s NetworkManager[1154]: <debug> > [1492257098.3995] device[0x1c3e3b0] (ttyMux1): remove_pending_action > (0): 'recheck-available' > _______________________________________________ > networkmanager-list mailing list > [email protected] > https://mail.gnome.org/mailman/listinfo/networkmanager-list _______________________________________________ networkmanager-list mailing list [email protected] https://mail.gnome.org/mailman/listinfo/networkmanager-list
