> -----Original Message-----
> From: Aleksander Morgado [mailto:aleksan...@aleksander.es]
> Sent: Friday, April 06, 2018 3:37 AM
> To: Matthew Starr
> Cc: Dan Williams; modemmanager-devel@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
_______________________________________________
ModemManager-devel mailing list
ModemManager-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel

Reply via email to