1.19 Regression: Simple connect hangs on "wait to get packet service state attached"
There seems to be a race condition introduced in the recent changes related to the "packet service state" (commits 9746600a, 6761fc00). In some cases the "packet service state" is not updated when the modem moves from "registering" to e.g. "home" state. In this state mmcli
reports that the modem is registered but the "packet service state" remains "detached", until ModemManager is either restarted or the modem is at least disabled and enabled again (effectively initiating a full sync).
Trying to use simple connect in this state causes MM to hang forever in simple connect state (7/10): wait to get packet service state attached
, eventually resulting in:
error: couldn't connect the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Retry: Too much time waiting to get to a final packet service state'
It happens quite reliably for me when debug logging is disabled. Trying to enable full debug logging to a file seems to change the timing enough to (sadly) avoid the issue. I managed to grab the following (partial) debug log:
Click me
[2123]: <debug> [1660575286.450402] [modem0] running registration checks (CS: 'yes', PS: 'yes', EPS: 'yes', 5GS: 'no')
[2123]: <debug> [1660575286.450724] [qrtr://0] Sent message...
<<<<<< RAW:
<<<<<< length = 13
<<<<<< data = 01:0C:00:00:03:01:00:0E:00:4D:00:00:00
[2123]: <debug> [1660575286.450907] [qrtr://0] Sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 12
<<<<<< flags = 0x00
<<<<<< service = "nas"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 14
<<<<<< tlv_length = 0
<<<<<< message = "Get System Info" (0x004D)
[2123]: <debug> [1660575286.452749] [qrtr://0] Received message...
<<<<<< RAW:
<<<<<< length = 133
<<<<<< data = ...
[2123]: <debug> [1660575286.454251] [qrtr://0] Received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 132
<<<<<< flags = 0x00
<<<<<< service = "nas"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 14
<<<<<< tlv_length = 120
<<<<<< message = "Get System Info" (0x004D)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "GSM Service Status" (0x12)
<<<<<< length = 3
<<<<<< value = 00:00:00
<<<<<< translated = [ service_status = 'none' true_service_status = 'none' preferred_data_path = 'no' ]
<<<<<< TLV:
<<<<<< type = "WCDMA Service Status" (0x13)
<<<<<< length = 3
<<<<<< value = 00:00:00
<<<<<< translated = [ service_status = 'none' true_service_status = 'none' preferred_data_path = 'no' ]
<<<<<< TLV:
<<<<<< type = "LTE Service Status" (0x14)
<<<<<< le
[2123]: <debug> [1660575286.454647] [modem0] no NR5G service reported
[2123]: <debug> [1660575286.455052] [qrtr://0] Sent message...
<<<<<< RAW:
<<<<<< length = 13
<<<<<< data = 01:0C:00:00:2A:01:00:03:00:24:00:00:00
[2123]: <debug> [1660575286.455244] [qrtr://0] Sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 12
<<<<<< flags = 0x00
<<<<<< service = "dsd"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 3
<<<<<< tlv_length = 0
<<<<<< message = "Get System Status" (0x0024)
[2123]: <debug> [1660575286.457237] [qrtr://0] Received message...
<<<<<< RAW:
<<<<<< length = 248
<<<<<< data = ...
[2123]: <debug> [1660575286.458269] [qrtr://0] Received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 247
<<<<<< flags = 0x00
<<<<<< service = "dsd"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 3
<<<<<< tlv_length = 235
<<<<<< message = "Get System Status" (0x0024)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Available Systems" (0x10)
<<<<<< length = 17
<<<<<< value = 01:00:00:00:00:00:00:00:00:00:08:00:00:00:00:00:00
<<<<<< translated = { [0] = '[ technology = '3gpp' rat = 'unknown' so_mask = '3gpp-so-mask-lte-limited-srvc' ] '}
...
[2123]: <debug> [1660575286.458629] [modem0] initial 3GPP registration checks finished
[2123]: <debug> [1660575293.221521] [qrtr://0] Received message...
<<<<<< RAW:
<<<<<< length = 148
<<<<<< data = ...
[2123]: <debug> [1660575293.222929] [qrtr://0] Received generic indication (translated)...
<<<<<< QMUX:
<<<<<< length = 147
<<<<<< flags = 0x00
<<<<<< service = "nas"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "indication"
<<<<<< transaction = 7
<<<<<< tlv_length = 135
<<<<<< message = "System Info" (0x004E)
<<<<<< TLV:
<<<<<< type = "GSM Service Status" (0x12)
<<<<<< length = 3
<<<<<< value = 00:00:00
<<<<<< translated = [ service_status = 'none' true_service_status = 'none' preferred_data_path = 'no' ]
<<<<<< TLV:
<<<<<< type = "WCDMA Service Status" (0x13)
<<<<<< length = 3
<<<<<< value = 00:00:00
<<<<<< translated = [ service_status = 'none' true_service_status = 'none' preferred_data_path = 'no' ]
<<<<<< TLV:
<<<<<< type = "LTE Service Status" (0x14)
<<<<<< length = 3
<<<<<< value = 02:02:00
<<<<<< translated = [ service_status = 'available' true_service_status = 'available' preferre
[2123]: <debug> [1660575293.223809] [qrtr://0] Received message...
<<<<<< RAW:
<<<<<< length = 148
<<<<<< data = ...
[2123]: <debug> [1660575293.225221] [qrtr://0] Received generic indication (translated)...
<<<<<< QMUX:
<<<<<< length = 147
<<<<<< flags = 0x00
<<<<<< service = "nas"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "indication"
<<<<<< transaction = 8
<<<<<< tlv_length = 135
<<<<<< message = "System Info" (0x004E)
<<<<<< TLV:
<<<<<< type = "GSM Service Status" (0x12)
<<<<<< length = 3
<<<<<< value = 00:00:00
<<<<<< translated = [ service_status = 'none' true_service_status = 'none' preferred_data_path = 'no' ]
<<<<<< TLV:
<<<<<< type = "WCDMA Service Status" (0x13)
<<<<<< length = 3
<<<<<< value = 00:00:00
<<<<<< translated = [ service_status = 'none' true_service_status = 'none' preferred_data_path = 'no' ]
<<<<<< TLV:
<<<<<< type = "LTE Service Status" (0x14)
<<<<<< length = 3
<<<<<< value = 02:02:00
<<<<<< translated = [ service_status = 'available' true_service_status = 'available' preferre
[2123]: <debug> [1660575293.225783] [modem0] no NR5G service reported
[2123]: <info> [1660575293.225984] [modem0] 3GPP registration state changed (unknown -> registering)
[2123]: <debug> [1660575293.226166] [modem0] fallback PS registration state to idle: DSD data RAT unavailable
[2123]: <debug> [1660575293.226555] [modem0] access technology changed (unknown -> lte)
[2123]: <debug> [1660575293.226737] [modem0] 3GPP tracking area code updated: '000000->...'
[2123]: <debug> [1660575293.226846] [modem0] 3GPP cell id updated: '00000000->...'
[2123]: <debug> [1660575293.226958] [modem0] 3GPP location updated (...)
[2123]: <debug> [1660575293.227183] [modem0] no NR5G service reported
[2123]: <debug> [1660575293.227324] [modem0] fallback PS registration state to idle: DSD data RAT unavailable
[2123]: <debug> [1660575293.227873] [modem0] 3GPP location updated (...)
...
[2123]: <debug> [1660575293.235379] [qrtr://0] Received message...
<<<<<< RAW:
<<<<<< length = 241
<<<<<< data = ...
[2123]: <debug> [1660575293.236429] [qrtr://0] Received generic indication (translated)...
<<<<<< QMUX:
<<<<<< length = 240
<<<<<< flags = 0x00
<<<<<< service = "dsd"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "indication"
<<<<<< transaction = 1
<<<<<< tlv_length = 228
<<<<<< message = "System Status" (0x0026)
<<<<<< TLV:
<<<<<< type = "Available Systems" (0x10)
<<<<<< length = 17
<<<<<< value = 01:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
<<<<<< translated = { [0] = '[ technology = '3gpp' rat = 'unknown' so_mask = '(null)' ] '}
...
[2123]: <debug> [1660575293.236732] [modem0] current operator long name: ...
[2123]: <debug> [1660575293.236844] [modem0] current operator short name: ...
[2123]: <debug> [1660575293.237016] [modem0] current operator service name: (null)
[2123]: <info> [1660575293.237371] [modem0] 3GPP registration state changed (registering -> home)
[2123]: <debug> [1660575293.237491] [modem0] consolidated registration state: cs 'home', ps 'idle', eps 'idle', 5gs 'unknown' --> 'home'
[2123]: <debug> [1660575293.237890] [modem0] will start keeping track of state for subsystem '3gpp'
[2123]: <info> [1660575293.238043] [modem0] state changed (enabled -> registered)
[2123]: <debug> [1660575293.238442] [modem0] network timezone polling started
[2123]: <debug> [1660575293.239734] [modem0] periodic signal checks enabled
[2123]: <debug> [1660575293.239895] [modem0] periodic signal check refresh requested
[2123]: <debug> [1660575293.240046] [modem0] loading signal quality...
...
[2123]: <debug> [1660575293.242057] [modem0] fallback PS registration state to idle: DSD data RAT unavailable
...
[2123]: <debug> [1660575293.244336] [modem0] RSSI (LTE): -51 dBm
[2123]: <debug> [1660575293.244450] [modem0] RSSI: -51 dBm --> 100%
[2123]: <debug> [1660575293.244983] [modem0] signal quality updated (100)
[2123]: <debug> [1660575293.245174] [modem0] periodic signal quality and access technology checks scheduled
[2123]: <debug> [1660575293.251451] [qrtr://0] Received message...
<<<<<< RAW:
<<<<<< length = 36
<<<<<< data = ...
[2123]: <debug> [1660575293.251988] [qrtr://0] Received generic indication (translated)...
<<<<<< QMUX:
<<<<<< length = 35
<<<<<< flags = 0x00
<<<<<< service = "wds"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "indication"
<<<<<< transaction = 1
<<<<<< tlv_length = 23
<<<<<< message = "Event Report" (0x0001)
<<<<<< TLV:
<<<<<< type = "Data Systems" (0x24)
<<<<<< length = 20
<<<<<< value = 00:02:00:20:00:00:00:00:00:00:00:01:00:00:00:00:00:00:00:00
<<<<<< translated = [ preferred_network_type = '3gpp' networks = '{ [0] = '[ network_type = '3gpp' rat_mask = '32' so_mask = '0' ] ' [1] = '[ network_type = '3gpp2' rat_mask = '0' so_mask = '0' ] '}' ]
[2123]: <debug> [1660575293.252354] [modem0] data systems update, preferred network: 3gpp
[2123]: <debug> [1660575293.252688] [qrtr://0] Sent message...
<<<<<< RAW:
<<<<<< length = 13
<<<<<< data = 01:0C:00:00:01:01:00:0A:00:85:00:00:00
[2123]: <debug> [1660575293.252932] [qrtr://0] Sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 12
<<<<<< flags = 0x00
<<<<<< service = "wds"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 10
<<<<<< tlv_length = 0
<<<<<< message = "Get LTE Attach Parameters" (0x0085)
[2123]: <debug> [1660575293.254876] [qrtr://0] Received message...
<<<<<< RAW:
<<<<<< length = 46
<<<<<< data = ...
[2123]: <debug> [1660575293.255439] [qrtr://0] Received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 45
<<<<<< flags = 0x00
<<<<<< service = "wds"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 10
<<<<<< tlv_length = 33
<<<<<< message = "Get LTE Attach Parameters" (0x0085)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "APN" (0x10)
<<<<<< length = 8
<<<<<< value = 69:6E:74:65:72:6E:65:74
<<<<<< translated = internet
<<<<<< TLV:
<<<<<< type = "IP Support Type" (0x11)
<<<<<< length = 1
<<<<<< value = 02
<<<<<< translated = ipv4v6
<<<<<< TLV:
<<<<<< type = "OTA Attach Performed" (0x12)
<<<<<< length = 1
<<<<<< value = 01
<<<<<< translated = yes
...
[2123]: <debug> [1660575293.255916] [modem0] updating initial EPS bearer...
[2123]: <debug> [1660575293.259436] [qrtr://0] Received message...
<<<<<< RAW:
<<<<<< length = 308
<<<<<< data = ...
[2123]: <debug> [1660575293.260647] [qrtr://0] Received generic indication (translated)...
<<<<<< QMUX:
<<<<<< length = 307
<<<<<< flags = 0x00
<<<<<< service = "dsd"
<<<<<< client = 1
<<<<<< QMI:
<<<<<< flags = "indication"
<<<<<< transaction = 2
<<<<<< tlv_length = 295
<<<<<< message = "System Status" (0x0026)
<<<<<< TLV:
<<<<<< type = "Available Systems" (0x10)
<<<<<< length = 17
<<<<<< value = 01:00:00:00:00:03:00:00:00:00:10:00:00:00:00:00:00
<<<<<< translated = { [0] = '[ technology = '3gpp' rat = '3gpp-lte' so_mask = '3gpp-so-mask-lte-fdd' ] '}
...
[2123]: <debug> [1660575293.261575] [modem0] updating PS registration state: DSD data RAT available
From what I can tell the following is happening:
-
MM_IFACE_MODEM_3GPP_PACKET_SERVICE_STATE
is only set fromupdate_registration_reload_current_registration_info_ready()
(mm-iface-modem-3gpp) -
update_registration_reload_current_registration_info_ready()
is only called when the modem moves fromregistering
toregistered
/home
state (see3GPP registration state changed (registering -> home)
in the log) - The DSD indication did not come in yet at this point so it's still using the
fallback PS registration state to idle: DSD data RAT unavailable
- When the DSD indication comes in (end of log),
updating PS registration state: DSD data RAT available
is printed but it does not actually update theMM_IFACE_MODEM_3GPP_PACKET_SERVICE_STATE
.update_registration_state()
is called but probably just returns because the modem is already inregistered
state.
(Testing with qcom-soc plugin on MSM8909)