On 1/12/22 9:58 AM, Aleksander Morgado wrote:
Hey,
I'm not sure there's an easy way to do that; but in this case we may
also be interested in the QMI messages really, because we also want to
make sure the port probing is working as expected; i.e. if this issue
happens not only upon MM start, also when you power cycle the modem,
it could be that the port probing of the QMI port is not completing
successfully, so even if the ports are reported to MM, they're not
used as MM couldn't verify it's a valid QMI port.
Here we go. I may have to increase the ring buffer size; the top is
the earliest I was able to grab.
Some of the AT commands are coming from an external application using
mmcli; i wonder if that's confouding MM.
Wed Jan 12 14:50:08 2022 daemon.debug [2670]: <debug> [1641999008.905414]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:08 2022 daemon.debug [2670]: <debug> [1641999008.905722]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:08 2022 daemon.debug [2670]: <debug> [1641999008.906044]
[modem0/ttyUSB2/at] --> 'AT+CLCK="PP",2<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.044547]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.045268]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.045577]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.045887]
[modem0/ttyUSB2/at] --> 'AT+CLCK="PC",2<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.184502]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.185363]
[modem0] loading IMEI...
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.185597]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.185935]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.186344]
[modem0] loaded IMEI: 001119000013505
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.186606]
[modem0] loading UE mode of operation for EPS...
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.186806]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.187086]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.187382]
[modem0/ttyUSB2/at] --> 'AT+CEMODE?<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.291833]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CEMODE: 2<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.296783]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.297253]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.299541]
[modem0/ttyUSB2/at] device open count is 1 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.303960]
[modem0/ttyUSB2/at] device open count is 2 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.304451]
[modem0/ttyUSB2/at] --> 'AT+QGPS=?<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.393243]
[modem0/ttyUSB2/at] <-- '<CR><LF>+QGPS:
(1-4),(1-255),(1-3),(100-65535)<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.393933]
[modem0] (quectel) GPS management with +QGPS is supported
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.399827]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.400289]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.400607]
[modem0/ttyUSB2/at] --> 'AT+CNMI=?<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.490668]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CNMI:
(0-2),(0-3),(0,2),(0-2),(0,1)<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.491404]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.491690]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.491954]
[modem0/ttyUSB2/at] --> 'AT+CPMS=?<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.580850]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CPMS:
("ME","MT","SM","SR"),("ME","MT","SM","SR"),("ME","MT","SM","SR")<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.583725]
[modem0] supported storages loaded:
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.583885]
[modem0] mem1 (list/read/delete) storages: 'me, mt, sm, sr'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.583993]
[modem0] mem2 (write/send) storages: 'me, mt, sm, sr'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.584100]
[modem0] mem3 (reception) storages: 'me, mt, sm, sr'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.584559]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.584853]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.585143]
[modem0/ttyUSB2/at] --> 'AT+CPMS?<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.660979]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CPMS:
"ME",0,127,"ME",0,127,"ME",0,127<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.661826]
[modem0] current storages initialized:
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.661969]
[modem0] mem1 (list/read/delete) storages: 'me'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.662094]
[modem0] mem2 (write/send) storages: 'me'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.662226]
[modem0] current storages initialized
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.664799]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.665199]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.665498]
[modem0/ttyUSB2/at] --> 'AT+CTZU=?<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.750667]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CTZU: (0,1)<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.751384]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.751654]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.751916]
[modem0/ttyUSB2/at] --> 'AT+CTZU=1<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.841040]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.841567]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.841812]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.842070]
[modem0/ttyUSB2/at] --> 'AT+CCLK?<CR>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.920845]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CCLK:
"22/01/12,15:08:32-20"<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.922630]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.923005]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:09 2022 daemon.debug [2670]: <debug> [1641999009.923287]
[modem0/ttyUSB2/at] --> 'AT+CESQ=?<CR>'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.010633]
[modem0/ttyUSB2/at] <-- '<CR><LF>ERROR<CR><LF>'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.011066]
[modem0/ttyUSB2/at] operation failure: 100 (Unknown error)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.011275]
[modem0] extended signal support check failed: Unknown error
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.011439]
[modem0] couldn't initialize interface: 'Extended Signal information not supported'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.013177]
[modem0/ttyUSB2/at] device open count is 1 (close)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.013491]
[modem0] couldn't initialize interface: 'OMA not supported'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.017120]
[modem0/ttyUSB2/at] device open count is 2 (open)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.017618]
[modem0/ttyUSB2/at] --> 'ATH<CR>'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.050618]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.051206]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.051450]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.051706]
[modem0/ttyUSB2/at] --> 'AT+CLCC=?<CR>'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.140698]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.141569]
[modem0] periodic call list polling will be used if supported
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.142783]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.143121]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.143404]
[modem0/ttyUSB2/at] --> 'AT+QFASTBOOT=?<CR>'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.283064]
[modem0/ttyUSB2/at] <-- '<CR><LF>ERROR<CR><LF>'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.283524]
[modem0/ttyUSB2/at] operation failure: 100 (Unknown error)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.288969]
[modem0] creating ports context for SIM hot swap
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.289183]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:10 2022 daemon.info [2670]: <info> [1641999010.289971]
[modem0] state changed (unknown -> disabled)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.290611]
[modem0] modem initialized
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.300337]
[device /sys/devices/platform/1e1c0000.xhci/usb2/2-1] exported modem at path
'/org/freedesktop/ModemManager1/Modem/0'
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.300608]
[device /sys/devices/platform/1e1c0000.xhci/usb2/2-1] plugin: quectel
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.300786]
[device /sys/devices/platform/1e1c0000.xhci/usb2/2-1] vid:pid: 0x2C7C:0x0512
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.301201]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:10 2022 daemon.debug [2670]: <debug> [1641999010.301562]
[modem0/ttyUSB2/at] device open count is 1 (close)
Wed Jan 12 14:50:11 2022 user.notice ModemManager: hotplug: modem exported
successfully at /sys/devices/platform/1e1c0000.xhci/usb2/2-1
Wed Jan 12 14:50:11 2022 user.notice ModemManager: hotplug: setting interface
'wwan' as available
Wed Jan 12 14:50:11 2022 daemon.notice netifd: Interface 'wwan' is setting up
now
Wed Jan 12 14:50:11 2022 daemon.notice netifd: wwan (4960): modem available at
/org/freedesktop/ModemManager1/Modem/0
Wed Jan 12 14:50:11 2022 daemon.notice netifd: wwan (4960): starting connection
with apn 'firstnet-broadband'...
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.616275]
[modem0] user request to connect modem
Wed Jan 12 14:50:11 2022 daemon.info [2670]: <info> [1641999011.617097]
[modem0] simple connect started...
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.617233]
[modem0] profile ID: unspecified
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.617341]
[modem0] PIN: unspecified
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.617447]
[modem0] operator ID: unspecified
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.617558]
[modem0] allowed roaming: yes
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.617666]
[modem0] APN: firstnet-broadband
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.617774]
[modem0] APN type: unspecified
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.617888]
[modem0] IP family: ipv4v6
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.618004]
[modem0] allowed authentication: unspecified
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.618118]
[modem0] user: unspecified
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.618223]
[modem0] password: unspecified
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.618332]
[modem0] multiplex: unspecified
Wed Jan 12 14:50:11 2022 daemon.info [2670]: <info> [1641999011.618439]
[modem0] simple connect state (3/8): enable
Wed Jan 12 14:50:11 2022 daemon.info [2670]: <info> [1641999011.619017]
[modem0] state changed (disabled -> enabling)
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.620911]
[modem0] skipping initialization: device hotplugged
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.621154]
[modem0/ttyUSB2/at] device open count is 2 (open)
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.621273]
[modem0] flashing primary AT port before enabling...
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.621757]
[modem0] loading power state...
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.621991]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.622413]
[modem0/ttyUSB2/at] --> 'AT+CFUN?<CR>'
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.700679]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CFUN: 1<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.701469]
[modem0] no need to change power state: already 'on'
Wed Jan 12 14:50:11 2022 daemon.info [2670]: <info> [1641999011.701600]
[modem0] power state updated: on
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.701847]
[modem0] checking if SIM was swapped...
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.702018]
[modem0/sim0] loading SIM identifier...
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.702207]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.702524]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.702805]
[modem0/ttyUSB2/at] --> 'AT+CRSM=176,12258,0,0,10<CR>'
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.940975]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CRSM:
144,0,"98100140030092884575"<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.942000]
[modem0/sim0] loaded SIM identifier: 89011004300029885457
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.942348]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.942715]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:11 2022 daemon.debug [2670]: <debug> [1641999011.943045]
[modem0/ttyUSB2/at] --> 'AT+IFC=?<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.020589]
[modem0/ttyUSB2/at] <-- '<CR><LF>+IFC: (0-2),(0-2)<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.021417]
[modem0] TE supports no flow control
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.021570]
[modem0] TE supports XON/XOFF flow control
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.021730]
[modem0] TE supports RTS/CTS flow control
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.021926]
[modem0] TA supports no flow control
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.022066]
[modem0] TA supports XON/XOFF flow control
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.022219]
[modem0] TA supports RTS/CTS flow control
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.022473]
[modem0] flow control settings automatically selected: rts-cts
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.022722]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.023046]
[modem0] modem has 3GPP capabilities, enabling the Modem 3GPP interface...
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.023292]
[modem0] checking indicator support...
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.023491]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.023957]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.024415]
[modem0/ttyUSB2/at] --> 'AT+IFC=2,2<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.111036]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.111797]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.112264]
[modem0/ttyUSB2/at] --> 'AT+CIND=?<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.200752]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CIND:
("battchg",(0-5)),("signal",(0-5)),("service",(0-1)),("call",(0-1)),("roam",(0-1)),("smsfull",(0-1)),("GPRS
coverage",(0-1)),("callsetup",(0-3))<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.201985]
[modem0] signal quality indications via CIND are supported at index '2' (min: 0,
max: 5)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.202152]
[modem0] roaming indications via CIND are supported at index '5'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.202314]
[modem0] service indications via CIND are supported at index '3'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.202649]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.202943]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.203276]
[modem0/ttyUSB2/at] --> 'AT+CMER=?<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.290028]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CMER:
(0-3),(0),(0),(0,1),(0,1)<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.291317]
[modem0] supported +CMER modes: discard-urcs, discard-urcs-if-link-reserved,
buffer-urcs-if-link-reserved, forward-urcs
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.291626]
[modem0] supported +CMER indication settings: disable, enable-not-caused-by-cind
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.291867]
[modem0] +CMER enable mode: forward-urcs
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.292028]
[modem0] +CMER disable mode: discard-urcs
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.292191]
[modem0] +CMER indication setting: enable-not-caused-by-cind
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.292366]
[modem0] checking packet domain event reporting...
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.292684]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.293043]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.293574]
[modem0/ttyUSB2/at] --> 'AT+CGEREP=?<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.400722]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CGEREP: (0-2),(0,1)<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.401382]
[modem0] packet domain event reporting is supported
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.401606]
[modem0] setting 3GPP +CIEV unsolicited events handlers in ttyUSB2
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.401783]
[modem0] setting 3GPP +CGEV unsolicited events handlers in ttyUSB2
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.402019]
[modem0] enabling +CIND event reporting in primary port...
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.402215]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.402511]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.402775]
[modem0/ttyUSB2/at] --> 'AT+CMER=3,0,0,1<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.551250]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.552079]
[modem0] enabling +CGEV event reporting in primary port...
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.552417]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.552787]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.553218]
[modem0/ttyUSB2/at] --> 'AT+CGEREP=2<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.633749]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.640772]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.643278]
[modem0] setting up 3GPP unsolicited registration messages handlers in ttyUSB2
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.643753]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.644179]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.644479]
[modem0/ttyUSB2/at] --> 'AT+QGPSCFG=autogps,1<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.842945]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CME ERROR: 501<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.843449]
[modem0/ttyUSB2/at] operation failure: 501 (GNSS - Invalid parameter)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.844410]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.844773]
[modem0/ttyUSB2/at] --> 'AT+CREG=2<CR>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.930700]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.931439]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.931731]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:12 2022 daemon.debug [2670]: <debug> [1641999012.932000]
[modem0/ttyUSB2/at] --> 'AT+CGREG=2<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.020850]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.021762]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.022232]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.022660]
[modem0/ttyUSB2/at] --> 'AT+CEREG=2<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.047590]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.110659]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.111302]
[modem0] modem has 3GPP profile management capabilities, enabling the Modem 3GPP
Profile Manager interface...
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.111623]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.111899]
[modem0] modem has 3GPP/USSD capabilities, enabling the Modem 3GPP/USSD interface...
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.112161]
[modem0] setting unsolicited result code handlers in ttyUSB2
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.112543]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.112832]
[modem0/ttyUSB2/at] --> 'AT+QGPS=1<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.207745]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.209029]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.209409]
[modem0/ttyUSB2/at] --> 'AT+CUSD=1<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.299578]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.300847]
[modem0] modem has location capabilities, enabling the Location interface...
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.301303]
[modem0] location 'gps-raw' gathering is already disabled...
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.301521]
[modem0] location 'gps-nmea' gathering is already disabled...
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.301739]
[modem0] location 'gps-unmanaged' gathering is already disabled...
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.301954]
[modem0] need to enable the following location sources: '3gpp-lac-ci'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.310078]
[modem0] running registration checks (CS: 'yes', PS: 'yes', EPS: 'yes', 5GS: 'no')
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.310553]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.311201]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.314498]
[modem0] modem has messaging capabilities, enabling the Messaging interface...
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.315793]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.316427]
[modem0/ttyUSB2/at] --> 'AT+CREG?<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.389738]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.390399]
[modem0] 3GPP registration state change ignored as modem isn't enabled
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.390969]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.391203]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.391495]
[modem0/ttyUSB2/at] --> 'AT+CMGF=?<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.479613]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CMGF: (0,1)<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.480570]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.480824]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.481137]
[modem0/ttyUSB2/at] --> 'AT+CGREG?<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.569545]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CGREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.570262]
[modem0] 3GPP registration state change ignored as modem isn't enabled
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.570852]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.571091]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.571391]
[modem0/ttyUSB2/at] --> 'AT+CMGF=0<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.656569]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.657235]
[modem0] successfully set preferred SMS mode: 'PDU'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.657938]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.658404]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.660232]
[modem0/ttyUSB2/at] --> 'AT+CEREG?<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.690379]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.739507]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CEREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.740115]
[modem0] 3GPP registration state change ignored as modem isn't enabled
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.740767]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.741123]
[modem0/ttyUSB2/at] --> 'AT+CPMS="ME","MT","MT"<CR>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.962244]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CPMS: 0,127,0,127,0,127<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.962864]
[modem0] listing SMS parts in storage 'me'
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.963026]
[modem0] locking SMS storages to: mem1 (ME), mem2 (none)...
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.963233]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.963491]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:13 2022 daemon.debug [2670]: <debug> [1641999013.963768]
[modem0/ttyUSB2/at] --> 'AT+CPIN?<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.039510]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CPIN: READY<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.040741]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.041902]
[modem0/ttyUSB2/at] --> 'AT+CPMS="ME"<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.160024]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CPMS: 0,127,0,127,0,127<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.161054]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.161572]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.161999]
[modem0/ttyUSB2/at] --> 'AT+CMGL=4<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.239995]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.241191]
[modem0] listing SMS parts in storage 'sm'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.241488]
[modem0] locking SMS storages to: mem1 (SM), mem2 (none)...
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.241802]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.242259]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.242705]
[modem0/ttyUSB2/at] --> 'AT+CPMS="SM"<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.245847]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.354983]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CPMS: 0,5,0,127,0,127<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.355700]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.355964]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.356239]
[modem0/ttyUSB2/at] --> 'AT+GSN<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.409610]
[modem0/ttyUSB2/at] <-- '<CR><LF>001119000013505<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.410992]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.412163]
[modem0/ttyUSB2/at] --> 'AT+CMGL=4<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.499728]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.500649]
[modem0] listing SMS parts in storage 'sr'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.500819]
[modem0] locking SMS storages to: mem1 (SR), mem2 (none)...
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.501032]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.501333]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.501603]
[modem0/ttyUSB2/at] --> 'AT+CPMS="SR"<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.612500]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CPMS:
0,0,0,127,0,127<CR><LF><CR><LF>OK<CR><LF><CR><LF>+CIEV: 5,1<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.613933]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.614757]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.615424]
[modem0/ttyUSB2/at] --> 'AT+CMGL=4<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.639793]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.689538]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.690470]
[modem0] setting messaging unsolicited events handlers in ttyUSB2
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.690784]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.691113]
[modem0] enabling messaging unsolicited events on primary port ttyUSB2
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.691311]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.691602]
[modem0/ttyUSB2/at] --> 'AT+QCCID<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.769532]
[modem0/ttyUSB2/at] <-- '<CR><LF>+QCCID:
89011004300029885457<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.770849]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.771346]
[modem0/ttyUSB2/at] --> 'AT+CNMI=2,1,2,1,0<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.940985]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.941637]
[modem0] messaging unsolicited events enabled on primary port ttyUSB2
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.941814]
[modem0] modem has time capabilities, enabling the Time interface...
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.942225]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.942506]
[modem0] modem has voice capabilities, enabling the Voice interface...
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.942995]
[modem0] setting voice unsolicited events handlers in ttyUSB2
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.943419]
[modem0] enabling +CLIP calling line reporting in primary port...
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.943642]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.944102]
[modem0/ttyUSB2/at] --> 'AT+CLIP=1<CR>'
Wed Jan 12 14:50:14 2022 daemon.debug [2670]: <debug> [1641999014.974978]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.019519]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.020079]
[modem0] enabling +CRC extended format of incoming call indications in primary
port...
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.020282]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.020498]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.020778]
[modem0/ttyUSB2/at] --> 'AT+CIMI<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.089543]
[modem0/ttyUSB2/at] <-- '<CR><LF>313100002988545<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.090872]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.091302]
[modem0/ttyUSB2/at] --> 'AT+CRC=1<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.169578]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.170282]
[modem0] enabling +CCWA call waiting indications in primary port...
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.170544]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.170840]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.171165]
[modem0/ttyUSB2/at] --> 'AT+CCWA=1<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.262568]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.info [2670]: <info> [1641999015.263299]
[modem0] simple connect state (4/8): wait to get fully enabled
Wed Jan 12 14:50:15 2022 daemon.info [2670]: <info> [1641999015.263668]
[modem0] state changed (enabling -> enabled)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.266642]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:15 2022 daemon.info [2670]: <info> [1641999015.267280]
[modem0] simple connect state (5/8): register
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.267815]
[modem0] launching automatic network registration...
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.268318]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.269469]
[modem0] running registration checks (CS: 'yes', PS: 'yes', EPS: 'yes', 5GS: 'no')
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.270060]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.270538]
[modem0/ttyUSB2/at] --> 'AT+COPS=0<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.298120]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.366187]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.366812]
[modem0] running registration checks (CS: 'yes', PS: 'yes', EPS: 'yes', 5GS: 'no')
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.367047]
[modem0/ttyUSB2/at] device open count is 6 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.367298]
[modem0/ttyUSB2/at] device open count is 5 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.367605]
[modem0/ttyUSB2/at] --> 'AT+CREG?<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.449499]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.info [2670]: <info> [1641999015.450222]
[modem0] 3GPP registration state changed (unknown -> registering)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.450432]
[modem0] loading Operator Code...
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.450615]
[modem0/ttyUSB2/at] device open count is 6 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.450867]
[modem0/ttyUSB2/at] device open count is 7 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.451344]
[modem0] access technology changed (unknown -> lte)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.451536]
[modem0] 3GPP tracking area code updated: '000000->005507'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.451650]
[modem0] 3GPP cell id updated: '00000000->0BE722D8'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.451769]
[modem0] 3GPP location updated (MCCMNC: '<none>', location area code: '0000',
tracking area code: '005507', cell ID: '0BE722D8')
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.452210]
[modem0/ttyUSB2/at] device open count is 8 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.452423]
[modem0/ttyUSB2/at] device open count is 7 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.453513]
[modem0/ttyUSB2/at] --> 'AT+CGMR<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.519584]
[modem0/ttyUSB2/at] <-- '<CR><LF>EM12AWPAR01A07M4G<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.521037]
[modem0/ttyUSB2/at] device open count is 6 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.522175]
[modem0/ttyUSB2/at] --> 'AT+CREG?<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.590822]
[modem0/ttyUSB2/at] <-- '<CR><LF>+QLWURC: "pdp
active","failed","firstnetbroadband"<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.591748]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.592735]
[modem0/ttyUSB2/at] device open count is 7 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.592985]
[modem0/ttyUSB2/at] device open count is 6 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.593285]
[modem0/ttyUSB2/at] --> 'AT+COPS=3,2<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.689911]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.690598]
[modem0/ttyUSB2/at] device open count is 5 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.691020]
[modem0/ttyUSB2/at] --> 'AT+COPS?<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.721423]
[modem0/ttyUSB2/at] device open count is 6 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.749491]
[modem0/ttyUSB2/at] <-- '<CR><LF>+COPS: 0,2,"313100",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.750524]
[modem0] couldn't convert operator string '313100' from charset 'UCS2': Invalid
conversion from UCS2 to UTF-8: Couldn't convert from UCS2 to UTF-8 with
translit: Could not open converter from “UCS-2BE” to “UTF-8”
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.750715]
[modem0] operator normalized '313100'->'313100'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.750878]
[modem0] loaded Operator Code: 313100
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.751356]
[modem0] 3GPP location updated (MCCMNC: '313100', location area code: '0000',
tracking area code: '005507', cell ID: '0BE722D8')
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.751523]
[modem0] loading Operator Name...
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.751760]
[modem0/ttyUSB2/at] device open count is 7 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.752063]
[modem0/ttyUSB2/at] device open count is 8 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.752323]
[modem0/ttyUSB2/at] device open count is 7 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.753435]
[modem0/ttyUSB2/at] --> 'AT+CGREG?<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.839467]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CGREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.840326]
[modem0] 3GPP location area code updated: '0000->5507'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.840477]
[modem0] 3GPP tracking area code cleared: '005507->000000'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.840652]
[modem0] 3GPP location updated (MCCMNC: '313100', location area code: '5507',
tracking area code: '000000', cell ID: '0BE722D8')
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.841229]
[modem0/ttyUSB2/at] device open count is 8 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.841507]
[modem0/ttyUSB2/at] device open count is 7 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.841864]
[modem0/ttyUSB2/at] --> 'AT+CGREG?<CR>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.929436]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CGREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.930407]
[modem0/ttyUSB2/at] device open count is 8 (open)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.930645]
[modem0/ttyUSB2/at] device open count is 7 (close)
Wed Jan 12 14:50:15 2022 daemon.debug [2670]: <debug> [1641999015.930942]
[modem0/ttyUSB2/at] --> 'AT+QCFG="band"<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.069687]
[modem0/ttyUSB2/at] <-- '<CR><LF>+QCFG:
"band",0x260,0x2000000003000281a,0x0<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.071007]
[modem0/ttyUSB2/at] device open count is 6 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.071437]
[modem0/ttyUSB2/at] --> 'AT+COPS=3,0<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.179819]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.180629]
[modem0/ttyUSB2/at] device open count is 5 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.181070]
[modem0/ttyUSB2/at] --> 'AT+COPS?<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.249879]
[modem0/ttyUSB2/at] <-- '<CR><LF>+COPS: 0,0,"FirstNet",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.250932]
[modem0] couldn't convert operator string 'FirstNet' from charset 'UCS2': Hex
byte conversion from 'Fi' failed
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.251157]
[modem0] operator normalized 'FirstNet'->'FirstNet'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.251320]
[modem0] loaded Operator Name: FirstNet
Wed Jan 12 14:50:16 2022 daemon.info [2670]: <info> [1641999016.251789]
[modem0] 3GPP registration state changed (registering -> home)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.251939]
[modem0] consolidated registration state: cs 'home', ps 'home', eps 'home', 5gs
'unknown' --> 'home'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.252485]
[modem0] will start keeping track of state for subsystem '3gpp'
Wed Jan 12 14:50:16 2022 daemon.info [2670]: <info> [1641999016.252709]
[modem0] state changed (enabled -> registered)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.253307]
[modem0] network timezone polling started
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.256161]
[modem0] periodic signal checks enabled
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.256497]
[modem0] periodic signal check refresh requested
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.256697]
[modem0] loading signal quality...
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.257042]
[modem0/ttyUSB2/at] device open count is 6 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.257569]
[modem0/ttyUSB2/at] device open count is 5 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.262863]
[modem0/ttyUSB2/at] --> 'AT+CEREG?<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.281030]
[modem0/ttyUSB2/at] device open count is 6 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.329512]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CEREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.330246]
[modem0] 3GPP tracking area code updated: '000000->005507'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.330398]
[modem0] 3GPP location area code cleared: '5507->0000'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.330578]
[modem0] 3GPP location updated (MCCMNC: '313100', location area code: '0000',
tracking area code: '005507', cell ID: '0BE722D8')
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.331115]
[modem0] initial 3GPP registration checks finished
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.331335]
[modem0/ttyUSB2/at] device open count is 5 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.331679]
[modem0/ttyUSB2/at] --> 'AT+CEREG?<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.419509]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CEREG:
2,1,"5507","BE722D8",7<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.420440]
[modem0] periodic signal check refresh ignored: check already running
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.420588]
[modem0] currently registered in a 3GPP network
Wed Jan 12 14:50:16 2022 daemon.info [2670]: <info> [1641999016.420798]
[modem0] simple connect state (6/8): bearer
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.420952]
[modem0] creating new bearer...
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.421218]
[modem0] creating broadband bearer in broadband modem...
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.436529]
[modem0/ttyUSB2/at] device open count is 6 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.437069]
[modem0/ttyUSB2/at] device open count is 5 (close)
Wed Jan 12 14:50:16 2022 daemon.info [2670]: <info> [1641999016.438846]
[modem0] simple connect state (7/8): connect
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.442000]
[modem0/bearer0] connecting...
Wed Jan 12 14:50:16 2022 daemon.info [2670]: <info> [1641999016.442377]
[modem0] state changed (registered -> connecting)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.444650]
[modem0/bearer0] launching 3GPP connection attempt
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.445020]
[modem0] set profile state (1/8): check format
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.445377]
[modem0/ttyUSB2/at] device open count is 6 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.445881]
[modem0/ttyUSB2/at] device open count is 5 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.447888]
[modem0/ttyUSB2/at] --> 'AT+CIND?<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.529577]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CIND: 0,5,1,1,0,1,1,0<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.530964]
[modem0] signal quality updated (100)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.531379]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.532517]
[modem0] polling to refresh access technologies is unsupported
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.533745]
[modem0] periodic signal quality and access technology checks scheduled
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.534175]
[modem0/ttyUSB2/at] --> 'AT+QTEMP<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.647867]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.649481]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.650764]
[modem0/ttyUSB2/at] <-- '<CR><LF>+QTEMP:
"xo_therm_buf","23"<CR><LF><CR><LF>+QTEMP:
"mdm_case_therm","23"<CR><LF><CR><LF>+QTEMP:
"pa_therm1","22"<CR><LF><CR><LF>+QTEMP:
"tsens_tz_sensor0","26"<CR><LF><CR><LF>+QTEMP:
"tsens_tz_sensor1","26"<CR><LF><CR><LF>+QTEMP:
"tsens_tz_sensor2","26"<CR><LF><CR><LF>+QTEMP:
"tsens_tz_sensor3","26"<CR><LF><CR><LF>+QTEMP: "tsens_tz_sensor4","26"<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.652957]
[modem0] unhandled PDP type in CGDCONT=? reply: 'PPP'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.653432]
[modem0] +CGDCONT format details for PDP type 'ipv4v6': minimum 1, maximum 42
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.653708]
[modem0] context definition format: minimum 1, maximum 42
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.653828]
[modem0] set profile state (2/8): list before
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.654105]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.654401]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.654727]
[modem0/ttyUSB2/at] --> 'AT+CGDCONT?<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.761059]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CGDCONT:
1,"IPV4V6","firstnet-broadband","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0<CR><LF>+CGDCONT:
16,"IP","firstnetbroadband","0.0.0.0",0,0,0,0<CR><LF>+CGDCONT:
2,"IPV4V6","ims","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0<CR><LF>+CGDCONT:
3,"IPV4V6","SOS","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,1<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.764328]
[modem0] set profile state (3/8): select profile (best)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.764880]
[modem0] found exact context at profile 1
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.765170]
[modem0] reusing profile '1'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.765432]
[modem0] set profile state (4/8): check activated profile
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.765859]
[modem0] checking if profile with id '1' is already activated...
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.766292]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.766910]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.767545]
[modem0/ttyUSB2/at] --> 'AT+CGACT?<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.849726]
[modem0/ttyUSB2/at] <-- '<CR><LF>+CGACT: 1,1<CR><LF>+CGACT: 16,0<CR><LF>+CGACT:
2,0<CR><LF>+CGACT: 3,0<CR><LF><CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.851120]
[modem0] profile '1' is activated
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.851356]
[modem0] set profile state (5/8): deactivate profile
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.851585]
[modem0] deactivating profile with id '1'...
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.851911]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.852345]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.853189]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.853540]
[modem0/ttyUSB2/at] --> 'AT+CGACT=0,1<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.969735]
[modem0/ttyUSB2/at] <-- '<CR><LF>ERROR<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.970307]
[modem0/ttyUSB2/at] operation failure: 100 (Unknown error)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.970555]
[modem0] couldn't deactivate profile with id '1': Unknown error
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.970671]
[modem0] set profile state (6/8): profile already stored
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.970779]
[modem0] set profile state (8/8): all done
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.970978]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.971088]
[modem0/bearer0] connection through a plain serial AT port: ttyUSB2
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.971292]
[modem0/ttyUSB2/at] device open count is 6 (open)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.971685]
[modem0/ttyUSB2/at] device open count is 5 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.971980]
[modem0/ttyUSB2/at] --> 'AT<CR>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.989507]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.990700]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:16 2022 daemon.debug [2670]: <debug> [1641999016.991241]
[modem0/ttyUSB2/at] --> 'ATD*99***1#<CR>'
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.103929]
[modem0/ttyUSB2/at] <-- '<CR><LF>CONNECT 150000000<CR><LF>'
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.105184]
[modem0/bearer0] setting flow control in ttyUSB2: rts-cts
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.105508]
[modem0/ttyUSB2/at] enabling RTS/CTS flow control
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.105655]
[modem0/ttyUSB2/at] port attributes not fully set
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.105776]
[modem0/ttyUSB2/at] flow control settings updated to rts-cts
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.106223]
[modem0/ttyUSB2/at] port now connected
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.106987]
[modem0/bearer0] connected
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.109636]
[modem0/bearer0] PPP is required for connection, will ignore disconnection reports
Wed Jan 12 14:50:17 2022 daemon.info [2670]: <info> [1641999017.110160]
[modem0] state changed (connecting -> connected)
Wed Jan 12 14:50:17 2022 daemon.info [2670]: <info> [1641999017.119730]
[modem0] simple connect state (8/8): all done
Wed Jan 12 14:50:17 2022 daemon.debug [2670]: <debug> [1641999017.121774]
[modem0/ttyUSB2/at] device open count is 3 (close)
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (4960): successfully
connected the modem
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (4960): signal refresh rate
is not set
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (4960): network operator
name: FirstNet
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (4960): network operator
MCCMNC: 313100
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (4960): registration type:
home
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (4960): access technology:
lte
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (4960): signal quality: 100%
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (5161): stopping network
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (5161): IPv4 connection
teardown required in interface wwan: ppp
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (5161): IPv6 connection
teardown required in interface wwan: ppp
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (5161): running
disconnection (ppp method)
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (5161): pppd result code not
given
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (5161): running
disconnection (common)
Wed Jan 12 14:50:17 2022 daemon.notice netifd: wwan (5161): Command failed:
Permission denied
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.093772]
[modem0] user request to disconnect modem (all bearers)
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.094330]
[modem0/bearer0] disconnecting...
Wed Jan 12 14:50:18 2022 daemon.info [2670]: <info> [1641999018.094588]
[modem0] state changed (connected -> disconnecting)
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.096886]
[modem0/bearer0] reopening data port ttyUSB2...
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.097173]
[modem0/ttyUSB2/at] reopening port (3)
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.097328]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.097490]
[modem0/ttyUSB2/at] device open count is 1 (close)
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.097664]
[modem0/ttyUSB2/at] device open count is 0 (close)
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.097845]
[modem0/ttyUSB2/at] closing serial port...
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.098038]
[modem0/ttyUSB2/at] port now disconnected
Wed Jan 12 14:50:18 2022 daemon.debug [2670]: <debug> [1641999018.099014]
[modem0/ttyUSB2/at] serial port closed
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.108635]
[modem0/ttyUSB2/at] opening serial port...
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.109415]
[modem0/ttyUSB2/at] setting up baudrate: 57600
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.109563]
[modem0/ttyUSB2/at] no flow control explicitly requested for device
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.109694]
[modem0/ttyUSB2/at] port attributes not fully set
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.109950]
[modem0/ttyUSB2/at] device open count is 1 (open)
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.110072]
[modem0/ttyUSB2/at] device open count is 2 (open)
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.110180]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.110388]
[modem0/bearer0] flashing data port ttyUSB2...
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.110739]
[modem0/ttyUSB2/at] device open count is 2 (close)
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.110859]
[modem0/ttyUSB2/at] running init sequence...
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.111167]
[modem0/bearer0] sending PDP context deactivation in primary/data port...
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.111335]
[modem0/ttyUSB2/at] device open count is 3 (open)
Wed Jan 12 14:50:19 2022 daemon.debug [2670]: <debug> [1641999019.111631]
[modem0/ttyUSB2/at] --> 'ATE0<CR>'
Wed Jan 12 14:50:21 2022 daemon.debug [2670]: <debug> [1641999021.398795]
[modem0/ttyUSB2/at] device open count is 4 (open)
Wed Jan 12 14:50:22 2022 authpriv.info dropbear[5214]: Child connection from
192.168.113.254:35818
Wed Jan 12 14:50:22 2022 daemon.debug [2670]: <debug> [1641999022.399108]
[modem0/ttyUSB2/at] --> 'ATV1<CR>'
Wed Jan 12 14:50:22 2022 daemon.notice netifd: Interface 'wwan' is now down
Wed Jan 12 14:50:22 2022 daemon.notice netifd: Interface 'wwan' is setting up
now
Wed Jan 12 14:50:22 2022 authpriv.notice dropbear[5214]: Auth succeeded with
blank password for 'root' from 192.168.113.254:35818
Wed Jan 12 14:50:22 2022 daemon.debug [2670]: <debug> [1641999022.664913]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:22 2022 daemon.notice netifd: wwan (5223): modem available at
/org/freedesktop/ModemManager1/Modem/0
Wed Jan 12 14:50:22 2022 daemon.debug [2670]: <debug> [1641999022.960945]
[modem0] user request to disconnect modem (all bearers)
Wed Jan 12 14:50:23 2022 daemon.notice netifd: wwan (5223): starting connection
with apn 'firstnet-broadband'...
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.251778]
[modem0] user request to connect modem
Wed Jan 12 14:50:23 2022 daemon.info [2670]: <info> [1641999023.252417]
[modem0] simple connect started...
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.252557]
[modem0] profile ID: unspecified
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.252712]
[modem0] PIN: unspecified
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.252866]
[modem0] operator ID: unspecified
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.253020]
[modem0] allowed roaming: yes
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.253177]
[modem0] APN: firstnet-broadband
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.253334]
[modem0] APN type: unspecified
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.253498]
[modem0] IP family: ipv4v6
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.253657]
[modem0] allowed authentication: unspecified
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.253819]
[modem0] user: unspecified
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.253977]
[modem0] password: unspecified
Wed Jan 12 14:50:23 2022 daemon.debug [2670]: <debug> [1641999023.254131]
[modem0] multiplex: unspecified
Wed Jan 12 14:50:23 2022 daemon.info [2670]: <info> [1641999023.254282]
[modem0] simple connect state (4/8): wait to get fully enabled
Wed Jan 12 14:50:25 2022 daemon.warn [2670]: <warn> [1641999025.398906]
[modem0] port ttyUSB2 timed out 2 consecutive times
Wed Jan 12 14:50:25 2022 daemon.debug [2670]: <debug> [1641999025.399308]
[modem0/ttyUSB2/at] --> 'AT+CMEE=1<CR>'
Wed Jan 12 14:50:28 2022 daemon.warn [2670]: <warn> [1641999028.398897]
[modem0] port ttyUSB2 timed out 3 consecutive times
Wed Jan 12 14:50:28 2022 daemon.debug [2670]: <debug> [1641999028.399241]
[modem0/ttyUSB2/at] --> 'ATX4<CR>'
Wed Jan 12 14:50:31 2022 daemon.warn [2670]: <warn> [1641999031.398894]
[modem0] port ttyUSB2 timed out 4 consecutive times
Wed Jan 12 14:50:31 2022 daemon.debug [2670]: <debug> [1641999031.399295]
[modem0/ttyUSB2/at] --> 'AT&C1<CR>'
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5223): error: couldn't
connect the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Retry:
Too much time waiting to get to a final state'
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5362): stopping network
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5362): IPv4 connection
teardown required in interface wwan: ppp
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5362): IPv6 connection
teardown required in interface wwan: ppp
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5362): running
disconnection (ppp method)
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5362): pppd result code not
given
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5362): running
disconnection (common)
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5362): Command failed:
Permission denied
Wed Jan 12 14:50:33 2022 daemon.debug [2670]: <debug> [1641999033.924642]
[modem0] user request to disconnect modem (all bearers)
Wed Jan 12 14:50:33 2022 daemon.notice netifd: wwan (5362): error: couldn't
disconnect all bearers in the modem:
'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.InProgress: Bearer already
being disconnected'
Wed Jan 12 14:50:34 2022 daemon.warn [2670]: <warn> [1641999034.398739]
[modem0] port ttyUSB2 timed out 5 consecutive times
Wed Jan 12 14:50:34 2022 daemon.debug [2670]: <debug> [1641999034.399073]
[modem0/ttyUSB2/at] --> 'AT+CGACT=0,1<CR>'
Wed Jan 12 14:50:38 2022 daemon.notice netifd: Interface 'wwan' is now down
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.399693]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:44 2022 daemon.info [2670]: <info> [1641999044.399981]
[modem0] state changed (disconnecting -> unknown)
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.403042]
[modem0] signal quality updated (0)
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.403726]
[modem0] access technology changed (lte -> unknown)
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.403990]
[modem0] periodic signal checks disabled
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.404519]
[modem0/bearer0] PDP context deactivation failed (not fatal): Serial command
timed out
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.404856]
[modem0/bearer0] disconnected
Wed Jan 12 14:50:44 2022 daemon.info [2670]: <info> [1641999044.405236]
[modem0] state changed (unknown -> registered)
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.406127]
[modem0] network timezone polling started
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.409009]
[modem0] periodic signal checks enabled
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.409309]
[modem0] periodic signal check refresh requested
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.409548]
[modem0] loading signal quality...
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.409922]
[modem0/ttyUSB2/at] device open count is 5 (open)
Wed Jan 12 14:50:44 2022 daemon.info [2670]: <info> [1641999044.412744]
[modem0/bearer0] connection #1 finished: duration 27s, tx: 0 bytes, rx: 0 bytes
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.413935]
[modem0/ttyUSB2/at] device open count is 4 (close)
Wed Jan 12 14:50:44 2022 daemon.warn [2670]: <warn> [1641999044.414398]
[modem0] port ttyUSB2 timed out 6 consecutive times
Wed Jan 12 14:50:44 2022 daemon.debug [2670]: <debug> [1641999044.416680]
[modem0/ttyUSB2/at] --> 'AT+CCLK?<CR>'
