u-blox TOBY-R200 Intermittent Long Registration on Simple Connect

Mon Apr 30 16:34:23 UTC 2018

> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.408139] [plugin manager] task 4,ttyACM0: found '7' plugins to try
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.408278] [plugin manager] task 4,ttyACM0: will try with plugin 'u-blox'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.408414] [plugin manager] task 4,ttyACM0: will try with plugin 'Telit'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.408538] [plugin manager] task 4,ttyACM0: will try with plugin 'Via CBP7'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.408662] [plugin manager] task 4,ttyACM0: will try with plugin 'Iridium'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.408789] [plugin manager] task 4,ttyACM0: will try with plugin 'Nokia'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.408907] [plugin manager] task 4,ttyACM0: will try with plugin 'Cinterion'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.409032] [plugin manager] task 4,ttyACM0: will try with plugin 'Generic'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.409184] [plugin manager) task 4,ttyACM0: started
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.409322] [plugin manager] task 4,ttyACM0: checking with plugin 'u-blox'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.409547] (u-blox) [ttyACM0] probe required: 'at'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.409740] (tty/ttyACM0) launching port probing: 'at'
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.411520] [plugin manager] task 4,ttyACM0: got suggested plugin (u-blox)
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.414868] [plugin Manager] task 4: still 1 running probes (1 active): ttyACM0
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.428515] (ttyACM0) opening serial port...
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.430200] (ttyACM0): setting up baudrate: 57600
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.431460] (ttyACM0) device open count is 1 (open)
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.432402] (ttyACM0): port attributes not fully set
> Apr  9 15:10:40 canect2 daemon.debug ModemManager[252]: <debug> [1523286640.533980] (tty/ttyACM0) waiting for READY unsolicited message...
> Apr  9 15:10:41 canect2 daemon.debug ModemManager[252]: <debug> [1523286641.372499] [plugin manager] task 4: min probing time elapsed
> Apr  9 15:10:41 canect2 daemon.debug ModemManager[252]: <debug> [1523286641.372683] [plugin Manager] task 4: still 1 running probes (1 active): ttyACM0
> Apr  9 15:10:41 canect2 daemon.debug ModemManager[252]: <debug> [1523286641.697020] (ttyACM0): <-- '<CR><LF>+PACSP0<CR><LF>'
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.874992] (tty/ttyACM0) timed out waiting for READY unsolicited message
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.875680] (ttyACM0): --> 'AT<CR>'
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.879180] (ttyACM0): <-- 'AT<CR><CR><LF>OK<CR><LF>'
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.879990] (tty/ttyACM0) port is AT-capable
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.880393] [plugin manager] task 4,ttyACM0: found best plugin for port (u-blox)
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.880603] [plugin manager] task 4,ttyACM0: finished in '22.009174' seconds
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.880830] [plugin manager] task 4,ttyACM0: best plugin matches device reported one: u-blox
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.880996] [plugin manager] task 4: no more ports to probe
> Apr  9 15:11:00 canect2 daemon.debug ModemManager[252]: <debug> [1523286660.881226] [plugin manager] task 4: finished in '22.010629' seconds
>
> The above issue where the 20 second timeout occurs is only if MM starts before the ttyACM interfaces are initialized.  In that case the registration issue does not seem to occur (after testing several times).
>
> If I put in a 7 second sleep in the MM init script right before MM is lauched, I do not see the 20 second timeout. In this case I instead get the longer registration where the "Simple connect state (5/8): Register" step reports "Launching automatic network registration..." and takes 60 seconds to register with the network before moving on to the next simple connect state.  The interesting thing is that the ttyACM0 interface takes 60 seconds to receive the +CEREG and other messages, but the ttyACM1 interface is receiving those messages at various points during the 60 seconds.  Also when the ttyACM0 receives its messages, it gets several messages all at once with 4 copies of the messages received all at once.  It almost looks like a modem firmware issue where ttyACM0 stops responding for 60 seconds and then blasts out all waiting messages that occurred during that time.
>
>
> It looks like no matter what I do I am encountering a delay or some sort on boot, one in probing the modem or another in the registration.  If I could resolve the 20 second timeout issue, that would resolve my main issue as I really don't want to put a delay before MM starts.
>
> I don't understand why there is a 20 second timeout.  Couldn't you just test the AT interface right away with 'AT' instead of waiting a timeout and then trying it.  Also 20 seconds is a long time.  Couldn't a much shorter timeout be put in with some message sent to the modem to get it to respond (like 'AT') and do that several times to add up to 20 seconds.  This seems like it would be much quicker in cases where the modem did not respond immediately and might resolve this issue.
>

That 20s timeout is really an artifact added for the TOBY-L4, to wait
for the +READY URC it sends if the port is detected via hotplug
events. It's actually just to make it quicker the probing in the
TOBY-L4. This should be therefore something specific for the TOBY-L4
and not something generic for all u-blox modems... sorry for that :/

I'll gladly accept a patch that makes this 20s timeout something
specific for the TOBY-L4 ;)

-- 
Aleksander
https://aleksander.es