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' _______________________________________________ networkmanager-list mailing list networkmanager-list@gnome.org https://mail.gnome.org/mailman/listinfo/networkmanager-list
