[Quectel EM160R-GL] Various commands over mbim fail with 'Invalid transition'
Alex Ballmer
alexb at meshplusplus.com
Mon Jun 12 23:43:11 UTC 2023
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
More information about the ModemManager-devel
mailing list