Hi,
We are getting following error when trying to send pin to the SIM card. The
problem is not observed in MM 1.20.4. However, please note that the SIM card
does unlocks after the below command even though error is reported.
# mmcli -i 0 --pin=1234
error: couldn't send PIN code to the SIM:
'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Failed: Couldn't get
interface skeleton'
Now, after looking through the code, following change is causing this issue.
This change was not present in 1.20.4
----
mm-broadband-modem-mbim.c:
if ((self->priv->enabled_cache.last_ready_state !=
MBIM_SUBSCRIBER_READY_STATE_DEVICE_LOCKED &&
ready_state == MBIM_SUBSCRIBER_READY_STATE_DEVICE_LOCKED) ||
(self->priv->enabled_cache.last_ready_state ==
MBIM_SUBSCRIBER_READY_STATE_DEVICE_LOCKED &&
ready_state != MBIM_SUBSCRIBER_READY_STATE_DEVICE_LOCKED)) {
mm_obj_dbg (self, "Lock state change detected");
active_sim_event = TRUE;
}
self->priv->enabled_cache.last_ready_state = ready_state;
if (active_sim_event) {
mm_iface_modem_process_sim_event (MM_IFACE_MODEM (self));
}
----
What is happening is when SIM PIN lock state changes then
mm_iface_modem_process_sim_event () is called which eventually calls
mm_base_modem_set_reprobe(). The reprobe, "unexports" the current modem
instance (modem 0) and recreates a new modem instance (1). As a result, the
above mmcli command is reporting error. I'm not sure why this should happen for
SIM Lock state change.
The logs are below. As you can see at timestamp 1713774618.140486, the modem
is unexported and then it's all cleanup and creation of new modem instance.
Please advise.
<dbg> [1713774617.896807] [modem0/sim0] sending PIN...
<dbg> [1713774617.896908] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 80
<<<<<< data = 03:00:00:00:50:00:00:00:17:00:00:00...
<dbg> [1713774617.897063] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 80
<<<<<< type = command (0x00000003)
<<<<<< transaction = 23
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'pin' (0x00000004)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< PinType = 'pin1'
<<<<<< PinOperation = 'enter'
<<<<<< Pin = '1234'
<<<<<< NewPin = '(NULL)'
<dbg> [1713774618.139714] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 144
>>>>>> data = 07:00:00:80:90:00:00:00:00:00:00:00...
<dbg> [1713774618.139908] [/dev/cdc-wdm0] received message (translated)...
>>>>>> Header:
>>>>>> length = 144
>>>>>> type = indicate-status (0x80000007)
>>>>>> transaction = 0
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'subscriber-ready-status' (0x00000002)
>>>>>> Fields:
>>>>>> ReadyState = 'not-initialized'
>>>>>> SubscriberId = '###'
>>>>>> SimIccId = '###'
>>>>>> ReadyInfo = 'none'
>>>>>> TelephoneNumbersCount = '0'
>>>>>> TelephoneNumbers = '###'
<dbg> [1713774618.139979] [modem0] received notification (service
'basic-connect', command 'subscriber-ready-status')
<dbg> [1713774618.140012] [modem0] processed subscriber ready status
notification
<dbg> [1713774618.140033] [modem0] Lock state change detected
<inf> [1713774618.140052] [modem0] Processing SIM event
<dbg> [1713774618.140486] [device
/sys/devices/platform/soc/soc:internal-regs/f10f0000.usb3/usb3/3-1] unexported
modem from path '/org/freedesktop/ModemManager1/Modem/0'
<dbg> [1713774618.140532] [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)
<dbg> [1713774618.140585] [cdc-wdm0/mbim] Releasing client for service 'uim'...
<dbg> [1713774618.140623] [/dev/cdc-wdm0] releasing 'uim' client with flags
'release-cid'...
<dbg> [1713774618.140657] [/dev/cdc-wdm0] unregistered 'uim' client with ID '2'
<dbg> [1713774618.140769] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 17
<<<<<< data = 01:10:00:00:00:00:00:07:23:00:05:00...
<dbg> [1713774618.140910] [/dev/cdc-wdm0] sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 16
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 7
<<<<<< tlv_length = 5
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 0B:02
<<<<<< translated = [ service = 'uim' cid = '2' ]
<dbg> [1713774618.140994] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 65
<<<<<< data = 03:00:00:00:41:00:00:00:15:00:00:00...
<dbg> [1713774618.141233] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 65
<<<<<< type = command (0x00000003)
<<<<<< transaction = 21
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'qmi' (d1a30bc2-f97a-6e43-bf65-c7e24fb0f0d3)
<<<<<< cid = 'msg' (0x00000001)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< QmiMsg = '01:10:00:00:00:00:00:07:23:00:05:00:01:02:00:0b:02'
<dbg> [1713774618.141459] [cdc-wdm0/mbim] Releasing client for service 'pdc'...
<dbg> [1713774618.141503] [/dev/cdc-wdm0] releasing 'pdc' client with flags
'release-cid'...
<dbg> [1713774618.141541] [/dev/cdc-wdm0] unregistered 'pdc' client with ID '1'
<dbg> [1713774618.141637] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 17
<<<<<< data = 01:10:00:00:00:00:00:08:23:00:05:00...
<dbg> [1713774618.141777] [/dev/cdc-wdm0] sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 16
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 8
<<<<<< tlv_length = 5
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 24:01
<<<<<< translated = [ service = 'pdc' cid = '1' ]
<dbg> [1713774618.141864] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 65
<<<<<< data = 03:00:00:00:41:00:00:00:16:00:00:00...
<dbg> [1713774618.142035] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 65
<<<<<< type = command (0x00000003)
<<<<<< transaction = 22
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'qmi' (d1a30bc2-f97a-6e43-bf65-c7e24fb0f0d3)
<<<<<< cid = 'msg' (0x00000001)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< QmiMsg = '01:10:00:00:00:00:00:08:23:00:05:00:01:02:00:24:01'
<dbg> [1713774618.142226] [cdc-wdm0/mbim] Releasing client for service 'loc'...
<dbg> [1713774618.142268] [/dev/cdc-wdm0] releasing 'loc' client with flags
'release-cid'...
<dbg> [1713774618.142304] [/dev/cdc-wdm0] unregistered 'loc' client with ID '1'
<dbg> [1713774618.142398] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 17
<<<<<< data = 01:10:00:00:00:00:00:09:23:00:05:00...
<dbg> [1713774618.142536] [/dev/cdc-wdm0] sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 16
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 9
<<<<<< tlv_length = 5
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 10:01
<<<<<< translated = [ service = 'loc' cid = '1' ]
<dbg> [1713774618.142608] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 65
<<<<<< data = 03:00:00:00:41:00:00:00:17:00:00:00...
<dbg> [1713774618.142778] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 65
<<<<<< type = command (0x00000003)
<<<<<< transaction = 23
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'qmi' (d1a30bc2-f97a-6e43-bf65-c7e24fb0f0d3)
<<<<<< cid = 'msg' (0x00000001)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< QmiMsg = '01:10:00:00:00:00:00:09:23:00:05:00:01:02:00:10:01'
<dbg> [1713774618.142941] [cdc-wdm0/mbim] Releasing client for service 'nas'...
<dbg> [1713774618.142981] [/dev/cdc-wdm0] releasing 'nas' client with flags
'release-cid'...
<dbg> [1713774618.143017] [/dev/cdc-wdm0] unregistered 'nas' client with ID '2'
<dbg> [1713774618.143120] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 17
<<<<<< data = 01:10:00:00:00:00:00:0A:23:00:05:00...
<dbg> [1713774618.143255] [/dev/cdc-wdm0] sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 16
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 10
<<<<<< tlv_length = 5
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 03:02
<<<<<< translated = [ service = 'nas' cid = '2' ]
<dbg> [1713774618.143329] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 65
<<<<<< data = 03:00:00:00:41:00:00:00:18:00:00:00...
<dbg> [1713774618.143500] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 65
<<<<<< type = command (0x00000003)
<<<<<< transaction = 24
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'qmi' (d1a30bc2-f97a-6e43-bf65-c7e24fb0f0d3)
<<<<<< cid = 'msg' (0x00000001)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< QmiMsg = '01:10:00:00:00:00:00:0a:23:00:05:00:01:02:00:03:02'
<dbg> [1713774618.143662] [cdc-wdm0/mbim] Releasing client for service 'dms'...
<dbg> [1713774618.143703] [/dev/cdc-wdm0] releasing 'dms' client with flags
'release-cid'...
<dbg> [1713774618.143739] [/dev/cdc-wdm0] unregistered 'dms' client with ID '1'
<dbg> [1713774618.143831] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 17
<<<<<< data = 01:10:00:00:00:00:00:0B:23:00:05:00...
<dbg> [1713774618.143975] [/dev/cdc-wdm0] sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 16
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 11
<<<<<< tlv_length = 5
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 02:01
<<<<<< translated = [ service = 'dms' cid = '1' ]
<dbg> [1713774618.144053] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 65
<<<<<< data = 03:00:00:00:41:00:00:00:19:00:00:00...
<dbg> [1713774618.144688] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 65
<<<<<< type = command (0x00000003)
<<<<<< transaction = 25
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'qmi' (d1a30bc2-f97a-6e43-bf65-c7e24fb0f0d3)
<<<<<< cid = 'msg' (0x00000001)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< QmiMsg = '01:10:00:00:00:00:00:0b:23:00:05:00:01:02:00:02:01'
<dbg> [1713774618.144932] [/dev/cdc-wdm0] closing device...
<dbg> [1713774618.144994] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 12
<<<<<< data = 02:00:00:00:0C:00:00:00:1A:00:00:00...
<dbg> [1713774618.145042] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 12
<<<<<< type = close (0x00000002)
<<<<<< transaction = 26
<dbg> [1713774618.145701] [modem0] cleaning up port 'unknown/ttyUSB0'...
<dbg> [1713774618.145742] [modem0] cleaning up port 'tty/ttyUSB1'...
<dbg> [1713774618.145767] [modem0] cleaning up port 'tty/ttyUSB2'...
<dbg> [1713774618.145794] [modem0] cleaning up port 'usbmisc/cdc-wdm0'...
<dbg> [1713774618.145842] [modem0] cleaning up port 'net/wwan0'...
<dbg> [1713774618.145883] [modem0/ttyUSB1/gps] forced to close port
<dbg> [1713774618.145982] [ttyUSB2/at] forced to close port
<dbg> [1713774618.146170] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 02:00:00:80:10:00:00:00:1A:00:00:00...
<dbg> [1713774618.146209] [/dev/cdc-wdm0] channel destroyed
<dbg> [1713774618.146453] [/dev/cdc-wdm0] closing device...
<dbg> [1713774618.146518] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 12
<<<<<< data = 02:00:00:00:0C:00:00:00:18:00:00:00...
<dbg> [1713774618.146567] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 12
<<<<<< type = close (0x00000002)
<<<<<< transaction = 24
<dbg> [1713774618.148503] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 02:00:00:80:10:00:00:00:18:00:00:00...
<dbg> [1713774618.148550] [/dev/cdc-wdm0] channel destroyed
<dbg> [1713774620.526412] [device
/sys/devices/platform/soc/soc:internal-regs/f10f0000.usb3/usb3/3-1] Reprobing
modem...
<msg> [1713774620.526462] [device
/sys/devices/platform/soc/soc:internal-regs/f10f0000.usb3/usb3/3-1] creating
modem with plugin 'sierra' and '5' ports
<dbg> [1713774620.526495] [plugin/sierra] (sierra) MBIM-powered Sierra modem
found...
<dbg> [1713774620.527187] [ttyUSB2/at] port monitoring enabled in AT port
<dbg> [1713774620.527379] [ttyUSB2/at] AT port flagged as primary
<dbg> [1713774620.527406] [modem1] port 'tty/ttyUSB2' grabbed
<dbg> [1713774620.527491] [modem1] port 'tty/ttyUSB1' grabbed
<dbg> [1713774620.527515] [plugin/sierra] port ttyUSB0 is explicitly ignored
<dbg> [1713774620.527569] [modem1] port 'tty/ttyUSB0' grabbed
<dbg> [1713774620.527618] [cdc-wdm0/mbim] port monitoring enabled in MBIM port
<dbg> [1713774620.527668] [modem1] port 'usbmisc/cdc-wdm0' grabbed
<dbg> [1713774620.527729] [modem1] port 'net/wwan0' grabbed
<inf> [1713774620.527759] [modem1] tty/ttyUSB2: at (primary)
<inf> [1713774620.527782] [modem1] tty/ttyUSB2: at (data primary)
<inf> [1713774620.527804] [modem1] net/wwan0: net (data)
<inf> [1713774620.527825] [modem1] tty/ttyUSB1: gps (nmea)
<inf> [1713774620.527846] [modem1] usbmisc/cdc-wdm0: mbim
<dbg> [1713774620.527879] [modem1] at data ports available but ignored
<dbg> [1713774620.528522] [modem1] not running data interface reset procedure:
device is hotplugged
<dbg> [1713774620.528714] [device
/sys/devices/platform/soc/soc:internal-regs/f10f0000.usb3/usb3/3-1] modem
recreated
<dbg> [1713774620.528857] [/dev/cdc-wdm0] opening device...
<dbg> [1713774620.529546] [/dev/cdc-wdm0] read max control message size from
descriptors file: 4096
<dbg> [1713774620.529696] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
---
Modem details:
root@AprisaLTE:/# mmcli -m 1
----------------------------------
General | path: /org/freedesktop/ModemManager1/Modem/1
| device id: efbe77ae4f80684040aa8189e7ce658a8f93cc1b
----------------------------------
Hardware | manufacturer: Sierra Wireless, Incorporated
| model: Sierra Wireless EM7565 Qualcomm®
Snapdragon⢠X16 LTE-A
| firmware revision: SWI9X50C_01.14.13.00
| carrier config: default
| h/w revision: EM7565
| supported: gsm-umts, lte
| current: gsm-umts, lte
| equipment id: 353533100763419
----------------------------------
System | device:
/sys/devices/platform/soc/soc:internal-regs/f10f0000.usb3/usb3/3-1
| physdev:
/sys/devices/platform/soc/soc:internal-regs/f10f0000.usb3/usb3/3-1
| drivers: cdc_mbim, qcserial
| plugin: sierra
| primary port: cdc-wdm0
| ports: cdc-wdm0 (mbim), ttyUSB0 (ignored),
ttyUSB1 (gps),
| ttyUSB2 (at), wwan0 (net)
----------------------------------
Status | lock: sim-pin2
| unlock retries: sim-pin2 (3)
| state: disabled
| power state: on
----------------------------------
Modes | supported: allowed: 3g; preferred: none
| allowed: 4g; preferred: none
| allowed: 3g, 4g; preferred: 4g
| allowed: 3g, 4g; preferred: 3g
| current: allowed: 4g; preferred: none
----------------------------------
Bands | supported: utran-1, utran-4, utran-6, utran-5,
utran-8, utran-9,
| utran-2, eutran-1, eutran-2, eutran-3,
eutran-4, eutran-5, eutran-7,
| eutran-8, eutran-9, eutran-12, eutran-13,
eutran-18, eutran-19,
| eutran-20, eutran-26, eutran-28,
eutran-29, eutran-30, eutran-32,
| eutran-41, eutran-42, eutran-43,
eutran-46, eutran-48, eutran-66,
| utran-19
| current: eutran-1, eutran-2, eutran-3, eutran-4,
eutran-5, eutran-7,
| eutran-8, eutran-9, eutran-12, eutran-13,
eutran-18, eutran-19,
| eutran-20, eutran-26, eutran-28,
eutran-29, eutran-30, eutran-32,
| eutran-41, eutran-42, eutran-43,
eutran-46, eutran-48, eutran-66
----------------------------------
IP | supported: ipv4, ipv6, ipv4v6
----------------------------------
3GPP | imei: 353533100763419
| enabled locks: sim, fixed-dialing
----------------------------------
3GPP EPS | ue mode of operation: csps-2
| initial bearer apn: internet
| initial bearer ip type: ipv4
----------------------------------
SIM | primary sim path: /org/freedesktop/ModemManager1/SIM/1
| sim slot paths: slot 1: none (active)
| slot 2: none
