Hi James,
On Wed, Mar 27, 2024 at 12:00:50PM -0400, James Tavares wrote:
I am having difficulty with a particular SIM card over osmo-remsim. On the bank daemon side, PCSC is timing out after 1 second on the same transaction (modemToCard: 81f2400202) after every reset.
I'm sorry to hear.
This behavior is very reliable and happens on every reset/initialization sequence from the modem. When I enable PCSC debugging, I see it is getting back the error CCID error 0xFE “Card absent or mute” from the CCID reader. When I use this card directly attached to the modem, everything is fine and the modem can go online (but I have no insight as to whether the modem is encountering an issue with the same APDU, or not).f
Do you have a SIMtrace2 around using which you could trace the successful communication when using the SIM directly in the modem?
Based on some earlier troubleshooting it appears to be related to eSIM (eUICC) functionality. This particular card reports as an eSIM (side note: curiously, its EID is blank). When I use old modem firmware that does not support eSIM capabilities, the card works just fine over osmo-remsim. It is only when I upgrade the modem firmware to a version that supports eSIM that this problem appears.
The 81f2400202 is a "GET STATUS" APDU. the '1' in 81 indicates it happens on a logical channel, not directly on the raw APDU
It seems that both GlobalPlatform as well as ETSI TS 102 221 both specify a F2 command, and both for CLA=8x (first nibble 8, any lower bits).
Oddly enough, according to https://gitea.osmocom.org/osmocom/libosmocore/src/branch/master/src/sim/clas... the ISO 7816 "case" of those two is different: TS 102 221 is marked as case '2' while GlobalPlatform is marked as case '4'
The way how the uicc_sim_ins_case[] is sorted, the ETSI spec will be used first, and hence case '2' is assumed.
Those cases refer to ISO 7816-3 12.1.2, where * case 2 means that there are no command bytes (Nc=0) but there are response bytes (Nr > 0) * case 4 measn that there is both Nc > 0 and Nr > 0
I will investigate this further; maybe there's a bug in class_tables.c, or if we somehow have to work around this in some other way.
- Is there a way to change the timeout? I tried modifying libccid to set bBWI to 0xFF for this transaction (it was 0x00), but that had to effect. Internal timeouts within pcscd seem to be set to 3 seconds, and so I do not think they are coming into play, here.
USB-CCID Readers typically handle all those timeouts inside a TPDU (waiting time, guard time, etc.) internally. The timeouts are part of the firmware.
- What are your feelings on having osmo-remsim-bankd ignore this error and return a 0x6f 0x00?
This sounds like a very bad approach, basically plastering over the problem at a much higher level. Without understanding the modem firmware in detail it's not clear what the unexpected consequences of that might be.
- Any other ideas?
Here is the truncated log of traffic leading up to the offending APDU: [...]
in general, a pcap file with the rspro communication is likely easier to analyze. Or even better: Enable the gsmtap logging (-g 127.0.0.1 and then tace a pcap file of 'lo'). This pcap file can then be analyzed by pySim-trace.py for meaningful high-level decode. Admittedly, pySim-trace is much more recent than osmo-remsim and I haven't used them in combination yet, but the GSMTAP SIM pcap format should ensure interoperability.
local4.info: 2024-03-26 03:10:31.221037 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(621982054221001c0383026f408a01058b036f06058002005488009000) local4.info: 2024-03-26 03:10:31.228286 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(00b208bc3e) local4.info: 2024-03-26 03:10:31.242339 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(800101a40683010195010880015aa40683010a9501088401d4a40683010a950108ffffffffffffffffffffffffffffffffffffffffffffffffffffffffff9000) local4.info: 2024-03-26 03:10:31.250619 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(00b205043e) local4.info: 2024-03-26 03:10:31.255170 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(800103a406830101950108800158a40683010a9501088401d4a40683010a950108ffffffffffffffffffffffffffffffffffffffffffffffffffffffffff9000) local4.info: 2024-03-26 03:10:31.263534 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(00b209043e) local4.info: 2024-03-26 03:10:31.267873 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(800101a406830101950108800102a406830181950108800158a40683010a9501088401d4a40683010a950108ffffffffffffffffffffffffffffffffffff9000) local4.info: 2024-03-26 03:10:31.276622 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(00b206043e) local4.info: 2024-03-26 03:10:31.280369 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(8001019000800102a406830101950108800158a40683010a9501088401d4a40683010a950108ffffffffffffffffffffffffffffffffffffffffffffffff9000) local4.info: 2024-03-26 03:10:31.288355 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(00b201043e) local4.info: 2024-03-26 03:10:31.293560 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(800101900080015aa40683010a9501088401d4a40683010a950108ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff9000) local4.info: 2024-03-26 03:10:31.304765 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(00a40804047fff6fc6) local4.info: 2024-03-26 03:10:31.312115 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(611c) local4.info: 2024-03-26 03:10:31.316190 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(00c000001c) local4.info: 2024-03-26 03:10:31.319163 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(621a8205422100080183026fc68a01058b036f0601800200088801d09000) local4.info: 2024-03-26 03:10:31.328212 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(00a2010408ffffffffffffffff) local4.info: 2024-03-26 03:10:31.330957 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:793 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Tx RSPRO tpduCardToModem(6282)
all of the above is communication on the primary logical channel (second nibble of CLA octet is 0), so it doesn't have any context to the parallel communication happening on other logical channels, like the 81 on lchan1 below.
Having a full/proper trace (ideally GSMTAP as described above) would allow to check what is happening on that logical channel 1 at an earlier time, ideally back to when itw as opened.
local4.info: 2024-03-26 03:10:31.335619 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:766 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Rx RSPRO tpduModemToCard(81f2400202) local4.info: 2024-03-26 03:10:32.363083 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_pcsc.c:319 [000 B1:0 CONN_CLIENT_MAPPED_CARD] SCardTransmit: Transaction failed. (0x80100016) local4.info: 2024-03-26 03:10:32.363239 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:970 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Error handling RSPRO local4.info: 2024-03-26 03:10:32.363364 bdu-arm-ce-imx8mp bankd-wrapper[1762]: 1763 DBANKDW INFO ../../../git/src/bankd/bankd_main.c:1051 [000 B1:0 CONN_CLIENT_MAPPED_CARD] Error -2146435050 occurred: Cleaning up state