Cinterion: PLS8x: "Connection is Closed" error

Mon Mar 23 12:14:38 UTC 2020

Hi

We have a product that has the PLS8x module (uses the Cinterion plugin).
ModemManager version : 1.8.2
Kernel:  4.14.79

I'm running into an issue where one of the d-bus clients of
ModemManager keeps getting "The connection is closed" error in
response to its d-bus call to ModemManager.

Summary:
It looks like after the call setup is successful (bearer connects),
there is a long delay when an IP is actually assigned.
During this transitional period, meaning from the time the bearer is
connected to the time an IP is assigned there is a dbus call from
another client that is querying the "Status" property of the Modem
interface. It gets the
"The connection is closed" error in response to its
"g_dbus_connection_call_sync"

And this keeps on repeating, eventually the data connection is
established (Bearer connects + IP assigned), but this client's dbus
API calls keeps failing with the "The connection is closed" error.
Is this a known issue? Should clients wait on an event/signal before
trying to make dbus API calls to ModemManager ?

Thanks !
Girish

[Log attached]

Here is a detailed timeline of events:
================================================================
1. ModemManager tries to setup a call
Mar 20 22:56:54.988703 ModemManager[571]: <debug> Connecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:56:54.989466 ModemManager[571]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
connecting)
Mar 20 22:56:54.996564 ModemManager[571]: <debug> Launching 3GPP
connection attempt with APN 'vzwinternet'

2. The module that kicks off the ModemManager Connect checks if the
call goes through by querying on the "Connected" property of the
Bearer interface "/org/freedesktop/ModemManager1/Bearer/" and declared
that it is indeed connected:
Mar 20 22:56:58.143371 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:56:59.173461 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:00.198153 modem_monitor[629]: Bearer 0 is connected

3. But the network interface (usb0) doesn't have an IP address yet and
eventually times out
20 22:57:30.786010 systemd-networkd-wait-online[548]: Event loop
failed: Connection timed out
Mar 20 22:57:30.839678 systemd[1]:
systemd-networkd-wait-online.service: Main process exited,
code=exited, status=1/FAILURE
Mar 20 22:57:30.843667 systemd[1]:
systemd-networkd-wait-online.service: Failed with result 'exit-code'.

20 22:57:30.786010 systemd-networkd-wait-online[548]: Event loop
failed: Connection timed out
Mar 20 22:57:30.839678 systemd[1]:
systemd-networkd-wait-online.service: Main process exited,
code=exited, status=1/FAILURE
Mar 20 22:57:30.843667 systemd[1]:
systemd-networkd-wait-online.service: Failed with result 'exit-code'.

4. After this the modem sw tries to use an invalid PDP (VZW only wants
PDP 3), and fails, ignore that bit (needs to be cleaned up by us).

5. It tries again on:
Mar 20 22:57:51.569962 modem_monitor[629]: modem is registered, state: 8
Mar 20 22:57:51.609287 ModemManager[571]: <debug> Connecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:57:51.616285 ModemManager[571]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
connecting)
Mar

6. Same thing happens as before the bearer is connected, but the IP
isn't assigned yet
r 20 22:57:51.569962 modem_monitor[629]: modem is registered, state: 8
Mar 20 22:57:51.609287 ModemManager[571]: <debug> Connecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:57:51.616285 ModemManager[571]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
connecting)

7.But in the meantime, another dbus client comes and tries to query
the Modem's "State" property and keeps seeing:
Mar 20 22:57:52.524539 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:52.574063 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:52.833912 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:52.836872 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:53.600452 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:53.841917 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:53.844880 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed

8. Eventually the bearer is connected and an IP assigned
Mar 20 22:58:54.210560 systemd-networkd[542]: usb0: Gained carrier
Mar 20 22:58:54.274655 systemd-networkd[542]: usb0: DHCPv4 address
100.125.178.70/30 via 100.125.178.69

9. But the other client's modem status query keeps getting
Mar 20 22:58:57.830241 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:57.841098 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:58.844856 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:58.847828 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:59.851793 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:59.859782 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:00.869693 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:00.880951 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:01.886924 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:01.898343 vrsd.exe[737]: Call to
g_dbus_connection_call_sync failed: The connection is closed

