GSM conn up fails first time with SIM PIN

[Colin Helliwell <colin helliwell ln-systems com>]

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)


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'