Modemmanager significant startup delay

Wed Aug 21 19:20:36 UTC 2019

Amol,

Try this 77-mm-sierra.rules udev rules file with port type hints for
Sierra MDM9x30 chipset modems.

Thanks,
Paul

On Wed, Aug 21, 2019 at 5:23 AM Amol Lad <Amol.Lad at 4rf.com> wrote:
>
> Please help with this. What could be the cause of significant MM startup delay?
>
>
>
> From: ModemManager-devel <modemmanager-devel-bounces at lists.freedesktop.org> On Behalf Of Amol Lad
> Sent: Monday, 19 August 2019 4:05 PM
> To: modemmanager-devel at lists.freedesktop.org
> Subject: Modemmanager significant startup delay
>
>
>
> 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).
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel

-- 
Random quote of the week/month/whenever i get to updating it:
"Criticism may not be agreeable, but it is necessary. It fulfils the
same function as pain in the human body. It calls attention to an
unhealthy state of things." - Winston Churchill
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 77-mm-sierra.rules
Type: application/octet-stream
Size: 1170 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20190821/552da2c0/attachment.obj>