===================================================================
-------------- next part --------------
Mar 20 22:56:54.988703 ModemManager[571]: <debug> Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:56:54.989466 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Mar 20 22:56:54.996564 ModemManager[571]: <debug> Launching 3GPP connection attempt with APN 'vzwinternet'
Mar 20 22:56:55.008941 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:56:55.013825 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:56:55.022318 ModemManager[571]: <debug> Looking for best CID...
Mar 20 22:56:55.025417 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:56:55.028332 ModemManager[571]: <debug> (ttyACM1): --> 'AT+CGDCONT?<CR>'
Mar 20 22:56:55.151002 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CGDCONT: 1,"IPV4V6","vzwims","0.0.0.0",0,0<CR><LF>+CGDCONT: 2,"IPV4V6","vzwadmin","0.0.0.0",0,0<CR><LF>+CGDCONT: 3,"IPV4V6","VZWINTERNET","0.0.0.0",0,0<CR><LF>+CGDCONT: 4,"IPV4V6","vzwapp","0.0.0.0",0,0<CR><LF>+CGDCONT: 5,"IP","vzwadmin","0.0.0.0",0,0<CR><LF>+CGDCONT: 6,"IP","proxy.trimble.com","0.0.0.0",0,0<CR><LF>+CGDCONT: 7,"IP","vzwinternet","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:56:55.159558 ModemManager[571]: <debug> Found '7' PDP contexts
Mar 20 22:56:55.162550 ModemManager[571]: <debug>   PDP context [cid=1] [type='ipv4v6'] [apn='vzwims']
Mar 20 22:56:55.165726 ModemManager[571]: <debug>   PDP context [cid=2] [type='ipv4v6'] [apn='vzwadmin']
Mar 20 22:56:55.167343 ModemManager[571]: <debug>   PDP context [cid=3] [type='ipv4v6'] [apn='VZWINTERNET']
Mar 20 22:56:55.167700 ModemManager[571]: <debug>   PDP context [cid=4] [type='ipv4v6'] [apn='vzwapp']
Mar 20 22:56:55.168050 ModemManager[571]: <debug>   PDP context [cid=5] [type='ipv4'] [apn='vzwadmin']
Mar 20 22:56:55.168399 ModemManager[571]: <debug>   PDP context [cid=6] [type='ipv4'] [apn='proxy.trimble.com']
Mar 20 22:56:55.168748 ModemManager[571]: <debug>   PDP context [cid=7] [type='ipv4'] [apn='vzwinternet']
Mar 20 22:56:55.169139 ModemManager[571]: <debug> Found PDP context with CID 7 and PDP type ipv4 for APN 'vzwinternet'
Mar 20 22:56:55.169994 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:56:55.170358 ModemManager[571]: <debug> cinterion dial step 1/4: authentication not required
Mar 20 22:56:55.170702 ModemManager[571]: <debug> cinterion dial step 2/4: starting SWWAN interface 1 connection...
Mar 20 22:56:55.171317 ModemManager[571]: <debug> (ttyACM1) device open count is 3 (open)
Mar 20 22:56:55.173323 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (close)
Mar 20 22:56:55.174202 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN=1,3,1<CR>'
Mar 20 22:56:55.516378 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>OK<CR><LF>'
Mar 20 22:56:55.544975 ModemManager[571]: <debug> cinterion dial step 3/4: checking SWWAN interface 1 status...
Mar 20 22:56:55.545754 ModemManager[571]: <debug> (ttyACM1) device open count is 3 (open)
Mar 20 22:56:55.546573 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (close)
Mar 20 22:56:55.574352 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN?<CR>'
Mar 20 22:56:55.658224 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>^SWWAN: 3,1,1<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:56:55.660395 ModemManager[571]: <debug> cinterion dial step 4/4: finished
Mar 20 22:56:55.671451 ModemManager[571]: <debug> (usb0): port now connected
Mar 20 22:56:55.671883 ModemManager[571]: <debug> Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:56:55.682765 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Mar 20 22:56:55.701584 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:56:57.108743 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:56:57.575633 ModemManager[571]: <debug> (ttyACM0): <-- '<CR><LF>+CIEV: 1,3<CR><LF>'
Mar 20 22:56:57.585133 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIEV: 1,3<CR><LF>'
Mar 20 22:56:57.617865 ModemManager[571]: <debug> loading signal quality...
Mar 20 22:56:57.618595 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:56:57.619633 ModemManager[571]: <debug> (ttyACM1): --> 'AT+CIND?<CR>'
Mar 20 22:56:57.648552 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIND: 0,3,1,1,0,0,1,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:56:57.651874 ModemManager[571]: <debug> Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (60)
Mar 20 22:56:57.652436 ModemManager[571]: <debug> Periodic signal quality checks scheduled in 30s
Mar 20 22:56:57.653047 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:56:58.143371 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:56:59.173461 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:00.198153 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:01.228948 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:02.253781 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:03.279000 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:04.307596 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:05.339374 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:06.371056 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:07.396503 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:08.422037 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:09.448710 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:10.479926 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:11.504439 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:12.529686 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:13.554231 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:14.579352 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:14.906634 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CGREG: 1,"0F02","4CEE716",7<CR><LF><CR><LF>+CEREG: 1,"0F02","4CEE716",7<CR><LF>'
Mar 20 22:57:15.614122 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:16.639386 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:17.664076 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:18.274530 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIEV: 1,2<CR><LF>'
Mar 20 22:57:18.276493 ModemManager[571]: <debug> (ttyACM0): <-- '<CR><LF>+CIEV: 1,2<CR><LF>'
Mar 20 22:57:18.689262 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:19.715427 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:20.741055 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:21.766457 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:22.793810 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:23.820216 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:24.851652 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:25.620664 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:57:25.625181 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN?<CR>'
Mar 20 22:57:25.648493 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>^SWWAN: 3,1,1<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:57:25.650645 ModemManager[571]: <warn>  checking if connected failed: No state returned for CID 7
Mar 20 22:57:25.651197 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:57:25.881986 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:26.907926 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:27.623952 ModemManager[571]: <debug> loading signal quality...
Mar 20 22:57:27.624687 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:57:27.625721 ModemManager[571]: <debug> (ttyACM1): --> 'AT+CIND?<CR>'
Mar 20 22:57:27.675335 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIND: 0,2,1,1,0,0,1,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:57:27.698830 ModemManager[571]: <debug> Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (40)
Mar 20 22:57:27.699321 ModemManager[571]: <debug> Periodic signal quality checks scheduled in 30s
Mar 20 22:57:27.699933 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:57:27.985172 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:29.010429 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:30.034522 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:30.786010 systemd-networkd-wait-online[548]: Event loop failed: Connection timed out
Mar 20 22:57:30.839678 systemd[1]: systemd-networkd-wait-online.service: Main process exited, code=exited, status=1/FAILURE
Mar 20 22:57:30.843667 systemd[1]: systemd-networkd-wait-online.service: Failed with result 'exit-code'.
Mar 20 22:57:31.063891 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:32.173589 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:31.344381 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:32.634754 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:33.690504 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:34.732248 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:35.764531 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:36.836383 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:37.914791 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:38.945058 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:39.969831 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:41.043349 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:41.048914 modem_monitor[629]: interface usb0 has no IPv4 address after waiting 45 seconds
Mar 20 22:57:41.065032 ModemManager[571]: <debug> Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:57:41.065775 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
Mar 20 22:57:41.083080 ModemManager[571]: <debug> cinterion disconnect step 1/3: disconnecting PDP CID 7...
Mar 20 22:57:41.085683 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:57:41.090757 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN=0,7,1<CR>'
Mar 20 22:57:41.129169 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CME ERROR: 256<CR><LF>'
Mar 20 22:57:41.133089 ModemManager[571]: <debug> Invalid mobile equipment error code: 256
Mar 20 22:57:41.135687 ModemManager[571]: <debug> Got failure code 100: Unknown error
Mar 20 22:57:41.138878 ModemManager[571]: <debug> cinterion disconnect step 2/3: checking SWWAN interface 1 status...
Mar 20 22:57:41.141812 ModemManager[571]: <debug> (ttyACM1) device open count is 3 (open)
Mar 20 22:57:41.144981 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (close)
Mar 20 22:57:41.148051 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN?<CR>'
Mar 20 22:57:41.180004 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>^SWWAN: 3,1,1<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:57:41.182172 ModemManager[571]: <debug> couldn't get CID 7 status, assume disconnected: No state returned for CID 7
Mar 20 22:57:41.182532 ModemManager[571]: <debug> cinterion disconnect step 3/3: finished
Mar 20 22:57:41.183317 ModemManager[571]: <debug> (usb0): port now disconnected
Mar 20 22:57:41.183733 ModemManager[571]: <debug> Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:57:41.184714 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> registered)
Mar 20 22:57:41.196690 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:57:42.466882 ModemManager[571]: <debug> (ttyACM0): <-- '<CR><LF>+CIEV: 3,0<CR><LF>'
Mar 20 22:57:42.469219 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIEV: 3,0<CR><LF>'
Mar 20 22:57:42.812837 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIEV: 3,1<CR><LF>'
Mar 20 22:57:42.814272 ModemManager[571]: <debug> (ttyACM0): <-- '<CR><LF>+CIEV: 3,1<CR><LF>'
Mar 20 22:57:44.385590 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIEV: 3,0<CR><LF>'
Mar 20 22:57:44.387019 ModemManager[571]: <debug> (ttyACM0): <-- '<CR><LF>+CIEV: 3,0<CR><LF>'
Mar 20 22:57:46.128869 modem_monitor[629]: Starting modem connect squence - attempt:9
Mar 20 22:57:51.364080 modem_monitor[629]: Modem index = 0
Mar 20 22:57:51.395369 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:51.410908 modem_monitor[629]: Pin State:uint32 1
Mar 20 22:57:51.464867 modem_monitor[629]: Modem 0 enabled
Mar 20 22:57:51.466889 modem_monitor[629]: Received APN:vzwinternet, User:(null), Password:(null), IpType:0, Pdp:0
Mar 20 22:57:51.504233 modem_monitor[629]: Found bearer:/org/freedesktop/ModemManager1/Bearer/0
Mar 20 22:57:51.504524 modem_monitor[629]: Using existing bearer:0
Mar 20 22:57:51.532758 modem_monitor[629]: checking for cell registration
Mar 20 22:57:51.569962 modem_monitor[629]: modem is registered, state: 8
Mar 20 22:57:51.609287 ModemManager[571]: <debug> Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:57:51.616285 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Mar 20 22:57:51.631274 ModemManager[571]: <debug> Launching 3GPP connection attempt with APN 'vzwinternet'
Mar 20 22:57:51.631671 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:57:51.632151 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:57:51.632589 ModemManager[571]: <debug> Looking for best CID...
Mar 20 22:57:51.633152 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:57:51.639798 ModemManager[571]: <debug> (ttyACM1): --> 'AT+CGDCONT?<CR>'
Mar 20 22:57:51.673599 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CGDCONT: 1,"IPV4V6","vzwims","0.0.0.0",0,0<CR><LF>+CGDCONT: 2,"IPV4V6","vzwadmin","0.0.0.0",0,0<CR><LF>+CGDCONT: 3,"IPV4V6","VZWINTERNET","0.0.0.0",0,0<CR><LF>+CGDCONT: 4,"IPV4V6","vzwapp","0.0.0.0",0,0<CR><LF>+CGDCONT: 6,"IP","proxy.trimble.com","0.0.0.0",0,0<CR><LF>+CGDCONT: 7,"IP","vzwinternet","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:57:51.677206 ModemManager[571]: <debug> Found '6' PDP contexts
Mar 20 22:57:51.677557 ModemManager[571]: <debug>   PDP context [cid=1] [type='ipv4v6'] [apn='vzwims']
Mar 20 22:57:51.677901 ModemManager[571]: <debug>   PDP context [cid=2] [type='ipv4v6'] [apn='vzwadmin']
Mar 20 22:57:51.678242 ModemManager[571]: <debug>   PDP context [cid=3] [type='ipv4v6'] [apn='VZWINTERNET']
Mar 20 22:57:51.689023 ModemManager[571]: <debug>   PDP context [cid=4] [type='ipv4v6'] [apn='vzwapp']
Mar 20 22:57:51.689399 ModemManager[571]: <debug>   PDP context [cid=6] [type='ipv4'] [apn='proxy.trimble.com']
Mar 20 22:57:51.689778 ModemManager[571]: <debug>   PDP context [cid=7] [type='ipv4'] [apn='vzwinternet']
Mar 20 22:57:51.690161 ModemManager[571]: <debug> Found PDP context with CID 7 and PDP type ipv4 for APN 'vzwinternet'
Mar 20 22:57:51.691011 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:57:51.691364 ModemManager[571]: <debug> cinterion dial step 1/4: authentication not required
Mar 20 22:57:51.691709 ModemManager[571]: <debug> cinterion dial step 2/4: starting SWWAN interface 1 connection...
Mar 20 22:57:51.692317 ModemManager[571]: <debug> (ttyACM1) device open count is 3 (open)
Mar 20 22:57:51.710397 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (close)
Mar 20 22:57:51.711272 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN=1,3,1<CR>'
Mar 20 22:57:51.818268 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>OK<CR><LF>'
Mar 20 22:57:51.850165 ModemManager[571]: <debug> cinterion dial step 3/4: checking SWWAN interface 1 status...
Mar 20 22:57:51.850944 ModemManager[571]: <debug> (ttyACM1) device open count is 3 (open)
Mar 20 22:57:51.851758 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (close)
Mar 20 22:57:51.852650 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN?<CR>'
Mar 20 22:57:51.910408 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>^SWWAN: 3,1,1<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:57:51.912569 ModemManager[571]: <debug> cinterion dial step 4/4: finished
Mar 20 22:57:51.913147 ModemManager[571]: <debug> (usb0): port now connected
Mar 20 22:57:51.913544 ModemManager[571]: <debug> Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:57:51.917835 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Mar 20 22:57:51.943151 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:57:52.524539 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:52.574063 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:52.833912 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:52.836872 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:53.600452 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:53.841917 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:53.844880 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:54.625474 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:54.848854 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:54.860140 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:55.651424 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:55.669539 ModemManager[571]: <debug> loading signal quality...
Mar 20 22:57:55.670260 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:57:55.671309 ModemManager[571]: <debug> (ttyACM1): --> 'AT+CIND?<CR>'
Mar 20 22:57:55.697579 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIND: 0,2,1,1,0,0,1,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:57:55.703328 ModemManager[571]: <debug> Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (40)
Mar 20 22:57:55.706557 ModemManager[571]: <debug> Periodic signal quality checks scheduled in 30s
Mar 20 22:57:55.709229 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:57:55.865972 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:55.877047 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:56.683416 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:56.882321 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:56.885289 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:57.714343 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:57.889538 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:57.900943 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:58.739939 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:58.906980 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:58.917659 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:59.771102 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:57:59.922526 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:57:59.925491 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:00.796275 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:00.929371 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:00.940491 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:01.822220 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:01.946353 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:01.957059 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:02.851355 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:02.962441 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:03.066386 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:03.073794 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:03.876090 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:04.079719 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:04.094211 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:04.901927 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:05.100431 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:05.113647 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:05.927055 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:06.119962 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:06.134007 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:06.952468 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:07.144193 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:07.151602 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:07.981422 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:08.155368 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:08.158421 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:09.048192 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:09.172127 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:09.175096 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:10.073994 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:10.179335 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:10.191290 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:11.099844 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:11.197072 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:11.208076 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:12.136685 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:12.212329 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:12.215290 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:13.165727 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:13.219164 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:13.323055 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:13.326009 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:14.197646 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:14.329900 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:14.340922 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:15.226940 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:15.346879 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:15.357648 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:16.257628 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:16.361908 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:16.364873 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:17.285437 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:17.369073 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:17.372043 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:18.310775 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:18.375737 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:18.386735 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:19.335498 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:19.396302 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:19.407219 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:20.362745 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:20.411066 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:20.421200 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:21.394082 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:21.424903 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:21.428049 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:21.671703 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:58:21.676206 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN?<CR>'
Mar 20 22:58:21.702144 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>^SWWAN: 3,1,1<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:58:21.704272 ModemManager[571]: <warn>  checking if connected failed: No state returned for CID 7
Mar 20 22:58:21.704803 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:58:22.420172 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:22.431863 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:22.434835 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:23.450940 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:23.463724 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:23.577887 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:23.582837 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:24.490147 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:24.586583 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:24.601633 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:25.522896 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:25.607960 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:25.618156 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:25.669281 ModemManager[571]: <debug> loading signal quality...
Mar 20 22:58:25.670000 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:58:25.671041 ModemManager[571]: <debug> (ttyACM1): --> 'AT+CIND?<CR>'
Mar 20 22:58:25.701747 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIND: 0,2,1,1,0,0,1,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:58:25.707302 ModemManager[571]: <debug> Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (40)
Mar 20 22:58:25.709150 ModemManager[571]: <debug> Periodic signal quality checks scheduled in 30s
Mar 20 22:58:25.709762 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:58:26.549531 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:26.625071 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:26.628011 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:27.580545 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:27.631818 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:27.634779 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:28.605422 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:28.638835 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:28.641778 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:29.631688 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:29.645532 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:29.656320 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:30.662490 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:30.665438 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:30.673052 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:31.669423 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:31.687606 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:31.710068 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:32.692803 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:32.695763 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:32.737439 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:33.710164 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:33.762794 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:33.822045 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:33.825105 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:34.789886 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:34.828999 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:34.841148 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:35.824080 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:35.847021 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:35.857747 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:36.856631 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:36.861985 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:36.864919 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:37.880781 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:37.894567 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:37.894843 modem_monitor[629]: interface usb0 has no IPv4 address after waiting 45 seconds
Mar 20 22:58:37.901457 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:37.922045 ModemManager[571]: <debug> Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:58:37.922777 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
Mar 20 22:58:37.941220 ModemManager[571]: <debug> cinterion disconnect step 1/3: disconnecting PDP CID 7...
Mar 20 22:58:37.943961 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:58:37.947589 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN=0,7,1<CR>'
Mar 20 22:58:38.004633 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CME ERROR: 256<CR><LF>'
Mar 20 22:58:38.006109 ModemManager[571]: <debug> Invalid mobile equipment error code: 256
Mar 20 22:58:38.006499 ModemManager[571]: <debug> Got failure code 100: Unknown error
Mar 20 22:58:38.007119 ModemManager[571]: <debug> cinterion disconnect step 2/3: checking SWWAN interface 1 status...
Mar 20 22:58:38.007896 ModemManager[571]: <debug> (ttyACM1) device open count is 3 (open)
Mar 20 22:58:38.028962 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (close)
Mar 20 22:58:38.029868 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN?<CR>'
Mar 20 22:58:38.052999 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>^SWWAN: 3,1,1<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:58:38.057473 ModemManager[571]: <debug> couldn't get CID 7 status, assume disconnected: No state returned for CID 7
Mar 20 22:58:38.059003 ModemManager[571]: <debug> cinterion disconnect step 3/3: finished
Mar 20 22:58:38.059710 ModemManager[571]: <debug> (usb0): port now disconnected
Mar 20 22:58:38.060137 ModemManager[571]: <debug> Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:58:38.060879 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> registered)
Mar 20 22:58:38.100272 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:58:38.927368 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:38.931743 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:39.383567 modem_monitor[629]: Starting modem connect squence - attempt:10
Mar 20 22:58:39.935453 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:39.938571 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:40.952322 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:40.955388 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:41.959312 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:41.970941 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:42.980424 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:43.031219 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:44.037987 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:44.151312 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:44.158985 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:44.470187 modem_monitor[629]: Modem index = 0
Mar 20 22:58:44.501506 modem_monitor[629]: Pin State:uint32 1
Mar 20 22:58:44.527562 modem_monitor[629]: Modem 0 enabled
Mar 20 22:58:44.534485 modem_monitor[629]: Received APN:vzwinternet, User:(null), Password:(null), IpType:0, Pdp:0
Mar 20 22:58:44.562018 modem_monitor[629]: Found bearer:/org/freedesktop/ModemManager1/Bearer/0
Mar 20 22:58:44.562305 modem_monitor[629]: Using existing bearer:0
Mar 20 22:58:44.591333 modem_monitor[629]: checking for cell registration
Mar 20 22:58:44.617317 modem_monitor[629]: modem is registered, state: 8
Mar 20 22:58:44.635571 ModemManager[571]: <debug> Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:58:44.636335 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Mar 20 22:58:44.657994 ModemManager[571]: <debug> Launching 3GPP connection attempt with APN 'vzwinternet'
Mar 20 22:58:44.659007 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:58:44.659503 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:58:44.659946 ModemManager[571]: <debug> Looking for best CID...
Mar 20 22:58:44.660515 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:58:44.667520 ModemManager[571]: <debug> (ttyACM1): --> 'AT+CGDCONT?<CR>'
Mar 20 22:58:44.703840 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CGDCONT: 1,"IPV4V6","vzwims","0.0.0.0",0,0<CR><LF>+CGDCONT: 2,"IPV4V6","vzwadmin","0.0.0.0",0,0<CR><LF>+CGDCONT: 3,"IPV4V6","VZWINTERNET","0.0.0.0",0,0<CR><LF>+CGDCONT: 4,"IPV4V6","vzwapp","0.0.0.0",0,0<CR><LF>+CGDCONT: 6,"IP","proxy.trimble.com","0.0.0.0",0,0<CR><LF>+CGDCONT: 7,"IP","vzwinternet","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:58:44.710600 ModemManager[571]: <debug> Found '6' PDP contexts
Mar 20 22:58:44.713397 ModemManager[571]: <debug>   PDP context [cid=1] [type='ipv4v6'] [apn='vzwims']
Mar 20 22:58:44.716002 ModemManager[571]: <debug>   PDP context [cid=2] [type='ipv4v6'] [apn='vzwadmin']
Mar 20 22:58:44.718856 ModemManager[571]: <debug>   PDP context [cid=3] [type='ipv4v6'] [apn='VZWINTERNET']
Mar 20 22:58:44.721554 ModemManager[571]: <debug>   PDP context [cid=4] [type='ipv4v6'] [apn='vzwapp']
Mar 20 22:58:44.724592 ModemManager[571]: <debug>   PDP context [cid=6] [type='ipv4'] [apn='proxy.trimble.com']
Mar 20 22:58:44.727315 ModemManager[571]: <debug>   PDP context [cid=7] [type='ipv4'] [apn='vzwinternet']
Mar 20 22:58:44.729029 ModemManager[571]: <debug> Found PDP context with CID 7 and PDP type ipv4 for APN 'vzwinternet'
Mar 20 22:58:44.729965 ModemManager[571]: <debug> No specific IP family requested, defaulting to ipv4
Mar 20 22:58:44.730524 ModemManager[571]: <debug> cinterion dial step 1/4: authentication not required
Mar 20 22:58:44.730876 ModemManager[571]: <debug> cinterion dial step 2/4: starting SWWAN interface 1 connection...
Mar 20 22:58:44.731497 ModemManager[571]: <debug> (ttyACM1) device open count is 3 (open)
Mar 20 22:58:44.732484 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (close)
Mar 20 22:58:44.733343 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN=1,3,1<CR>'
Mar 20 22:58:44.771630 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>OK<CR><LF>'
Mar 20 22:58:44.773129 ModemManager[571]: <debug> cinterion dial step 3/4: checking SWWAN interface 1 status...
Mar 20 22:58:44.773913 ModemManager[571]: <debug> (ttyACM1) device open count is 3 (open)
Mar 20 22:58:44.774729 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (close)
Mar 20 22:58:44.775632 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN?<CR>'
Mar 20 22:58:44.802574 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>^SWWAN: 3,1,1<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:58:44.806947 ModemManager[571]: <debug> cinterion dial step 4/4: finished
Mar 20 22:58:44.809215 ModemManager[571]: <debug> (usb0): port now connected
Mar 20 22:58:44.809617 ModemManager[571]: <debug> Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar 20 22:58:44.814175 ModemManager[571]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Mar 20 22:58:44.841024 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:58:45.199905 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:45.211170 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:45.791684 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:46.214880 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:46.217825 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:46.824806 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:47.221737 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:47.231143 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:47.849797 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:48.234847 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:48.237810 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:48.902312 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:49.242139 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:49.253782 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:49.956087 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:50.261154 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:50.273214 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:50.985006 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:51.277374 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:51.291205 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:52.071516 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:52.297373 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:52.311108 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:53.097467 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:53.317104 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:53.329283 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:54.124389 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:58:54.210560 systemd-networkd[542]: usb0: Gained carrier
Mar 20 22:58:54.274655 systemd-networkd[542]: usb0: DHCPv4 address 100.125.178.70/30 via 100.125.178.69
Mar 20 22:58:54.285394 dbus-daemon[518]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.2' (uid=995 pid=542 comm="/lib/systemd/systemd-networkd ")
Mar 20 22:58:54.335366 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:54.460963 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:54.774106 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:54.781106 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:55.127471 modem_monitor[629]: interface usb0 has IPv4 address: 100.125.178.70
Mar 20 22:58:55.127741 modem_monitor[629]: interface usb0 got IPv4 address after waiting 9 seconds
Mar 20 22:58:55.521428 ntpd[596]: Listen normally on 9 usb0 100.125.178.70:123
Mar 20 22:58:55.530680 ntpd[596]: unable to create socket on usb0 (10) for 2600:100e:b050:bf03:dcad:beff:feef:0#123
Mar 20 22:58:55.531876 ntpd[596]: Listen normally on 11 usb0 [fe80::dcad:beff:feef:0%8]:123
Mar 20 22:58:55.671010 ModemManager[571]: <debug> loading signal quality...
Mar 20 22:58:55.671744 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:58:55.672797 ModemManager[571]: <debug> (ttyACM1): --> 'AT+CIND?<CR>'
Mar 20 22:58:55.727070 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>+CIND: 0,2,1,1,0,0,1,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:58:55.750789 ModemManager[571]: <debug> Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (40)
Mar 20 22:58:55.753556 ModemManager[571]: <debug> Periodic signal quality checks scheduled in 30s
Mar 20 22:58:55.756417 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:58:55.784873 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:55.787926 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:56.281114 systemd-networkd[542]: usb0: Configured
Mar 20 22:58:56.802160 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:56.824124 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:57.502228 ntpd[596]: Listen normally on 12 usb0 [2600:100e:b050:bf03:dcad:beff:feef:0]:123
Mar 20 22:58:57.830241 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:57.841098 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:58.844856 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:58.847828 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:59.851793 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:58:59.859782 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:00.869693 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:00.880951 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:01.886924 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:01.898343 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:02.902358 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:02.905380 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:03.919843 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:03.933866 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:04.939950 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:05.054618 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:05.057593 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:06.071838 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:06.081121 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:07.091886 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:07.094857 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:08.118950 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:08.147115 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:09.152354 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:09.155408 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:10.151144 modem_monitor[629]: Bearer 0 is connected
Mar 20 22:59:10.153991 modem_monitor[629]: interface usb0 has IPv4 address: 100.125.178.70
Mar 20 22:59:10.161930 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:10.164859 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:11.168706 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:11.180278 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:12.186639 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:12.198002 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:13.202405 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:13.209097 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:14.212802 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:14.215760 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:14.675779 ModemManager[571]: <debug> (ttyACM1) device open count is 2 (open)
Mar 20 22:59:14.689570 ModemManager[571]: <debug> (ttyACM1): --> 'AT^SWWAN?<CR>'
Mar 20 22:59:14.715353 ModemManager[571]: <debug> (ttyACM1): <-- '<CR><LF>^SWWAN: 3,1,1<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 22:59:14.719935 ModemManager[571]: <warn>  checking if connected failed: No state returned for CID 7
Mar 20 22:59:14.723424 ModemManager[571]: <debug> (ttyACM1) device open count is 1 (close)
Mar 20 22:59:15.219756 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed
Mar 20 22:59:15.332099 vrsd.exe[737]: Call to g_dbus_connection_call_sync failed: The connection is closed