Using u-blox TOBY-R200, ModemManager not detecting already registered with network

Thu Feb 1 23:41:32 UTC 2018

On Thu, 2018-02-01 at 22:09 +0000, Matthew Starr wrote:
> I am using a TOBY-R200 which does not support USB Ethernet like TOBY-
> L2 models, but only supports AT interface over USB serial.  When I
> use a NetworkManager profile to start a 3G/4G connection using
> ModemManager with the TOBY-R200, the registration step takes a long
> time (~37 seconds).  The modem does eventually connect and everything
> work, but it takes too long for my use case.  When I use a u-blox
> LISA U230 modem with the same software configuration, hardware
> platform, and SIM card, I get a connection quickly (~5 second).  When
> I put ModemManager in debug mode there is a difference in the
> connection between the two at the registration step as shown below. I
> have the same issue on ModemManager versions 1.4.14, 1.6.4, and
> 1.6.12.

<snip>

> On the TOBY R200, instead of realizing that the modem is already
> registered with the network, it runs AT+COPS=0 to reregister with the
> network.  I confirmed that the modem registered with the network by
> checking the AT+CREG?, AT+CEREG?, and AT+CGREG? commands.  Here is
> what ModemManager is outputting when connecting to the network:

Do you see this line at all?

Modem XXX: 3GPP Registration state changed (XXX -> registering)

Basically, right after enabling the modem, ModemManager should be
running initial registration checks.  That will run a sequence of
AT+CREG?, AT+CGREG?, and AT+CEREG? requests which should report the
operator ID (eg MCC/MNC).  This should all happen before the connect,
but perhaps the NM connect request is happening to quickly.

Can you include a bit more of the ModemManager debug output from the
time the modem is "enabling" until what you show below?

Dan

