Hey everyone,
I'm using openWRT 23.05.0 on a RaspberryPi 4B with a Sierra Wireless EM7455 in a usb enclosure, which is set to MBIM mode. I've stumbled upon a weird issue with my SIM and the MBIM interface.
I'll start by explaining the background, how the issue looks like and what I suspect the problem is. Scroll to the bottom for the issue description.
I've installed all the necessary packages according to the How to use LTE modem in QMI mode for WAN connection wiki page. I initially struggled to get the connection working with an MBIM interface, so I switched to modemmanager, which worked flawlessly. Then, I saw some interesting packages from @IceG like luci-app-sms-tool-js, which unfortunately don't work with modemmanager, according to the README.
This motivated my to try again to get an MBIM interface working, so I uninstalled modemmanager, rebooted, set up the MBIM interface in LuCI and rebooted again. Unfortunately, something was not working properly. I always got a PIN code rejected error displayed on the interfaces page. I double checked, if the correct PIN was entered in the config but it still didn't work. Then, I checked the log:
Thu Dec 7 23:29:23 2023 daemon.notice netifd: Interface 'lte1' is setting up now
Thu Dec 7 23:29:23 2023 daemon.notice netifd: lte1 (4547): mbim[4547] Reading capabilities
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): devicetype: 0003 - remote
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): cellularclass: 0001
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): voiceclass: 0001 - no-voice
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): simclass: 0002
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): dataclass: 003C
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): smscaps: 0003
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): controlcaps: 0001
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): maxsessions: 0008
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): deviceid: xxx
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): firmwareinfo: SWI9X30C_02.38.00.00
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): hardwareinfo: EM7455
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): mbim[4547] Sending pin
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): required pin: 12 - puk2
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): remaining attempts: 10
Thu Dec 7 23:29:25 2023 daemon.notice netifd: lte1 (4547): mbim[4547] Unable to verify PIN
Thu Dec 7 23:29:25 2023 user.notice root: mbim bringup failed, retry in 15s
Thu Dec 7 23:29:40 2023 daemon.notice netifd: lte1 (4568): mbim[4568] Stopping network
Thu Dec 7 23:29:40 2023 daemon.notice netifd: lte1 (4568): Command failed: ubus call network.interface notify_proto { "action": 0, "link-up": false, "keep": false, "interface": "lte1" } (Permission denied)
Thu Dec 7 23:29:40 2023 daemon.notice netifd: Interface 'lte1' is now down
For some reason it wants the PUK2 of the SIM?!
Then, I configured my lte1 interface to not come up on boot and rebooted the system and modem. Connected over ssh to openWRT and checked the PIN status with umbim -d /dev/cdc-wdm0 pinstate, which returned:
required pin: 2 - pin1
remaining attempts: 3
Then connected via picocom to the modem and also checked the PIN state there with AT+CPIN?, which returned: +CPIN: SIM PIN. Everything alright so far. SIM is locked like expected.
After that, I started the interface, which causes the error from above to appear. So I checked the commands again and got this back: AT+CPIN? returns +CPIN: READY, which means that the SIM is unlocked and should work. umbim -d /dev/cdc-wdm0 pinstate returns:
required pin 12 - puk2
remaining attempts: 10
The interface shows PIN code rejected in LuCI and no connection is established.
Then, I disabled the PIN of the SIM with AT+CLCK="SC",0,"<myPIN>", removed the PIN from the interface config and rebooted. Interface still configured to not come up on boot.
After the reboot AT+CPIN? now returns +CPIN: READY, meaning SIM is unlocked. umbim -d /dev/cdc-wdm0 pinstate returns:
required pin 12 - puk2
remaining attempts: 10
Then I start the interface with the restart button in LuCI and...everything works! Connected to the internet. The two commands return the same output as before the interface was brought up btw.
Now to what I think could cause the issue:
I don't know the inner workings of the procedure that is used to bring up the interface and the mbim commands that are used during this. So it could be that:
The EM7455 sends an unusual response for the unlock command
My SIM is configured unconventionally
umbim tries to unlock every PIN lock present on the SIM with the same PIN, unlocks PIN1, fails on PIN2 and reports a failure and stops. Since there is still a lock present, it reports PIN code rejected
The script, that calls umbim tries the above and fails
I don't really understand, why it works with the PIN1 disabled. There must be something else going on here. I think the root cause is having PIN1 and PIN2 activated at the same time.
Anyways, the obvious solution would be to just deactivate PIN1 and be done with it or stick to modemmanager, but that is not always acceptable. The device is on a remote location. I'm not comfortable with the idea that someone could steal the whole thing and use a SIM that is registered on my name. Sure the threat model is debatable but hopefully you get the point I'm trying to make.
The other thing is that this probably shouldn't be the expected behaviour, right!? I don't know how common it is to have a SIM with a PIN2 but iirc this was or can still be used to restrict the numbers that can call this SIM. You could maybe solve this issue as well by deactivating the PIN2 like described here (similar issue in this thread but on Fedora with modemmanager). The PIN2 and PUK2 used to be printed on the plastic card, where your phone number, PIN1 and PUK1 are printed on but is seems like providers stopped doing that, at least in my case. Some providers also seem charge a unreasonable fee for providing the codes according to some old (german) article.
If the behaviour can't be changed in the code, I think it would at least be worthy to mention this in the wiki.
I don't know if this also happens with QMI, haven't tested that yet.
Hope someone with more insight can look into this or help debugging.
Just tested it with QMI, by disabling MBIM on the modem with AT commands. It seems like QMI does not have this issue. I can always connect, no matter if the PIN1 is activated or not.
Hi @sodaws
I can't help you with configuring the modem because I've never had such a modem, but for this version of OpenWrt I recommend installing the luci-app-sms-tool-js package instead of luci-app-sms-tool.
In general, it is the same package, but one is indicated for LuCi JS and the other for LuCI Lua.
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:
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:
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:
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.
After fixing this issue, I tried to use mbim again. However, I was still experiencing some issues. I'm relying on Tailscale in my setup and as soon as I would do anything over this interface, the connection would just crap itself and only a restart of the mbim interface would fix the connection. I was unable to ping from any device to the internet from any interface. Same problem with qmi. Then, I switched back to modemmanager, which worked flawlessly. However, I was still experiencing issues with the modem. I was losing the connection every 5-60 minutes (similar to this issue). The openWRT side seemed fine but I was not getting any responses to pings. I unfortunately can't get into more detail here. Debugging the connection on the modem side is pretty hard. I think you can do it via the unsolicited result codes. However, I was having issues monitoring them while modemmanager was runnning. Running watchcat or luci-app-lite-watchdog in the case of mbim/qmi helped, but the interface restart would happen so often that the connection was basically unusable. I was also pretty tired of this anyway, so I just tried a different modem. Also tried rooter goldenorb but the flexibility of openWRT outweighs the convenience features. Not beeing able to install kmods (or having to compile them myself) was too tiring for me at this point.
With the Fibocom L850-GL the umbim solution wouldn't give me a IPv6...I suspect this is because this modem expects host SLAAC for IPv6, like described here. I didn't look further into this.
In the end, I switched to the Fibocom L850-GL and modemmanager. Forced disconnects from my ISP happen every 24h and I use watchcat to automatically restart the interface.
From my research it seems like there is still some work to be done with cellular connections in openWRT. Especially with the forced disconnects and IP changes. See the discussions and proposals here, here, here, here, here and here. Progress is beeing made.
I'm not really confident in saying this but I think using modemmager probably is the preferred solution at the moment. It also seems to be the project where support for all the different modems and all of their quirks is beeing worked on.
Some luci apps for modemmanager like the ones from 4iceG would also be nice....maybe I'll try to make one when I have more free time at some point in the future.
Will also try to make a PR for this change when I find time.