GNOME.org
 

Re: GSM conn up fails first time with SIM PIN

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
networkmanager-list gnome org
https://mail.gnome.org/mailman/listinfo/networkmanager-list
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]