> Feb 18 17:32:29 canect2 daemon.info NetworkManager[307]: <info>  [-
> 185178451.8116] device (ttyACM0): Activation: starting connection
> 'Aeris' (83187ceb-ad3a-4af8-92d8-7a255d9c5e3f)
> Feb 18 17:32:29 canect2 daemon.info NetworkManager[307]: <info>  [-
> 185178451.8155] audit: op="connection-activate" uuid="83187ceb-ad3a-
> 4af8-92d8-7a255d9c5e3f" name="Aeris" pid=1021 uid=0 result="success"
> Feb 18 17:32:29 canect2 daemon.info NetworkManager[307]: <info>  [-
> 185178451.8230] device (ttyACM0): state change: disconnected ->
> prepare (reason 'none') [30 40 0]
> Feb 18 17:32:29 canect2 daemon.info NetworkManager[307]: <info>  [-
> 185178451.8302] manager: NetworkManager state is now CONNECTING
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <info>  [-
> 185178451.838433] [mm-iface-modem-simple.c:641] connect_auth_ready():
> Simple connect started...
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.838916] [mm-iface-modem-simple.c:651]
> connect_auth_ready():    PIN: unspecified
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.839073] [mm-iface-modem-simple.c:653]
> connect_auth_ready():    Operator ID: unspecified
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.839171] [mm-iface-modem-simple.c:655]
> connect_auth_ready():    Allowed roaming: yes
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.839254] [mm-iface-modem-simple.c:657]
> connect_auth_ready():    APN: iot.aer.net
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.839353] [mm-iface-modem-simple.c:662]
> connect_auth_ready():    IP family: ipv4v6
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.839440] [mm-iface-modem-simple.c:673]
> connect_auth_ready():    Allowed authentication: unspecified
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.839522] [mm-iface-modem-simple.c:675]
> connect_auth_ready():    User: unspecified
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.839602] [mm-iface-modem-simple.c:677]
> connect_auth_ready():    Password: unspecified
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.839679] [mm-iface-modem-simple.c:679]
> connect_auth_ready():    Number: *99#
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <info>  [-
> 185178451.839743] [mm-iface-modem-simple.c:469] connection_step():
> Simple connect state (4/8): Wait to get fully enabled
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <info>  [-
> 185178451.840022] [mm-iface-modem-simple.c:478] connection_step():
> Simple connect state (5/8): Register
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.840252] [mm-iface-modem-3gpp.c:407]
> mm_iface_modem_3gpp_register_in_network(): Launching automatic
> network registration...
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.841569] [mm-port-serial.c:1296] mm_port_serial_open():
> (ttyACM0) device open count is 2 (open)
> Feb 18 17:32:29 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178451.842205] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> --> 'AT+COPS=0<CR>'
> Feb 18 17:32:42 canect2 user.alert kernel: [ 1806.015885] wlan: mlan0
> START SCAN
> Feb 18 17:32:44 canect2 user.warn kernel: [ 1807.628802] wlan: SCAN
> COMPLETED: scanned AP count=12
> Feb 18 17:32:44 canect2 user.err kernel: [ 1807.659005] Invalid
> sched_scan req parameter
> Feb 18 17:32:46 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178434.854065] [mm-broadband-modem.c:1991]
> modem_load_signal_quality(): loading signal quality...
> Feb 18 17:32:46 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178434.854351] [mm-port-serial.c:1296] mm_port_serial_open():
> (ttyACM0) device open count is 3 (open)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.932620] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> <-- '<CR><LF>OK<CR><LF>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.933119] [mm-iface-modem-3gpp.c:761]
> mm_iface_modem_3gpp_run_registration_checks(): Running registration
> checks (CS: 'yes', PS: 'yes', EPS: 'yes')
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.933349] [mm-port-serial.c:1296] mm_port_serial_open():
> (ttyACM0) device open count is 4 (open)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.933540] [mm-port-serial.c:1353] _close_internal():
> (ttyACM0) device open count is 3 (close)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.933873] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> --> 'AT+CIND?<CR>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.945441] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> <-- '<CR><LF>+CIND:
> 5,3,1,0,0,0,0,0,2,0,0,0<CR><LF><CR><LF>OK<CR><LF>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.946423] [mm-port-serial.c:1353] _close_internal():
> (ttyACM0) device open count is 2 (close)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.947295] [mm-iface-modem.c:1206] update_signal_quality():
> Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated
> (60)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.947864] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> --> 'AT+CREG?<CR>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.960041] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> <-- '<CR><LF>+CREG:
> 2,1,"####","########",6<CR><LF><CR><LF>OK<CR><LF>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.961122] [mm-port-serial.c:1296] mm_port_serial_open():
> (ttyACM0) device open count is 3 (open)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.961698] [mm-port-serial.c:1353] _close_internal():
> (ttyACM0) device open count is 2 (close)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.962244] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> --> 'AT+CGREG?<CR>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.975696] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> <-- '<CR><LF>+CGREG:
> 2,1,"####","########",6,"6C"<CR><LF><CR><LF>OK<CR><LF>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.976795] [mm-port-serial.c:1296] mm_port_serial_open():
> (ttyACM0) device open count is 3 (open)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.977362] [mm-port-serial.c:1353] _close_internal():
> (ttyACM0) device open count is 2 (close)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.977865] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> --> 'AT+CEREG?<CR>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.991164] [mm-port-serial-at.c:460] debug_log(): (ttyACM0):
> <-- '<CR><LF>+CEREG: 2,0<CR><LF><CR><LF>OK<CR><LF>'
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.992035] [mm-port-serial.c:1353] _close_internal():
> (ttyACM0) device open count is 1 (close)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.992719] [mm-iface-modem-3gpp.c:275]
> run_registration_checks_ready(): Modem is currently registered in a
> 3GPP network
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <info>  [-
> 185178421.993368] [mm-iface-modem-simple.c:501] connection_step():
> Simple connect state (6/8): Bearer
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.993795] [mm-iface-modem-simple.c:521] connection_step():
> Creating new bearer...
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.994256] [mm-broadband-modem.c:297] modem_create_bearer():
> Creating Broadband bearer in broadband modem
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.996835] [mm-port-serial.c:1296] mm_port_serial_open():
> (ttyACM0) device open count is 2 (open)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.997384] [mm-port-serial.c:1353] _close_internal():
> (ttyACM0) device open count is 1 (close)
> Feb 18 17:32:59 canect2 daemon.info ModemManager[300]: <debug> [-
> 185178421.998174] [mm-broadband-modem.c:258]
> modem_create_bearer_finish(): New bearer created at DBus path
> '/org/freedesktop/ModemManager1/Bearer/0'
> Feb 18 17:33:00 canect2 daemon.info ModemManager[300]: <info>  [-
> 185178420.002296] [mm-iface-modem-simple.c:583] connection_step():
> Simple connect state (7/8): Connect
> 
> Does anyone know why both these devices are connecting using the same
> AT interface, but ModemManager cannot detect that the TOBY R200 is
> already registered with the network causing a long registration time?
> 
> Any ideas how I could speed this up or make ModemManager realize the
> modem is registered already?
> 
> Best regards,
>  
> Matthew Starr
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel