Modemmanager significant startup delay

Mon Aug 19 10:35:29 UTC 2019

Hi,

I'm using Solidrun's clearfog-base plarform with Sierra Wireless EM7430 LTE chipset. I'm running OpenWRT 18.06 with ModemManager feed from https://gitlab.freedesktop.org/mobile-broadband/mobile-broadband-openwrt

It is taking around 20 seconds for modemanager to bring up the LTE IP interface (i.e. after around 20 seconds 'wwan1' interface is up and I can ping external world). With uqmi the interface comes up instantly. Please refer to below logs (captured in -debug mode). It seems most of this delay is because of "serial command timeout". As you can see from the last time "[plugin manager] task 0: finished in '17.149826' seconds
"

Please advise what is going wrong.

...
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.535657] (ttyUSB2): <-- '<CR>'
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.535956] (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.536110] (tty/ttyUSB2) port is AT-capable
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.536188] [plugin manager] task 0,ttyUSB2: found best plugin for port (Sierra)
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.536269] [plugin manager] task 0,ttyUSB2: finished in '1.604063' seconds
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.536348] [plugin manager] task 0,ttyUSB2: best plugin matches device reported one: Sierra
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.536433] [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.536565] (ttyUSB2) device open count is 0 (close)
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.536702] (ttyUSB2) closing
 port...
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.537143] (ttyUSB2) serial port closed
Mon Aug 19 10:11:05 2019 daemon.debug [2086]: <debug> [1566209465.537304] (ttyUSB2) forced to close port
Mon Aug 19 10:11:06 2019 daemon.debug [2086]: <debug> [1566209466.220126] [plugin manager] task 0: min probing time elapsed
Mon Aug 19 10:11:06 2019 daemon.debug [2086]: <debug> [1566209466.220187] [plugin Manager] task 0: still 2 running probes (2 active): ttyUSB1, ttyUSB0
Mon Aug 19 10:11:08 2019 daemon.debug [2086]: <debug> [1566209468.868113] Parsing AT got: 'Serial command timed out'
Mon Aug 19 10:11:08 2019 daemon.debug [2086]: <debug> [1566209468.868197] Parsing AT got: 'Serial command timed out'
Mon Aug 19 10:11:08 2019 daemon.debug [2086]: <debug> [1566209468.868282] (ttyUSB1): --> 'AT<CR>'
Mon Aug 19 10:11:08 2019 daemon.debug [2086]: <debug> [1566209468.868351] (ttyUSB0): --> 'AT<CR>'
Mon Aug 19 10:11:11 2019 daemon.debug [2086]: <debug> [1566209471.869749] Parsing AT got: 'Serial command timed out'
Mon Aug 19 10:11:11 2019 daemon.debug [2086]: <debug> [1566209471.869831] Parsing AT got: 'Serial command timed out'
Mon Aug 19 10:11:11 2019 daemon.debug [2086]: <debug> [1566209471.869917] (ttyUSB1): --> 'AT<CR>'
Mon Aug 19 10:11:11 2019 daemon.debug [2086]: <debug> [1566209471.869984] (ttyUSB0): --> 'AT<CR>'
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.869689] Parsing AT got: 'Serial command timed out'
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.869745] (tty/ttyUSB1) port is not AT-capable
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.869806] Parsing AT got: 'Serial command timed out'
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.869834] (tty/ttyUSB0) port is not AT-capable
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.869884] (tty/ttyUSB1) probing QCDM...
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.869916] (ttyUSB1) device open count is 0 (close)
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.869943] (ttyUSB1) closing serial port...
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.870349] (ttyUSB1) serial port closed
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.870415] (ttyUSB1) forced to close port
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.870517] (ttyUSB1) opening serial port...
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.870779] (ttyUSB1) device open count is 1 (open)
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.870851] (tty/ttyUSB0) probing QCDM...
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.870886] (ttyUSB0) device open count is 0 (close)
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.870913] (ttyUSB0) closing serial port...
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.871138] (ttyUSB0) serial port closed
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.871196] (ttyUSB0) forced to close port
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.871261] (ttyUSB0) opening serial port...
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.871351] (ttyUSB0) device open count is 1 (open)
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.871423] (ttyUSB1): --> 7e 00 78 f0 7e
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.871485] (ttyUSB0): --> 7e 00 78 f0 7e
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872338] (ttyUSB0): <-- 00 4f 63 74 20 32 32 20 32 30 31 36 30 39 3a 31 30 3a 30 33 4f 63 74 20 31 33 20 32 30 31 36 30 34 3a 30 30 3a 30 30 43 32 32 33 30 30 30 30 3a 06 ff 64 00 02 09 22 a3 95 7e
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872410] (tty/ttyUSB0) port is QCDM-capable
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872447] [plugin manager] task 0,ttyUSB0: found best plugin for port (Sierra)
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872478] [plugin manager] task 0,ttyUSB0: finished in '11.009525' seconds
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872510] [plugin manager] task 0,ttyUSB0: best plugin matches device reported one: Sierra
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872539] [plugin Manager] task 0: still 1 running probes (1 active): ttyUSB1
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872595] (ttyUSB0) device open count is 0 (close)
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872624] (ttyUSB0) closing serial port...
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.872955] (ttyUSB0) serial port closed
Mon Aug 19 10:11:14 2019 daemon.debug [2086]: <debug> [1566209474.873022] (ttyUSB0) forced to close port
Mon Aug 19 10:11:17 2019 daemon.debug [2086]: <debug> [1566209477.870236] (ttyUSB1): --> 7e 00 78 f0 7e
Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug> [1566209480.868659] (tty/ttyUSB1) port is not QCDM-capable
Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug> [1566209480.868716] [plugin manager] task 0,ttyUSB1: found best plugin for port (Sierra)
Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug> [1566209480.868749] [plugin manager] task 0,ttyUSB1: finished in '16.971902' seconds
Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug> [1566209480.868783] [plugin manager] task 0,ttyUSB1: best plugin matches device reported one: Sierra
Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug> [1566209480.868811] [plugin manager] task 0: no more ports to probe
Mon Aug 19 10:11:20 2019 daemon.debug [2086]: <debug> [1566209480.868836] [plugin manager] task 0: finished in '17.149826' seconds

Full log is available at: https://drive.google.com/open?id=19DTc_FwKHmiuEB8VMoAczfzxaVsGPUAJ

Please help

Thanks in advance
Amol

________________________________
The information in this email communication (inclusive of attachments) is confidential to 4RF Limited and the intended recipient(s). If you are not the intended recipient(s), please note that any use, disclosure, distribution or copying of this information or any part thereof is strictly prohibited and that the author accepts no liability for the consequences of any action taken on the basis of the information provided. If you have received this email in error, please notify the sender immediately by return email and then delete all instances of this email from your system. 4RF Limited will not accept responsibility for any consequences associated with the use of this email (including, but not limited to, damages sustained as a result of any viruses and/or any action or lack of action taken in reliance on it).
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20190819/d63d2c4b/attachment-0001.html>