After upgrading an EM160R-GL modem via QFireHose from firmware version
EM160RGLAUR02A07M4G to version EM160RGLAUR02A07M4G, almost all functions fail
with ‘Invalid transition’. The modem power state is listed as "power state:
low” via mmcli. On the former firmware version everything was working fine.
This is currently happening with modemmanager 1.18.8 using mbim via the
qmi_wwan driver on openwrt with linux 4.4.60 and libmbim 1.28.4
I tried manually enabling it (in case it was FCC locked) via mbimcli
--device-open-proxy --device="/dev/cdc-wdm0" --quectel-set-radio-state=on, but
this also had no effect.
What additional steps would I need to take to debug this?
Thanks
Log snippet from logread on openwrt with LOG_LEVEL set to debug:
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.095984]
[modem0] user request to connect modem
Mon Jun 12 22:56:55 2023 daemon.info [10700]: <info> [1686610615.096263]
[modem0] simple connect started...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096345]
[modem0] profile ID: unspecified
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096402]
[modem0] PIN: unspecified
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096447]
[modem0] operator ID: unspecified
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096492]
[modem0] allowed roaming: yes
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096537]
[modem0] APN:
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096580]
[modem0] APN type: unspecified
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096629]
[modem0] IP family: unspecified
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096712]
[modem0] allowed authentication: unspecified
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096806]
[modem0] user: unspecified
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096866]
[modem0] password: unspecified
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.096934]
[modem0] multiplex: unspecified
Mon Jun 12 22:56:55 2023 daemon.info [10700]: <info> [1686610615.096982]
[modem0] simple connect state (3/8): enable
Mon Jun 12 22:56:55 2023 daemon.info [10700]: <info> [1686610615.097158]
[modem0] state changed (disabled -> enabling)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.097834]
[modem0] skipping initialization: not first enabling
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.097907]
[modem0/ttyUSB2/at] device open count is 2 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.097957]
[modem0/ttyUSB3/at] opening serial port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.099048]
[modem0/ttyUSB3/at] setting up baudrate: 57600
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.099138]
[modem0/ttyUSB3/at] no flow control explicitly requested for device
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.099196]
[modem0/ttyUSB3/at] port attributes not fully set
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.099295]
[modem0/ttyUSB3/at] device open count is 1 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.099345]
[modem0/ttyUSB3/at] running init sequence...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.099459]
[modem0/ttyUSB0/qcdm] opening serial port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.100476]
[modem0/ttyUSB0/qcdm] device open count is 1 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.100563]
[modem0] flashing primary AT port before enabling...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.100721]
[modem0/ttyUSB3/at] --> 'ATE0<CR>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message...
<<<<<< RAW: <<<<<< length = 48 <<<<<< data =
03:00:00:00:30:00:00:00:1D:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message
(translated)... <<<<<< Header: <<<<<< length = 48 <<<<<< type =
command (0x00000003) <<<<<< transaction = 29 <<<<<< Fragment header: <<<<<<
total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid =
'radio-state' (0x00000003) <<<<<< type = 'query' (0x00000000)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.108400]
[modem0/ttyUSB3/at] <-- '<CR><LF>OK<CR><LF>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received
message... >>>>>> RAW: >>>>>> length = 56 >>>>>> data =
03:00:00:80:38:00:00:00:1D:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received message
(translated)... >>>>>> Header: >>>>>> length = 56 >>>>>> type =
command-done (0x80000003) >>>>>> transaction = 29 >>>>>> Fragment header:
>>>>>> total = 1 >>>>>> current = 0 >>>>>> Contents: >>>>>> status
error = 'None' (0x00000000) >>>>>> service = 'basic-connect'
(a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) >>>>>> cid = 'radio-state'
(0x00000003) >>>>>> Fields: >>>>>> HwRadioState = 'on' >>>>>> SwRadioState
= 'off'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.132795]
[modem0] updating power state: 'on'...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message...
<<<<<< RAW: <<<<<< length = 52 <<<<<< data =
03:00:00:00:34:00:00:00:1E:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message
(translated)... <<<<<< Header: <<<<<< length = 52 <<<<<< type =
command (0x00000003) <<<<<< transaction = 30 <<<<<< Fragment header: <<<<<<
total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid =
'radio-state' (0x00000003) <<<<<< type = 'set' (0x00000001) <<<<<< Fields:
<<<<<< RadioState = 'on'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received
message... >>>>>> RAW: >>>>>> length = 48 >>>>>> data =
03:00:00:80:30:00:00:00:1E:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received message
(translated)... >>>>>> Header: >>>>>> length = 48 >>>>>> type =
command-done (0x80000003) >>>>>> transaction = 30 >>>>>> Fragment header:
>>>>>> total = 1 >>>>>> current = 0 >>>>>> Contents: >>>>>> status
error = 'OperationNotAllowed' (0x0000001c) >>>>>> service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) >>>>>> cid =
'radio-state' (0x00000003)
Mon Jun 12 22:56:55 2023 daemon.warn [10700]: <warn> [1686610615.164856]
[modem0] OperationNotAllowed
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.164931]
[modem0] couldn't update power state: Invalid transition
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.165016]
[modem0] attempting fcc unlock...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.165232] [fcc
unlock dispatcher] Cannot run fcc unlock operation from
/etc/ModemManager/fcc-unlock.d/2c7c:0620: file doesn't exist
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.165357] [fcc
unlock dispatcher] Cannot run fcc unlock operation from
/usr/lib/ModemManager/fcc-unlock.d/2c7c:0620: file doesn't exist
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.165509]
[modem0] couldn't run FCC unlock: fcc unlock operation launch aborted: no valid
program found
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.165560]
[modem0] updating power state: 'on'...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message...
<<<<<< RAW: <<<<<< length = 52 <<<<<< data =
03:00:00:00:34:00:00:00:1F:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message
(translated)... <<<<<< Header: <<<<<< length = 52 <<<<<< type =
command (0x00000003) <<<<<< transaction = 31 <<<<<< Fragment header: <<<<<<
total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid =
'radio-state' (0x00000003) <<<<<< type = 'set' (0x00000001) <<<<<< Fields:
<<<<<< RadioState = 'on'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received
message... >>>>>> RAW: >>>>>> length = 48 >>>>>> data =
03:00:00:80:30:00:00:00:1F:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received message
(translated)... >>>>>> Header: >>>>>> length = 48 >>>>>> type =
command-done (0x80000003) >>>>>> transaction = 31 >>>>>> Fragment header:
>>>>>> total = 1 >>>>>> current = 0 >>>>>> Contents: >>>>>> status
error = 'OperationNotAllowed' (0x0000001c) >>>>>> service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) >>>>>> cid =
'radio-state' (0x00000003)
Mon Jun 12 22:56:55 2023 daemon.warn [10700]: <warn> [1686610615.196716]
[modem0] OperationNotAllowed
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.196776]
[modem0] couldn't update power state: Invalid transition
Mon Jun 12 22:56:55 2023 daemon.warn [10700]: <warn> [1686610615.196831]
[modem0] couldn't enable interface: 'Invalid transition'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.196876]
[modem0] running implicit disable after failed enable...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.196935]
[modem0] modem has voice capabilities, disabling the Voice interface...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.197011]
[modem0] disabling +CLIP calling line reporting in primary port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.197085]
[modem0/ttyUSB2/at] device open count is 3 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.197288]
[modem0/ttyUSB2/at] --> 'AT+CLIP=0<CR>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.209424]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.209605]
[modem0] disabling +CLIP calling line reporting in secondary port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.209683]
[modem0/ttyUSB3/at] device open count is 2 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.209765]
[modem0/ttyUSB2/at] device open count is 2 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.209850]
[modem0/ttyUSB3/at] --> 'AT+CLIP=0<CR>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.221910]
[modem0/ttyUSB3/at] <-- '<CR><LF>OK<CR><LF>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.222093]
[modem0] disabling +CRC extended format of incoming call indications in primary
port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.222177]
[modem0/ttyUSB2/at] device open count is 3 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.222260]
[modem0/ttyUSB3/at] device open count is 1 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.222347]
[modem0/ttyUSB2/at] --> 'AT+CRC=0<CR>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.233244]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.233457]
[modem0] disabling +CRC extended format of incoming call indications in
secondary port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.233536]
[modem0/ttyUSB3/at] device open count is 2 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.233616]
[modem0/ttyUSB2/at] device open count is 2 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.233706]
[modem0/ttyUSB3/at] --> 'AT+CRC=0<CR>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.244421]
[modem0/ttyUSB3/at] <-- '<CR><LF>OK<CR><LF>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.244592]
[modem0] disabling +CCWA call waiting indications in primary port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.244672]
[modem0/ttyUSB2/at] device open count is 3 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.244752]
[modem0/ttyUSB3/at] device open count is 1 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.244841]
[modem0/ttyUSB2/at] --> 'AT+CCWA=0<CR>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.255967]
[modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.256118]
[modem0] disabling +CCWA call waiting indications in secondary port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.256194]
[modem0/ttyUSB3/at] device open count is 2 (open)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.256273]
[modem0/ttyUSB2/at] device open count is 2 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.256371]
[modem0/ttyUSB3/at] --> 'AT+CCWA=0<CR>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.267694]
[modem0/ttyUSB3/at] <-- '<CR><LF>OK<CR><LF>'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.268014]
[modem0] removing voice unsolicited events handlers in ttyUSB2
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.268081]
[modem0] removing voice unsolicited events handlers in ttyUSB3
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.268177]
[modem0/ttyUSB3/at] device open count is 1 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.268268]
[modem0] modem has extended signal reporting capabilities, disabling the Signal
interface...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.268464]
[modem0] modem has time capabilities, disabling the Time interface...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.268558]
[modem0] modem has messaging capabilities, disabling the Messaging interface...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.268628]
[modem0] enabled notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message...
<<<<<< RAW: <<<<<< length = 52 <<<<<< data =
03:00:00:00:34:00:00:00:20:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message
(translated)... <<<<<< Header: <<<<<< length = 52 <<<<<< type =
command (0x00000003) <<<<<< transaction = 32 <<<<<< Fragment header: <<<<<<
total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid =
'device-service-subscribe-list' (0x00000013) <<<<<< type = 'set'
(0x00000001) <<<<<< Fields: <<<<<< EventsCount = '0' <<<<<< Events = '{
<<<<<< }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received
message... >>>>>> RAW: >>>>>> length = 52 >>>>>> data =
03:00:00:80:34:00:00:00:20:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received message
(translated)... >>>>>> Header: >>>>>> length = 52 >>>>>> type =
command-done (0x80000003) >>>>>> transaction = 32 >>>>>> Fragment header:
>>>>>> total = 1 >>>>>> current = 0 >>>>>> Contents: >>>>>> status
error = 'None' (0x00000000) >>>>>> service = 'basic-connect'
(a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) >>>>>> cid =
'device-service-subscribe-list' (0x00000013) >>>>>> Fields: >>>>>>
EventsCount = '0' >>>>>> Events = '{ >>>>>> }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.269513]
[modem0] supported notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.269651]
[modem0] modem has location capabilities, disabling the Location interface...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.269733]
[modem0] location '3gpp-lac-ci' gathering is already disabled...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.269783]
[modem0] location 'gps-raw' gathering is already disabled...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.269831]
[modem0] location 'gps-nmea' gathering is already disabled...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.269884]
[modem0] location 'agps-msa' gathering is already disabled...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.269932]
[modem0] location 'agps-msb' gathering is already disabled...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.270052]
[modem0] modem has 3GPP/USSD capabilities, disabling the Modem 3GPP/USSD
interface...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.270121]
[modem0] enabled notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message...
<<<<<< RAW: <<<<<< length = 52 <<<<<< data =
03:00:00:00:34:00:00:00:21:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message
(translated)... <<<<<< Header: <<<<<< length = 52 <<<<<< type =
command (0x00000003) <<<<<< transaction = 33 <<<<<< Fragment header: <<<<<<
total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid =
'device-service-subscribe-list' (0x00000013) <<<<<< type = 'set'
(0x00000001) <<<<<< Fields: <<<<<< EventsCount = '0' <<<<<< Events = '{
<<<<<< }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received
message... >>>>>> RAW: >>>>>> length = 52 >>>>>> data =
03:00:00:80:34:00:00:00:21:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received message
(translated)... >>>>>> Header: >>>>>> length = 52 >>>>>> type =
command-done (0x80000003) >>>>>> transaction = 33 >>>>>> Fragment header:
>>>>>> total = 1 >>>>>> current = 0 >>>>>> Contents: >>>>>> status
error = 'None' (0x00000000) >>>>>> service = 'basic-connect'
(a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) >>>>>> cid =
'device-service-subscribe-list' (0x00000013) >>>>>> Fields: >>>>>>
EventsCount = '0' >>>>>> Events = '{ >>>>>> }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.270938]
[modem0] supported notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.271073]
[modem0] modem has 3GPP profile management capabilities, disabling the Modem
3GPP Profile Manager interface...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.271139]
[modem0] enabled notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message...
<<<<<< RAW: <<<<<< length = 52 <<<<<< data =
03:00:00:00:34:00:00:00:22:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message
(translated)... <<<<<< Header: <<<<<< length = 52 <<<<<< type =
command (0x00000003) <<<<<< transaction = 34 <<<<<< Fragment header: <<<<<<
total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid =
'device-service-subscribe-list' (0x00000013) <<<<<< type = 'set'
(0x00000001) <<<<<< Fields: <<<<<< EventsCount = '0' <<<<<< Events = '{
<<<<<< }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received
message... >>>>>> RAW: >>>>>> length = 52 >>>>>> data =
03:00:00:80:34:00:00:00:22:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received message
(translated)... >>>>>> Header: >>>>>> length = 52 >>>>>> type =
command-done (0x80000003) >>>>>> transaction = 34 >>>>>> Fragment header:
>>>>>> total = 1 >>>>>> current = 0 >>>>>> Contents: >>>>>> status
error = 'None' (0x00000000) >>>>>> service = 'basic-connect'
(a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) >>>>>> cid =
'device-service-subscribe-list' (0x00000013) >>>>>> Fields: >>>>>>
EventsCount = '0' >>>>>> Events = '{ >>>>>> }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.271911]
[modem0] supported notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.272031]
[modem0] modem has 3GPP capabilities, disabling the Modem 3GPP interface...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.272116]
[modem0] enabled notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message...
<<<<<< RAW: <<<<<< length = 52 <<<<<< data =
03:00:00:00:34:00:00:00:23:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message
(translated)... <<<<<< Header: <<<<<< length = 52 <<<<<< type =
command (0x00000003) <<<<<< transaction = 35 <<<<<< Fragment header: <<<<<<
total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid =
'device-service-subscribe-list' (0x00000013) <<<<<< type = 'set'
(0x00000001) <<<<<< Fields: <<<<<< EventsCount = '0' <<<<<< Events = '{
<<<<<< }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received
message... >>>>>> RAW: >>>>>> length = 52 >>>>>> data =
03:00:00:80:34:00:00:00:23:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received message
(translated)... >>>>>> Header: >>>>>> length = 52 >>>>>> type =
command-done (0x80000003) >>>>>> transaction = 35 >>>>>> Fragment header:
>>>>>> total = 1 >>>>>> current = 0 >>>>>> Contents: >>>>>> status
error = 'None' (0x00000000) >>>>>> service = 'basic-connect'
(a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) >>>>>> cid =
'device-service-subscribe-list' (0x00000013) >>>>>> Fields: >>>>>>
EventsCount = '0' >>>>>> Events = '{ >>>>>> }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.272888]
[modem0] supported notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.273009]
[modem0] supported notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.273124]
[modem0] enabled notifications: signal (no), registration (no), sms (no),
connect (no), subscriber (no), packet (no), pco (no), ussd (no), lte attach
info (no), provisioned contexts (no), slot_info_status (no)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message...
<<<<<< RAW: <<<<<< length = 52 <<<<<< data =
03:00:00:00:34:00:00:00:24:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] sent message
(translated)... <<<<<< Header: <<<<<< length = 52 <<<<<< type =
command (0x00000003) <<<<<< transaction = 36 <<<<<< Fragment header: <<<<<<
total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service =
'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid =
'device-service-subscribe-list' (0x00000013) <<<<<< type = 'set'
(0x00000001) <<<<<< Fields: <<<<<< EventsCount = '0' <<<<<< Events = '{
<<<<<< }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received
message... >>>>>> RAW: >>>>>> length = 52 >>>>>> data =
03:00:00:80:34:00:00:00:24:00:00:00...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: [/dev/cdc-wdm0] received message
(translated)... >>>>>> Header: >>>>>> length = 52 >>>>>> type =
command-done (0x80000003) >>>>>> transaction = 36 >>>>>> Fragment header:
>>>>>> total = 1 >>>>>> current = 0 >>>>>> Contents: >>>>>> status
error = 'None' (0x00000000) >>>>>> service = 'basic-connect'
(a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) >>>>>> cid =
'device-service-subscribe-list' (0x00000013) >>>>>> Fields: >>>>>>
EventsCount = '0' >>>>>> Events = '{ >>>>>> }'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.273915]
[modem0] disabling the Modem interface...
Mon Jun 12 22:56:55 2023 daemon.info [10700]: <info> [1686610615.274271]
[modem0] state changed (enabling -> disabled)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.274766]
[modem0/ttyUSB2/at] device open count is 1 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.274829]
[modem0/ttyUSB3/at] device open count is 0 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.274883]
[modem0/ttyUSB3/at] closing serial port...
Mon Jun 12 22:56:55 2023 daemon.notice netifd: wwan (15881): error: couldn't
connect the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Retry:
Invalid transition'
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.276252]
[modem0/ttyUSB3/at] serial port closed
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.276330]
[modem0/ttyUSB0/qcdm] device open count is 0 (close)
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.276385]
[modem0/ttyUSB0/qcdm] closing serial port...
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.277878]
[modem0/ttyUSB0/qcdm] serial port closed
Mon Jun 12 22:56:55 2023 daemon.notice netifd: wwan (16013): stopping network
Mon Jun 12 22:56:55 2023 daemon.notice netifd: wwan (16013): couldn't load
bearer path: disconnecting anyway
Mon Jun 12 22:56:55 2023 daemon.debug [10700]: <debug> [1686610615.383600]
[modem0] user request to disconnect modem (all bearers)
Mon Jun 12 22:56:55 2023 daemon.notice netifd: Interface 'wwan' is now down
