Cinterion: Call setup gets stuck.

[Aleksander Morgado]

Hey,

> 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
>

What you're seeing is just that your DBus call finished before the AT
command has replied.

10s of timeout for a connection attempt is extremely extremely low. A
good safe value would be up to 180s or something like that. If you
look at the code the SWWAN=1 command itself has a 90s timeout, the
extra timeout up to 180s in the Simple.Connect() operation would be to
handle the steps before the SWWAN=1, e.g. waiting to get registered
and such.

-- 
Aleksander
https://aleksander.es