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

Mon Apr 9 16:25:15 UTC 2018

> -----Original Message-----
> From: Aleksander Morgado [mailto:aleksander at aleksander.es]
> Sent: Friday, April 06, 2018 3:37 AM
> To: Matthew Starr
> Cc: Dan Williams; modemmanager-devel at lists.freedesktop.org
> Subject: Re: u-blox TOBY-R200 Intermittent Long Registration on Simple
> Connect
> 
> Hey!
> 
> > I looked a little more into what was going on and found that this TOBY-R200
> modem takes much longer than other u-blox modems I have used to
> initialize the virtual USB serial ports on startup.  It appears with the USB serial
> ports appear after ModemManager has already started, the longer
> registration occurs.  When I put a delay before ModemManager is started
> until after the USB serial ports appear, then I always get the fast registration.
> This is without the "mmcli -m 0 -e" command being run at all.
> >
> 
> So you mean that if MM tries to poke the ports *while* the TOBY is still
> booting, it makes it timeout in the registration?
> I have seen myself that in a different u-blox device the TTYs are
> *not* ready as soon as they're exposed by the kernel, it may take up to 10s-
> 15s since they are exposed to be ready for AT commands (although it usually
> is something like 5s-8s). But I haven't seen a case where poking the TTYs
> early would end up triggering registration failures or delays.

I blacklisted all the ports except the primary AT port (ttyACM0) following the example file you gave below.  That helped speed up things a little bit since MM isn't waiting on a timeout from a non-AT interface.  Unfortunately I am seeing exactly what you said where the ttyACM0 interface comes up, immediately it probed by MM, and then eventually MM times out after 20 seconds.  After the timeout MM continues with probing the device successfully.  It looks like MM is waiting for a READY message that never comes and eventually times out after 20 seconds.  The interesting thing is that the modem appears to send the message '<CR><LF>+PACSP0<CR><LF>' within the first second of the 20 second timeout period, but MM seems to do nothing with it.  I also tried this with all other valid AT interfaces (ttyACM1 and ttyACM2) not blacklisted at the same time, and they also encountered the same 20 second timeout with the same '+PACSP0' message.  See the following for the case with just ttyACM0 not blacklisted:

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.

> 
> > I am not sure what in ModemManager is causing the registration issue
> based on this ordering of which appears/starts first.
> >
> 
> I've asked u-blox about this and hopefully they'll have an idea of what's
> happening here.

From observations after adding the blacklist for non-AT interfaces, I am not getting the registration issue, but there is the 20 second timeout issue discussed above.  

> 
> >
> > Additionally it seems to take a really long time during a fast registration for
> ModemManager to actually startup, probe the modem, and attempt to
> connect.  It looks like the time between when ModemManager starts and
> when a simple connect can start because enough probing of the modem was
> finished is 34 seconds.  Much of this is waiting for 20 seconds for the
> /dev/ttyACM3, /dev/ttyACM4, and /dev/ttyACM5 interfaces to timeout to
> probing and then another 5 seconds as the same interfaces have AT
> commands sent to it and timed out again.  These are not AT command
> interfaces so it would be nice if this could be optimized for this modem.  I am
> not sure if this can be done or how to do it with ModemManager.
> >
> 
> That is easily solvable if the modem has predefined interfaces for different
> purposes, which is very probable in this case. See e.g. the
> TOBY-L4 port type rules defined here:
> https://cgit.freedesktop.org/ModemManager/ModemManager/tree/plugin
> s/ublox/77-mm-ublox-port-types.rules

I put in the blacklisting for ttyACM3-ttyACM5 which appears to work, but I am still getting a 20 second timeout on valid AT ports.  See above for details of what is going on.

I may send in a patch for a few of the u-blox modems I use to blacklist non-AT ports.

Matthew

> 
> --
> Aleksander
> https://aleksander.es