TL;DR: To fix the bug, change 2 lines in /lib/netifd/proto/mbim.sh on your running system. To have a nice experience, switch to modemmanager + watchcat and maybe switch to another modem.
Change this:
To:
echo "mbim[$$]" "Sending pin"
umbim $DBG -n -t $tid -d $device unlock "$pincode"
[ $? -eq 2 ] && {
echo "mbim[$$]" "Unable to verify PIN"
Just like line 112-113 in the same file.
Background
See MBIM specification for more background info.
The relevant code is this section:
In line 100, if the umbim command returns a non-zero exit code, a PIN_FAILED error is returned. umbim internally sends a MBIM_CID_PIN command of the Basic Connect Service with a MBIM_SET_PIN structure to unlock PIN1, then the modem returns a MBIM_PIN_INFO structure. This pin info structure contains PinType (MBIM_PIN_TYPE) and PinState (MBIM_PIN_STATE). If PinState is not 0 (MBIMPinStateUnlocked), the exit code of umbim is the value of the returned PinType.
See this code from umbim:
and the relevant enums in:
and:
This is analogous to the MBIM spec page 88-92. If the wrong PIN is entered, PinType, PinState and the remaining unlock tries are returned.
How this Error happens
Now let's look at the debug output of the pin unlock command from umbim when executed manually:
root@OpenWrt:~# umbim -v -d /dev/cdc-wdm0 unlock 1111
sending (16): 01 00 00 00 10 00 00 00 01 00 00 00 00 10 00 00
header_type: 0001
header_length: 0010
header_transaction: 0001
reading (16): 01 00 00 80 10 00 00 00 01 00 00 00 00 00 00 00
header_type: 80000001
header_length: 0010
header_transaction: 0001
sending (80): 03 00 00 00 50 00 00 00 02 00 00 00 01 00 00 00 00 00 00 00 a2 89 cc 33 bc bb 8b 4f b6 b0 13 3e c2 aa e6 df 04 00 00 00 01 00 00 00 20 00 00 00 02 00 00 00 00 00 00 00 18 00 00 00 08 00 00 00 00 00 00 00 00 00 00 00 31 00 31 00 31 00 31 00
header_type: 0003
header_length: 0050
header_transaction: 0002
reading (60): 03 00 00 80 3c 00 00 00 02 00 00 00 01 00 00 00 00 00 00 00 a2 89 cc 33 bc bb 8b 4f b6 b0 13 3e c2 aa e6 df 04 00 00 00 00 00 00 00 0c 00 00 00 03 00 00 00 01 00 00 00 03 00 00 00
header_type: 80000003
header_length: 003C
header_transaction: 0002
command_id: 0004
status_code: 0000
required pin: 3 - pin2
remaining attempts: 3
sending (16): 02 00 00 00 10 00 00 00 03 00 00 00 01 00 00 00
header_type: 0002
header_length: 0010
header_transaction: 0003
reading (16): 02 00 00 80 10 00 00 00 03 00 00 00 00 00 00 00
header_type: 80000002
header_length: 0010
header_transaction: 0003
A unlock command for PIN1 is sent but the modem returns the status of PIN2 instead of PIN1. Let's reinsert the SIM and unlock PIN2 like this before unlocking PIN1:
# unlock PIN2 by trying to unlock the Fixed Dialing feature of the SIM
picocom -d /dev/ttyUSB1
AT+CLCK="FD",0,"2222"
ERROR
# this returns an error because this can only be unlocked if PIN1
# was unlocked beforehand, however it still checks if the entered
# PIN2 is valid. This will unlock PIN2 authentication for the current
# SIM power cycle.
# also: Disabling the FD lock will not disable PIN2 and solve this issue
Now if we run the umbim command again, we get:
NOTE: need verification here. I already deployed my router and forgot to take a log from this exact sequence. The following log is from unlocking PIN1 and then PIN2 via mbimcli so that there are no other locks active after that. I suspect we'd get the same raw mbim responses if it was the other way around and done with umbim. (Unlocking PIN2 first with mbim and then unlocking PIN1 with umbim, since umbim cannot unlock PIN2)
root@OpenWrt:~# mbimcli --verbose-full -d /dev/cdc-wdm0 --enter-pin=pin1,1111
[14 Dec 2023, 19:14:53] [Debug] [/dev/cdc-wdm0] opening device...
[14 Dec 2023, 19:14:53] [Debug] [/dev/cdc-wdm0] queried max control message size: 4096
[14 Dec 2023, 19:14:53] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:01:00:00:00:00:10:00:00
[14 Dec 2023, 19:14:53] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 1
<<<<<< Contents:
<<<<<< max control transfer = 4096
[14 Dec 2023, 19:14:55] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 01:00:00:80:10:00:00:00:01:00:00:00:00:00:00:00
[14 Dec 2023, 19:14:55] [Debug] MBIM Device at '/dev/cdc-wdm0' ready
[14 Dec 2023, 19:14:55] [Debug] Asynchronously entering PIN...
[14 Dec 2023, 19:14:55] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 80
<<<<<< data = 03:00:00:00:50:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:01:00:00:00:20:00:00:00:02:00:00:00:00:00:00:00:18:00:00:00:08:00:00:00:00:00:00:00:00:00:00:00:31:00:31:00:31:00:31:00
[14 Dec 2023, 19:14:55] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 80
<<<<<< type = command (0x00000003)
<<<<<< transaction = 2
<<<<<< 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 = '1111'
<<<<<< NewPin = '(null)'
[14 Dec 2023, 19:14:56] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 60
>>>>>> data = 03:00:00:80:3C:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:00:00:00:00:0C:00:00:00:03:00:00:00:01:00:00:00:03:00:00:00
[14 Dec 2023, 19:14:56] [Debug] [/dev/cdc-wdm0] received message (translated)...
>>>>>> Header:
>>>>>> length = 60
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 2
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'pin' (0x00000004)
>>>>>> Fields:
>>>>>> PinType = 'pin2'
>>>>>> PinState = 'locked'
>>>>>> RemainingAttempts = '3'
[/dev/cdc-wdm0] PIN operation successful
[/dev/cdc-wdm0] PIN info:
PIN state: 'locked'
PIN type: 'pin2'
Remaining attempts: '3'
[14 Dec 2023, 19:14:56] [Debug] [/dev/cdc-wdm0] closing device...
[14 Dec 2023, 19:14:56] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 12
<<<<<< data = 02:00:00:00:0C:00:00:00:03:00:00:00
[14 Dec 2023, 19:14:56] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 12
<<<<<< type = close (0x00000002)
<<<<<< transaction = 3
[14 Dec 2023, 19:14:56] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 02:00:00:80:10:00:00:00:03:00:00:00:00:00:00:00
[14 Dec 2023, 19:14:56] [Debug] [/dev/cdc-wdm0] channel destroyed
[14 Dec 2023, 19:14:56] [Debug] Device closed
----------------------------------------------------------------------------------------
root@OpenWrt:~# mbimcli --verbose-full -d /dev/cdc-wdm0 --enter-pin=pin2,2222
[14 Dec 2023, 19:16:21] [Debug] [/dev/cdc-wdm0] opening device...
[14 Dec 2023, 19:16:21] [Debug] [/dev/cdc-wdm0] queried max control message size: 4096
[14 Dec 2023, 19:16:21] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:01:00:00:00:00:10:00:00
[14 Dec 2023, 19:16:21] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 1
<<<<<< Contents:
<<<<<< max control transfer = 4096
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 01:00:00:80:10:00:00:00:01:00:00:00:00:00:00:00
[14 Dec 2023, 19:16:23] [Debug] MBIM Device at '/dev/cdc-wdm0' ready
[14 Dec 2023, 19:16:23] [Debug] Asynchronously entering PIN...
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 80
<<<<<< data = 03:00:00:00:50:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:01:00:00:00:20:00:00:00:03:00:00:00:00:00:00:00:18:00:00:00:08:00:00:00:00:00:00:00:00:00:00:00:32:00:32:00:32:00:32:00
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 80
<<<<<< type = command (0x00000003)
<<<<<< transaction = 2
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'pin' (0x00000004)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< PinType = 'pin2'
<<<<<< PinOperation = 'enter'
<<<<<< Pin = '2222'
<<<<<< NewPin = '(null)'
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 60
>>>>>> data = 03:00:00:80:3C:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:00:00:00:00:0C:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] received message (translated)...
>>>>>> Header:
>>>>>> length = 60
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 2
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'pin' (0x00000004)
>>>>>> Fields:
>>>>>> PinType = 'unknown'
>>>>>> PinState = 'unlocked'
>>>>>> RemainingAttempts = '0'
[/dev/cdc-wdm0] PIN operation successful
[/dev/cdc-wdm0] PIN info:
PIN state: 'unlocked'
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] closing device...
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 12
<<<<<< data = 02:00:00:00:0C:00:00:00:03:00:00:00
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 12
<<<<<< type = close (0x00000002)
<<<<<< transaction = 3
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 02:00:00:80:10:00:00:00:03:00:00:00:00:00:00:00
[14 Dec 2023, 19:16:23] [Debug] [/dev/cdc-wdm0] channel destroyed
[14 Dec 2023, 19:16:23] [Debug] Device closed
Here is the stupid part after unlocking PIN1 and PIN2:
>>>>>> PinType = 'unknown'
>>>>>> PinState = 'unlocked'
>>>>>> RemainingAttempts = '0'
This modem never returns the status of the PIN that was unlocked with the pin type specified in the unlock command. If both PINs are active and locked, a unlock command will always return the status of the other PIN that is still locked. The successful unlock command of the remaining PIN will return the above.
In my opinion the response should be the state of the PIN type the unlock command was intended for. Just like my Fibocom L850-GL does. See the log of that modem:
root@OpenWrt:~# mbimcli --verbose-full -d /dev/cdc-wdm0 --enter-pin=pin1,1111
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] opening device...
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] queried max control message size: 512
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:01:00:00:00:00:02:00:00
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 1
<<<<<< Contents:
<<<<<< max control transfer = 512
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 01:00:00:80:10:00:00:00:01:00:00:00:00:00:00:00
[14 Dec 2023, 20:23:49] [Debug] MBIM Device at '/dev/cdc-wdm0' ready
[14 Dec 2023, 20:23:49] [Debug] Asynchronously entering PIN...
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 80
<<<<<< data = 03:00:00:00:50:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:01:00:00:00:20:00:00:00:02:00:00:00:00:00:00:00:18:00:00:00:08:00:00:00:00:00:00:00:00:00:00:00:31:00:31:00:31:00:31:00
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 80
<<<<<< type = command (0x00000003)
<<<<<< transaction = 2
<<<<<< 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 = '1111'
<<<<<< NewPin = '(null)'
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 60
>>>>>> data = 03:00:00:80:3C:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:00:00:00:00:0C:00:00:00:02:00:00:00:00:00:00:00:03:00:00:00
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] received message (translated)...
>>>>>> Header:
>>>>>> length = 60
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 2
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'pin' (0x00000004)
>>>>>> Fields:
>>>>>> PinType = 'pin1'
>>>>>> PinState = 'unlocked'
>>>>>> RemainingAttempts = '3'
[/dev/cdc-wdm0] PIN operation successful
[/dev/cdc-wdm0] PIN info:
PIN state: 'unlocked'
PIN type: 'pin1'
Remaining attempts: '3'
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] closing device...
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 12
<<<<<< data = 02:00:00:00:0C:00:00:00:03:00:00:00
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 12
<<<<<< type = close (0x00000002)
<<<<<< transaction = 3
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 02:00:00:80:10:00:00:00:03:00:00:00:00:00:00:00
[14 Dec 2023, 20:23:49] [Debug] [/dev/cdc-wdm0] channel destroyed
[14 Dec 2023, 20:23:49] [Debug] Device closed
Also interesting: umbim checks if the returned structure contains PinState unlocked and proceeds regardless of the PinType. Which actually is reasonable, because why would you expect a response to a different PIN type when you send the unlock command for PIN1.
Solutions
This issue has showed up multiple times in the past here, here, here and here.
The solution proposed from the libmbim aka modemmanager folks was to just ignore this, since only a unlocked PIN1 is needed to connect to the network.
A similar issue previously happened right after the initially cited code from mbim.sh here:
The code previously was having the same issue, where the PIN1 was unlocked but after the that the umbim pinstate command would return the status of a PIN2 if it was active on the SIM card.
Back in the day the solution for this, as part of some other changes, were proposed here:
However, the above PR ended up not beeing merged. Another PR picked up the essence of the fix:
And the fix was ultimately merged with this commit:
The solution to this issue here is basically the same and therefore I think the same kind of solution should be applied just like I typed in the beginning of this post.
You can also not query for the state of a specific PIN type with mbim. The query operation has no input buffer.
Non-viable or less preferred solutions
Disabling PIN2 doesn't seem to be possible
I can also confirm this. Neither EM7455 nor L850-GL can disable PIN2, see the logs:
--------- first em7455 -------
root@OpenWrt:~# mbimcli --verbose-full -d /dev/cdc-wdm0 --disable-pin=pin2,2222
[14 Dec 2023, 19:17:05] [Debug] [/dev/cdc-wdm0] opening device...
[14 Dec 2023, 19:17:05] [Debug] [/dev/cdc-wdm0] queried max control message size: 4096
[14 Dec 2023, 19:17:05] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:01:00:00:00:00:10:00:00
[14 Dec 2023, 19:17:05] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 1
<<<<<< Contents:
<<<<<< max control transfer = 4096
[14 Dec 2023, 19:17:07] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 01:00:00:80:10:00:00:00:01:00:00:00:00:00:00:00
[14 Dec 2023, 19:17:07] [Debug] MBIM Device at '/dev/cdc-wdm0' ready
[14 Dec 2023, 19:17:07] [Debug] Asynchronously disabling PIN...
[14 Dec 2023, 19:17:07] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 80
<<<<<< data = 03:00:00:00:50:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:01:00:00:00:20:00:00:00:03:00:00:00:02:00:00:00:18:00:00:00:08:00:00:00:00:00:00:00:00:00:00:00:32:00:32:00:32:00:32:00
[14 Dec 2023, 19:17:07] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 80
<<<<<< type = command (0x00000003)
<<<<<< transaction = 2
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'pin' (0x00000004)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< PinType = 'pin2'
<<<<<< PinOperation = 'disable'
<<<<<< Pin = '2222'
<<<<<< NewPin = '(null)'
[14 Dec 2023, 19:17:08] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 60
>>>>>> data = 03:00:00:80:3C:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:09:00:00:00:0C:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
[14 Dec 2023, 19:17:08] [Debug] [/dev/cdc-wdm0] received message (translated)...
>>>>>> Header:
>>>>>> length = 60
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 2
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'NoDeviceSupport' (0x00000009)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'pin' (0x00000004)
error: operation failed: NoDeviceSupport
[14 Dec 2023, 19:17:08] [Debug] [/dev/cdc-wdm0] closing device...
[14 Dec 2023, 19:17:08] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 12
<<<<<< data = 02:00:00:00:0C:00:00:00:03:00:00:00
[14 Dec 2023, 19:17:08] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 12
<<<<<< type = close (0x00000002)
<<<<<< transaction = 3
[14 Dec 2023, 19:17:08] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 02:00:00:80:10:00:00:00:03:00:00:00:00:00:00:00
[14 Dec 2023, 19:17:08] [Debug] [/dev/cdc-wdm0] channel destroyed
[14 Dec 2023, 19:17:08] [Debug] Device closed
----------------------------------------
uqmi -d /dev/cdc-wdm0 --set-pin2-protection disabled --pin 2222
"Invalid QMI command"
----------------------------------------
qmicli -d /dev/cdc-wdm0 --dms-uim-set-pin-protection=PIN2,disable,2222
error: couldn't set PIN protection: QMI protocol error (71): 'InvalidQmiCommand'
----------------------------------------
qmicli --verbose-full -d /dev/cdc-wdm0 --uim-set-pin-protection=PIN2,disable,2222
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] opening device with flags 'auto'...
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] automatically selecting QMI mode
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] created endpoint
[14 Dec 2023, 20:16:21] [Debug] QMI Device at '/dev/cdc-wdm0' ready
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] assuming service 'uim' is supported...
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] allocating new client ID...
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:0F:00:00:00:00:00:01:22:00:04:00:01:01:00:0B
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 15
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 1
<<<<<< tlv_length = 4
<<<<<< message = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<< type = "Service" (0x01)
<<<<<< length = 1
<<<<<< value = 0B
<<<<<< translated = uim
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] received message...
<<<<<< RAW:
<<<<<< length = 24
<<<<<< data = 01:17:00:80:00:00:01:01:22:00:0C:00:02:04:00:00:00:00:00:01:02:00:0B:02
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 23
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 12
<<<<<< message = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Allocation Info" (0x01)
<<<<<< length = 2
<<<<<< value = 0B:02
<<<<<< translated = [ service = 'uim' cid = '2' ]
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] registered 'uim' (version unknown) client with ID '2'
[14 Dec 2023, 20:16:21] [Debug] Asynchronously setting PIN protection...
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 28
<<<<<< data = 01:1B:00:00:0B:02:00:01:00:25:00:0F:00:02:07:00:02:00:04:32:32:32:32:01:02:00:06:00
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 27
<<<<<< flags = 0x00
<<<<<< service = "uim"
<<<<<< client = 2
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 1
<<<<<< tlv_length = 15
<<<<<< message = "Set PIN Protection" (0x0025)
<<<<<< TLV:
<<<<<< type = "Info" (0x02)
<<<<<< length = 7
<<<<<< value = 02:00:04:32:32:32:32
<<<<<< translated = [ pin_id = 'pin2' pin_enabled = 'no' pin_value = '2222' ]
<<<<<< TLV:
<<<<<< type = "Session" (0x01)
<<<<<< length = 2
<<<<<< value = 06:00
<<<<<< translated = [ session_type = 'card-slot-1' application_identifier = '{}' ]
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] received message...
<<<<<< RAW:
<<<<<< length = 30
<<<<<< data = 01:1D:00:80:0B:02:02:01:00:25:00:11:00:02:04:00:01:00:19:00:13:02:00:6B:00:10:02:00:03:0A
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 29
<<<<<< flags = 0x80
<<<<<< service = "uim"
<<<<<< client = 2
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 17
<<<<<< message = "Set PIN Protection" (0x0025)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 01:00:19:00
<<<<<< translated = FAILURE: DeviceUnsupported
<<<<<< TLV:
<<<<<< type = 0x13
<<<<<< length = 2
<<<<<< value = 6B:00
<<<<<< TLV:
<<<<<< type = "Retries Remaining" (0x10)
<<<<<< length = 2
<<<<<< value = 03:0A
<<<<<< translated = [ verify_retries_left = '3' unblock_retries_left = '10' ]
error: couldn't set PIN protection: QMI protocol error (25): 'DeviceUnsupported'
[/dev/cdc-wdm0] Retries left:
Verify: 3
Unblock: 10
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] releasing 'uim' client with flags 'release-cid'...
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] unregistered 'uim' client with ID '2'
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 17
<<<<<< data = 01:10:00:00:00:00:00:02:23:00:05:00:01:02:00:0B:02
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 16
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 2
<<<<<< tlv_length = 5
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 0B:02
<<<<<< translated = [ service = 'uim' cid = '2' ]
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] received message...
<<<<<< RAW:
<<<<<< length = 24
<<<<<< data = 01:17:00:80:00:00:01:02:23:00:0C:00:02:04:00:00:00:00:00:01:02:00:0B:02
[14 Dec 2023, 20:16:21] [Debug] [/dev/cdc-wdm0] received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 23
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 2
<<<<<< tlv_length = 12
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 0B:02
<<<<<< translated = [ service = 'uim' cid = '2' ]
[14 Dec 2023, 20:16:21] [Debug] Client released
[14 Dec 2023, 20:16:21] [Debug] Closed
----- now fibocom l850-gl -----
mbimcli --verbose-full -d /dev/cdc-wdm0 --disable-pin=pin2,2222
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] opening device...
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] queried max control message size: 512
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:01:00:00:00:00:02:00:00
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 1
<<<<<< Contents:
<<<<<< max control transfer = 512
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 01:00:00:80:10:00:00:00:01:00:00:00:00:00:00:00
[14 Dec 2023, 20:29:14] [Debug] MBIM Device at '/dev/cdc-wdm0' ready
[14 Dec 2023, 20:29:14] [Debug] Asynchronously disabling PIN...
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 80
<<<<<< data = 03:00:00:00:50:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:01:00:00:00:20:00:00:00:03:00:00:00:02:00:00:00:18:00:00:00:08:00:00:00:00:00:00:00:00:00:00:00:32:00:32:00:32:00:32:00
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 80
<<<<<< type = command (0x00000003)
<<<<<< transaction = 2
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'pin' (0x00000004)
<<<<<< type = 'set' (0x00000001)
<<<<<< Fields:
<<<<<< PinType = 'pin2'
<<<<<< PinOperation = 'disable'
<<<<<< Pin = '2222'
<<<<<< NewPin = '(null)'
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 48
>>>>>> data = 03:00:00:80:30:00:00:00:02:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:04:00:00:00:09:00:00:00:00:00:00:00
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] received message (translated)...
>>>>>> Header:
>>>>>> length = 48
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 2
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'NoDeviceSupport' (0x00000009)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'pin' (0x00000004)
error: operation failed: NoDeviceSupport
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] closing device...
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 12
<<<<<< data = 02:00:00:00:0C:00:00:00:03:00:00:00
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 12
<<<<<< type = close (0x00000002)
<<<<<< transaction = 3
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 16
>>>>>> data = 02:00:00:80:10:00:00:00:03:00:00:00:00:00:00:00
[14 Dec 2023, 20:29:14] [Debug] [/dev/cdc-wdm0] channel destroyed
[14 Dec 2023, 20:29:14] [Debug] Device closed
I tested this with every combination.
EM7455:
- in QMI mode via qmicli and uqmi
- in MBIM mode via qmicli/uqmi with QMI over MBIM (qmi is always active on this modem)
- in MBIM mode via mbimcli
For L850-GL only with mbimcli of course.
I unlocked both pins before trying to disable PIN2. Also disabled PIN1 before trying to disable PIN2 and vice versa.
Error is always NoDeviceSupport or InvalidQmiCommand.
Disabling the FD lock with AT Commands also has no impact (disabled is the default state anyway)
Changing umbim exit codes
This doesn't feel right. It probably shouldn't be the job of umbim or libmbim to consider certain hardware quirks. These probably should return the unaltered modem response.
Unlocking PIN2 before PIN1
Implementing PIN2 unlock procedure in umbim, adding a field in luci and unlocking both PINs every time seems too much to just get the right exit code. Manually sending the AT command like shown above also seems not to be the preferred way.