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

Thu Feb 1 22:09:27 UTC 2018

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.

On the LISA U230 with a quick connection:

Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <info>  [1517434871.627410] [mm-iface-modem-simple.c:641] connect_auth_ready(): Simple connect started...
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.627805] [mm-iface-modem-simple.c:651] connect_auth_ready():    PIN: unspecified
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.628014] [mm-iface-modem-simple.c:653] connect_auth_ready():    Operator ID: unspecified
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.628182] [mm-iface-modem-simple.c:655] connect_auth_ready():    Allowed roaming: yes
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.628343] [mm-iface-modem-simple.c:657] connect_auth_ready():    APN: iot.aer.net
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.628518] [mm-iface-modem-simple.c:662] connect_auth_ready():    IP family: ipv4
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.628682] [mm-iface-modem-simple.c:673] connect_auth_ready():    Allowed authentication: unspecified
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.628839] [mm-iface-modem-simple.c:675] connect_auth_ready():    User: unspecified
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.628994] [mm-iface-modem-simple.c:677] connect_auth_ready():    Password: unspecified
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.629154] [mm-iface-modem-simple.c:679] connect_auth_ready():    Number: *99#
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <info>  [1517434871.629296] [mm-iface-modem-simple.c:469] connection_step(): Simple connect state (4/8): Wait to get fully enabled
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <info>  [1517434871.629619] [mm-iface-modem-simple.c:478] connection_step(): Simple connect state (5/8): Register
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.629940] [mm-iface-modem-3gpp.c:400] mm_iface_modem_3gpp_register_in_network(): Already registered in network '123456789012345678901234', automatic registration not launched...
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <info>  [1517434871.630317] [mm-iface-modem-simple.c:501] connection_step(): Simple connect state (6/8): Bearer
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.630561] [mm-iface-modem-simple.c:521] connection_step(): Creating new bearer...
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.634104] [mm-broadband-modem.c:286] modem_create_bearer(): Creating Broadband bearer in broadband modem
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.636403] [mm-port-serial.c:1250] mm_port_serial_open(): (ttyACM0) device open count is 2 (open)
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.640589] [mm-port-serial.c:1307] _close_internal(): (ttyACM0) device open count is 1 (close)
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <debug> [1517434871.641263] [mm-broadband-modem.c:247] modem_create_bearer_finish(): New bearer created at DBus path '/org/freedesktop/ModemManager1/Bearer/0'
Jan 31 21:41:11 canect2 daemon.info ModemManager[249]: <info>  [1517434871.650238] [mm-iface-modem-simple.c:583] connection_step(): Simple connect state (7/8): Connect

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:

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