<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40"> <head> <meta http-equiv="Content-Type" content="text/html; charset=us-ascii"> <meta name="Generator" content="Microsoft Word 15 (filtered medium)"> <style></style> </head> <body lang="EN-NZ" link="#0563C1" vlink="#954F72"> <div class="WordSection1"> Please help with this. What could be the cause of significant MM startup delay? <o:p> </o:p> <div> <div style="border:none;border-top:solid #E1E1E1 1.0pt;padding:3.0pt 0cm 0cm 0cm"> From: ModemManager-devel <modemmanager-devel-bounces@lists.freedesktop.org> On Behalf Of Amol Lad Sent: Monday, 19 August 2019 4:05 PM To: modemmanager-devel@lists.freedesktop.org Subject: Modemmanager significant startup delay </div> </div> <o:p> </o:p> Hi, <o:p> </o:p> I’m using Solidrun’s clearfog-base plarform with Sierra Wireless EM7430 LTE chipset. I’m running OpenWRT 18.06 with ModemManager feed from <a href="https://gitlab.freedesktop.org/mobile-broadband/mobile-broadband-openwrt"> https://gitlab.freedesktop.org/mobile-broadband/mobile-broadband-openwrt</a> <o:p> </o:p> 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 “ <o:p> </o:p> Please advise what is going wrong. <o:p> </o:p> … 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 <o:p> </o:p> Full log is available at: <a href="https://drive.google.com/open?id=19DTc_FwKHmiuEB8VMoAczfzxaVsGPUAJ"> https://drive.google.com/open?id=19DTc_FwKHmiuEB8VMoAczfzxaVsGPUAJ</a> <o:p> </o:p> Please help <o:p> </o:p> Thanks in advance Amol <o:p> </o:p> </div> <hr style="FONT-SIZE: 8pt; FONT-FAMILY: Arial"> 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). </body> </html>