Hi Alexander, I am having some issues with a Cinterion modem on our device. We're running ModemManager 1.8.2 [4.14 kernel]
The device is in a weak coverage area so it loses cell signal 2019-11-27T10:00:27.500773+0000 ModemManager[564]: <debug> [1574848827.500320] (ttyACM1): <-- '<CR><LF>+CIEV: 3,0<CR><LF><CR><LF>+CIEV: 1,2<CR><LF><CR><LF>+CIEV: 4,1<CR><LF>' 2019-11-27T10:00:27.609937+0000 kernel: cdc_ether 1-1:1.10 usb0: kevent 12 may have been dropped 2019-11-27T10:00:27.618523+0000 systemd-networkd[537]: usb0: Lost carrier . . . 2019-11-27T10:00:30.059611+0000 ModemManager[564]: <debug> [1574848830.059261] (ttyACM1): <-- '<CR><LF>+CGREG: 3<CR><LF>' 2019-11-27T10:00:33.040588+0000 ModemManager[564]: <debug> [1574848833.040239] (ttyACM1): <-- '<CR><LF>+CIEV: 1,1<CR><LF>' 2019-11-27T10:00:33.093582+0000 ModemManager[564]: <debug> [1574848833.093236] (ttyACM1): <-- '<CR><LF>+CGREG: 2<CR><LF>' After this the bearer is disconnected 2019-11-27T10:00:39.612824+0000 ModemManager[564]: <debug> [1574848839.612418] Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0' 2019-11-27T10:00:39.613612+0000 ModemManager[564]: <info> [1574848839.613270] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting) 2019-11-27T10:00:39.631930+0000 ModemManager[564]: <debug> [1574848839.631549] cinterion disconnect step 1/3: disconnecting PDP CID 4... 2019-11-27T10:00:39.634924+0000 ModemManager[564]: <debug> [1574848839.634591] (ttyACM1) device open count is 2 (open) 2019-11-27T10:00:39.636932+0000 ModemManager[564]: <debug> [1574848839.636594] (ttyACM1): --> 'AT^SWWAN=0,4,1<CR>' 2019-11-27T10:00:39.679504+0000 ModemManager[564]: <debug> [1574848839.679152] (ttyACM1): <-- '<CR><LF>OK<CR><LF>' 2019-11-27T10:00:39.683482+0000 ModemManager[564]: <debug> [1574848839.683116] cinterion disconnect step 2/3: checking SWWAN interface 1 status... 2019-11-27T10:00:39.686436+0000 ModemManager[564]: <debug> [1574848839.686099] (ttyACM1) device open count is 3 (open) 2019-11-27T10:00:39.687293+0000 ModemManager[564]: <debug> [1574848839.686973] (ttyACM1) device open count is 2 (close) 2019-11-27T10:00:39.688208+0000 ModemManager[564]: <debug> [1574848839.687888] (ttyACM1): --> 'AT^SWWAN?<CR>' 2019-11-27T10:00:39.715376+0000 ModemManager[564]: <debug> [1574848839.715040] (ttyACM1): <-- '<CR><LF>OK<CR><LF>' 2019-11-27T10:00:39.720706+0000 ModemManager[564]: <debug> [1574848839.720059] cinterion disconnect step 3/3: finished 2019-11-27T10:00:39.723603+0000 ModemManager[564]: <debug> [1574848839.723267] (usb0): port now disconnected 2019-11-27T10:00:39.726095+0000 ModemManager[564]: <debug> [1574848839.725751] Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/0' 2019-11-27T10:00:39.726874+0000 ModemManager[564]: <info> [1574848839.726544] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> searching) 2019-11-27T10:00:39.746710+0000 ModemManager[564]: <debug> [1574848839.746321] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (0) After this our sw (client of ModemManager) tries to re-establish the bearer (passes in a 10s timeout to the API call) 2019-11-27T10:04:07.561047+0000 ModemManager[564]: <debug> [1574849047.560693] Launching 3GPP connection attempt with APN 'internet.telecom.co.nz' 2019-11-27T10:04:07.563858+0000 ModemManager[564]: <debug> [1574849047.563523] No specific IP family requested, defaulting to ipv4 2019-11-27T10:04:07.566697+0000 ModemManager[564]: <debug> [1574849047.566363] No specific IP family requested, defaulting to ipv4 2019-11-27T10:04:07.567196+0000 ModemManager[564]: <debug> [1574849047.566894] Looking for best CID... 2019-11-27T10:04:07.567805+0000 ModemManager[564]: <debug> [1574849047.567488] (ttyACM1) device open count is 2 (open) 2019-11-27T10:04:07.574680+0000 ModemManager[564]: <debug> [1574849047.574309] (ttyACM1): --> 'AT+CGDCONT?<CR>' 2019-11-27T10:04:07.600658+0000 ModemManager[564]: <debug> [1574849047.600239] (ttyACM1): <-- '<CR><LF>+CGDCONT: 1,"IP","phone","0.0.0.0",0,0<CR><LF>+CGDCONT: 2,"IP","vodafone","0.0.0.0",0,0<CR><LF>+CGDCONT: 3,"IP","proxy.trimble.com","0.0.0.0",0,0<CR><LF>+CGDCONT: 4,"IP","internet.telecom.co.nz","0.0.0.0",0,0<CR><LF>+CGDCONT: 5,"IP","internet","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>' 2019-11-27T10:04:07.604002+0000 ModemManager[564]: <debug> [1574849047.603648] Found '5' PDP contexts 2019-11-27T10:04:07.604407+0000 ModemManager[564]: <debug> [1574849047.604087] PDP context [cid=1] [type='ipv4'] [apn='phone'] 2019-11-27T10:04:07.604796+0000 ModemManager[564]: <debug> [1574849047.604485] PDP context [cid=2] [type='ipv4'] [apn='vodafone'] 2019-11-27T10:04:07.605184+0000 ModemManager[564]: <debug> [1574849047.604874] PDP context [cid=3] [type='ipv4'] [apn='proxy.trimble.com'] 2019-11-27T10:04:07.616058+0000 ModemManager[564]: <debug> [1574849047.605258] PDP context [cid=4] [type='ipv4'] [apn='internet.telecom.co.nz'] 2019-11-27T10:04:07.616472+0000 ModemManager[564]: <debug> [1574849047.616150] PDP context [cid=5] [type='ipv4'] [apn='internet'] 2019-11-27T10:04:07.616908+0000 ModemManager[564]: <debug> [1574849047.616596] Found PDP context with CID 4 and PDP type ipv4 for APN 'internet.telecom.co.nz' 2019-11-27T10:04:07.619952+0000 ModemManager[564]: <debug> [1574849047.619595] No specific IP family requested, defaulting to ipv4 2019-11-27T10:04:07.620361+0000 ModemManager[564]: <debug> [1574849047.620045] cinterion dial step 1/4: authentication not required 2019-11-27T10:04:07.620746+0000 ModemManager[564]: <debug> [1574849047.620433] cinterion dial step 2/4: starting SWWAN interface 1 connection... 2019-11-27T10:04:07.621392+0000 ModemManager[564]: <debug> [1574849047.621077] (ttyACM1) device open count is 3 (open) 2019-11-27T10:04:07.622445+0000 ModemManager[564]: <debug> [1574849047.622093] (ttyACM1) device open count is 2 (close) 2019-11-27T10:04:07.623330+0000 ModemManager[564]: <debug> [1574849047.623003] (ttyACM1): --> 'AT^SWWAN=1,4,1<CR>' . . 10s later the API times out waiting for the "Connect" to finish. I can't tell what it is stuck on. I looked at the code and it looks like the AT command didn't finish ? Is that right ? Is there any other reason why it could get stuck ? 2019-11-27T10:04:17.536659+0000 [601]: Call to g_dbus_connection_call_sync failed: Timeout was reached Just for reference this what a successful connection looks like (an hour later) 2019-11-27T11:03:47.120505+0000 ModemManager[554]: <debug> [1574852627.120170] Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0' 2019-11-27T11:03:47.121270+0000 ModemManager[554]: <info> [1574852627.120947] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting) 2019-11-27T11:03:47.132753+0000 ModemManager[554]: <debug> [1574852627.132407] Launching 3GPP connection attempt with APN 'internet.telecom.co.nz' 2019-11-27T11:03:47.133182+0000 ModemManager[554]: <debug> [1574852627.132879] No specific IP family requested, defaulting to ipv4 2019-11-27T11:03:47.133706+0000 ModemManager[554]: <debug> [1574852627.133396] No specific IP family requested, defaulting to ipv4 2019-11-27T11:03:47.134188+0000 ModemManager[554]: <debug> [1574852627.133898] Looking for best CID... 2019-11-27T11:03:47.134777+0000 ModemManager[554]: <debug> [1574852627.134470] (ttyACM1) device open count is 3 (open) 2019-11-27T11:03:47.135980+0000 ModemManager[554]: <debug> [1574852627.135659] (ttyACM1): --> 'AT+CIND?<CR>' 2019-11-27T11:03:47.176263+0000 ModemManager[554]: <debug> [1574852627.175926] (ttyACM1): <-- '<CR><LF>+CIND: 0,2,1,0,0,1,1,0<CR><LF><CR><LF>OK<CR><LF>' 2019-11-27T11:03:47.183885+0000 ModemManager[554]: <debug> [1574852627.183533] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (40) 2019-11-27T11:03:47.187303+0000 ModemManager[554]: <debug> [1574852627.186826] (ttyACM1) device open count is 2 (close) 2019-11-27T11:03:47.196734+0000 ModemManager[554]: <debug> [1574852627.196383] Polling to refresh access technologies is unsupported 2019-11-27T11:03:47.197541+0000 ModemManager[554]: <debug> [1574852627.197215] Periodic signal quality checks scheduled in 30s 2019-11-27T11:03:47.198380+0000 ModemManager[554]: <debug> [1574852627.198064] (ttyACM1): --> 'AT+CGDCONT?<CR>' 2019-11-27T11:03:47.252391+0000 ModemManager[554]: <debug> [1574852627.252031] (ttyACM1): <-- '<CR><LF>+CGDCONT: 1,"IP","phone","0.0.0.0",0,0<CR><LF>+CGDCONT: 2,"IP","vodafone","0.0.0.0",0,0<CR><LF>+CGDCONT: 3,"IP","proxy.trimble.com","0.0.0' 2019-11-27T11:03:47.257792+0000 ModemManager[554]: <debug> [1574852627.257421] (ttyACM1): <-- '.0",0,0<CR><LF>+CGDCONT: 4,"IP","internet.telecom.co.nz","0.0.0.0",0,0<CR><LF>+CGDCONT: 5,"IP","internet","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>' 2019-11-27T11:03:47.265031+0000 ModemManager[554]: <debug> [1574852627.264697] Found '5' PDP contexts 2019-11-27T11:03:47.267489+0000 ModemManager[554]: <debug> [1574852627.267152] PDP context [cid=1] [type='ipv4'] [apn='phone'] 2019-11-27T11:03:47.267880+0000 ModemManager[554]: <debug> [1574852627.267569] PDP context [cid=2] [type='ipv4'] [apn='vodafone'] 2019-11-27T11:03:47.268262+0000 ModemManager[554]: <debug> [1574852627.267957] PDP context [cid=3] [type='ipv4'] [apn='proxy.trimble.com'] 2019-11-27T11:03:47.268654+0000 ModemManager[554]: <debug> [1574852627.268345] PDP context [cid=4] [type='ipv4'] [apn='internet.telecom.co.nz'] 2019-11-27T11:03:47.269034+0000 ModemManager[554]: <debug> [1574852627.268731] PDP context [cid=5] [type='ipv4'] [apn='internet'] 2019-11-27T11:03:47.269458+0000 ModemManager[554]: <debug> [1574852627.269153] Found PDP context with CID 4 and PDP type ipv4 for APN 'internet.telecom.co.nz' 2019-11-27T11:03:47.270347+0000 ModemManager[554]: <debug> [1574852627.270022] No specific IP family requested, defaulting to ipv4 2019-11-27T11:03:47.271909+0000 ModemManager[554]: <debug> [1574852627.270438] cinterion dial step 1/4: authentication not required 2019-11-27T11:03:47.272321+0000 ModemManager[554]: <debug> [1574852627.271997] cinterion dial step 2/4: starting SWWAN interface 1 connection... 2019-11-27T11:03:47.272974+0000 ModemManager[554]: <debug> [1574852627.272658] (ttyACM1) device open count is 3 (open) 2019-11-27T11:03:47.274968+0000 ModemManager[554]: <debug> [1574852627.274642] (ttyACM1) device open count is 2 (close) 2019-11-27T11:03:47.275845+0000 ModemManager[554]: <debug> [1574852627.275529] (ttyACM1): --> 'AT^SWWAN=1,4,1<CR>' 2019-11-27T11:03:50.403263+0000 ModemManager[554]: <debug> [1574852630.402921] (ttyACM1): <-- '<CR><LF>OK<CR><LF><CR><LF>+CIEV: 3,1<CR><LF>' 2019-11-27T11:03:50.405126+0000 ModemManager[554]: <debug> [1574852630.404677] cinterion dial step 3/4: checking SWWAN interface 1 status... 2019-11-27T11:03:50.405949+0000 ModemManager[554]: <debug> [1574852630.405630] (ttyACM1) device open count is 3 (open) 2019-11-27T11:03:50.406805+0000 ModemManager[554]: <debug> [1574852630.406486] (ttyACM1) device open count is 2 (close) 2019-11-27T11:03:50.420198+0000 ModemManager[554]: <debug> [1574852630.419870] (ttyACM1): --> 'AT^SWWAN?<CR>' 2019-11-27T11:03:50.522235+0000 ModemManager[554]: <debug> [1574852630.521809] (ttyACM1): <-- '<CR><LF>^SWWAN: 4,1,1<CR><LF><CR><LF>OK<CR><LF>' 2019-11-27T11:03:50.524333+0000 ModemManager[554]: <debug> [1574852630.523993] cinterion dial step 4/4: finished 2019-11-27T11:03:50.526092+0000 ModemManager[554]: <debug> [1574852630.525768] (usb0): port now connected 2019-11-27T11:03:50.526528+0000 ModemManager[554]: <debug> [1574852630.526216] Connected bearer '/org/freedesktop/ModemManager1/Bearer/0' 2019-11-27T11:03:50.583280+0000 ModemManager[554]: <info> [1574852630.582934] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected) Best Regards Girish _______________________________________________ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
