Cinterion: Call setup gets stuck.
Girish Mahadevan
girish_mahadevan at trimble.com
Thu Dec 12 00:56:49 UTC 2019
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
More information about the ModemManager-devel
mailing list