Bug #4742
closedTPDU failure in 00a20104020000
Added by laforge over 3 years ago. Updated over 3 years ago.
100%
Description
[001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:761 Rx RSPRO tpduModemToCard [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:701 tpduModemToCard(00a40004024f09) [001 CONN_CLIENT_MAPPED_CARD] bankd_pcsc.c:221 : OK [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:727 tpduModemToCard response from card: 6124 [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:761 Rx RSPRO tpduModemToCard [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:701 tpduModemToCard(00c0000024) [001 CONN_CLIENT_MAPPED_CARD] bankd_pcsc.c:221 : OK [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:727 tpduModemToCard response from card: 6222820542210002fa83024f09a506c00100ca01808a01058b036f0605800201f48801209000 [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:761 Rx RSPRO tpduModemToCard [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:701 tpduModemToCard(00a20104020000) [001 CONN_CLIENT_MAPPED_CARD] bankd_pcsc.c:221 SCardTransmit: Transaction failed. (0x80100016) [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:882 Error handling RSPRO [001 CONN_CLIENT_MAPPED_CARD] bankd_main.c:960 Error -2146435050 occurred: Cleaning up state
this happens reproducibly when using an EC20 via osmo-remsim with a sysmoUSIM-SJS1 in a sysmoOCTSIM.
Yet to be determined why.
Files
Updated by laforge over 3 years ago
INS=A2 is a "SEEK" command.
File 4f09 is EF_PBC in DF_PHONEBOOK (5F3A) beneath DF_TELECOM (7F10).
I can confirm the problem when manually executing the followng sequence:
(ISO 7816-4) > 00a40004023f00 -------------------------------------------------------------------------------- Beginning transaction 4 >> 0000: 00 a4 00 04 02 3f 00 .....?. << 0000: 61 56 aV >> 0000: 00 c0 00 00 56 ....V << 0000: 62 54 82 02 78 21 83 02 3f 00 a5 19 80 01 71 83 bT..x!..?.....q. 0010: 02 7f ff cb 0d 00 00 00 00 00 00 00 00 00 00 00 ................ 0020: 00 00 ca 01 82 8a 01 05 ab 1b 84 01 2e 90 00 84 ................ 0030: 01 88 a4 06 83 01 01 95 01 08 84 01 fc a4 06 83 ................ 0040: 01 0a 95 01 08 c6 0f 90 01 70 83 01 01 83 01 0a .........p...... 0050: 83 01 0b 83 01 81 90 00 ........ Ending transaction 4 -------------------------------------------------------------------------------- 0000: 62 54 82 02 78 21 83 02 3f 00 a5 19 80 01 71 83 bT..x!..?.....q. 0010: 02 7f ff cb 0d 00 00 00 00 00 00 00 00 00 00 00 ................ 0020: 00 00 ca 01 82 8a 01 05 ab 1b 84 01 2e 90 00 84 ................ 0030: 01 88 a4 06 83 01 01 95 01 08 84 01 fc a4 06 83 ................ 0040: 01 0a 95 01 08 c6 0f 90 01 70 83 01 01 83 01 0a .........p...... 0050: 83 01 0b 83 01 81 ...... Normal execution (SW 9000), 0.0431s (ISO 7816-4) > 00a40004027f10 -------------------------------------------------------------------------------- Beginning transaction 5 >> 0000: 00 a4 00 04 02 7f 10 ....... << 0000: 61 32 a2 >> 0000: 00 c0 00 00 32 ....2 << 0000: 62 30 82 02 78 21 83 02 7f 10 a5 16 83 02 7f ff b0..x!.......... 0010: cb 0d 00 00 00 00 00 00 00 00 00 00 00 00 00 ca ................ 0020: 01 82 8a 01 05 8b 03 2f 06 01 c6 06 90 01 00 83 ......./........ 0030: 01 01 90 00 .... Ending transaction 5 -------------------------------------------------------------------------------- 0000: 62 30 82 02 78 21 83 02 7f 10 a5 16 83 02 7f ff b0..x!.......... 0010: cb 0d 00 00 00 00 00 00 00 00 00 00 00 00 00 ca ................ 0020: 01 82 8a 01 05 8b 03 2f 06 01 c6 06 90 01 00 83 ......./........ 0030: 01 01 .. Normal execution (SW 9000), 0.0359s (ISO 7816-4) > 00a40004025F3A -------------------------------------------------------------------------------- Beginning transaction 7 >> 0000: 00 a4 00 04 02 5f 3a ....._: << 0000: 61 32 a2 >> 0000: 00 c0 00 00 32 ....2 << 0000: 62 30 82 02 78 21 83 02 5f 3a a5 16 83 02 7f ff b0..x!.._:...... 0010: cb 0d 00 00 00 00 00 00 00 00 00 00 00 00 00 ca ................ 0020: 01 80 8a 01 05 8b 03 6f 06 02 c6 06 90 01 00 83 .......o........ 0030: 01 01 90 00 .... Ending transaction 7 -------------------------------------------------------------------------------- 0000: 62 30 82 02 78 21 83 02 5f 3a a5 16 83 02 7f ff b0..x!.._:...... 0010: cb 0d 00 00 00 00 00 00 00 00 00 00 00 00 00 ca ................ 0020: 01 80 8a 01 05 8b 03 6f 06 02 c6 06 90 01 00 83 .......o........ 0030: 01 01 .. Normal execution (SW 9000), 0.0345s (ISO 7816-4) > 00a40004024f09 -------------------------------------------------------------------------------- Beginning transaction 9 >> 0000: 00 a4 00 04 02 4f 09 .....O. << 0000: 61 24 a$ >> 0000: 00 c0 00 00 24 ....$ << 0000: 62 22 82 05 42 21 00 02 fa 83 02 4f 09 a5 06 c0 b"..B!.....O.... 0010: 01 00 ca 01 80 8a 01 05 8b 03 6f 06 05 80 02 01 ..........o..... 0020: f4 88 01 20 90 00 ... .. Ending transaction 9 -------------------------------------------------------------------------------- 0000: 62 22 82 05 42 21 00 02 fa 83 02 4f 09 a5 06 c0 b"..B!.....O.... 0010: 01 00 ca 01 80 8a 01 05 8b 03 6f 06 05 80 02 01 ..........o..... 0020: f4 88 01 20 ... Normal execution (SW 9000), 0.0338s (ISO 7816-4) > 00a20104020000 -------------------------------------------------------------------------------- Beginning transaction 10 >> 0000: 00 a2 01 04 02 00 00 ....... <class 'smartcard.Exceptions.CardConnectionException'>: Failed to transmit with protocol T0. Transaction failed. File "/space/home/laforge/projects/git/cyberflex-shell/shell.py", line 126, in _run
Updated by laforge over 3 years ago
the ISO7816-3 FSM goes into the RESET state and gets stuck there:
ISO7816 ERROR <0002> ../ccid_common/iso7816_fsm.c:214 ISO7816-3(SIM2)[0x200140a0]{RESET}: Event UART_RX_SINGLE not permitted
ISO7816 ERROR <0002> ../ccid_common/iso7816_fsm.c:214 ISO7816-3(SIM2)[0x200140a0]{RESET}: Event UART_RX_SINGLE not permitted
even re-starting the client program doesn't help:
ISO7816 ERROR <0002> ../ccid_common/ccid_slot_fsm.c:286 ISO7816-3(SIM2)[0x200140a0]{RESET}: Event XCEIVE_TPDU_CMD not permitted
</pr>Updated by laforge over 3 years ago
- % Done changed from 0 to 10
It turns out the waiting time expires, i.e. CUART_E_RX_TIMEOUT is received and delivered as ISO7816_E_WTIME_EXP to the ISO7816-3 FSM which then transitions to RESET state.
The ISO7816-3 FSM is in IN_TPDU state, and the TPDU FSM is in SW1 state, i.e. waiting for the status word. As we receive two RX_SINGLE events after going into RESET, I think the timeout expires prematurely in this case? Either our timeout is too short regarding the spec, or the card is slower than specified?
Updated by laforge over 3 years ago
- % Done changed from 10 to 20
Extending the waiting time by 1s (as a hack) seems to work:
(ISO 7816-4) > 00a20104020000
--------------------------------------------------------------------------------
Beginning transaction 4
>> 0000: 00 a2 01 04 02 00 00 .......
<< 0000: 61 fa a.
>> 0000: 00 c0 00 00 fa .....
<< 0000: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 ................
0010: 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 ...............
0020: 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 !"#$%&'()*+,-./0
0030: 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 123456789:;<=>?@
0040: 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 ABCDEFGHIJKLMNOP
0050: 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 QRSTUVWXYZ[\]^_`
0060: 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 abcdefghijklmnop
0070: 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f 80 qrstuvwxyz{|}~..
0080: 81 82 83 84 85 86 87 88 89 8a 8b 8c 8d 8e 8f 90 ................
0090: 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f a0 ................
00a0: a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 ................
00b0: b1 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 ................
00c0: c1 c2 c3 c4 c5 c6 c7 c8 c9 ca cb cc cd ce cf d0 ................
00d0: d1 d2 d3 d4 d5 d6 d7 d8 d9 da db dc dd de df e0 ................
00e0: e1 e2 e3 e4 e5 e6 e7 e8 e9 ea eb ec ed ee ef f0 ................
00f0: f1 f2 f3 f4 f5 f6 f7 f8 f9 fa 90 00 ............
Ending transaction 4
--------------------------------------------------------------------------------
0000: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 ................
0010: 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 ...............
0020: 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 !"#$%&'()*+,-./0
0030: 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 123456789:;<=>?@
0040: 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 ABCDEFGHIJKLMNOP
0050: 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 QRSTUVWXYZ[\]^_`
0060: 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 abcdefghijklmnop
0070: 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f 80 qrstuvwxyz{|}~..
0080: 81 82 83 84 85 86 87 88 89 8a 8b 8c 8d 8e 8f 90 ................
0090: 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f a0 ................
00a0: a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 ................
00b0: b1 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 ................
00c0: c1 c2 c3 c4 c5 c6 c7 c8 c9 ca cb cc cd ce cf d0 ................
00d0: d1 d2 d3 d4 d5 d6 d7 d8 d9 da db dc dd de df e0 ................
00e0: e1 e2 e3 e4 e5 e6 e7 e8 e9 ea eb ec ed ee ef f0 ................
00f0: f1 f2 f3 f4 f5 f6 f7 f8 f9 fa ..........
Normal execution (SW 9000), 0.336s
Updated by laforge over 3 years ago
with that artificial 1s WTIME extension, I am getting the EC20 + sysmoUSIM fully bootstrapped:
+CPIN: READY +QUSIM: 1 +QIND: SMS DONE +QIND: PB DONE
Updated by Hoernchen over 3 years ago
I've just tried to reproduce this, but I can't - it just works for me...
Updated by Hoernchen over 3 years ago
That is with the cyberflex shell and the octsim itself, no modem involved - and at least after looking at the fsms I can't see why it would fail either. That being said the minimum timeout value can safely be increased to any kind of value, since expected timeouts are only going to happen during powerup with wrong voltages for old 5v cards and during ATR reading with arcane tail bytes.
Updated by laforge over 3 years ago
for the record, there's a patch available at https://gerrit.osmocom.org/c/osmo-ccid-firmware/+/19952/3
If it only happens on my system, I don't think it's worth to merge it. I guess we'd need more samples from people with other computers/kernels/distributions/...
Updated by Hoernchen over 3 years ago
There was maybe a slight miscalculation involved, so probably fixed by https://gerrit.osmocom.org/c/osmo-ccid-firmware/+/20071 even though I never ran into any issues.
Updated by laforge over 3 years ago
On Thu, Sep 10, 2020 at 11:05:11PM +0000, Hoernchen [REDMINE] wrote:
There was maybe a slight miscalculation involved, so probably fixed by https://gerrit.osmocom.org/c/osmo-ccid-firmware/+/20071 even though I never ran into any issues.
thanks, I'll try to reproduce the problem on the old firmware first and then try your patch.
Updated by laforge over 3 years ago
laforge wrote:
On Thu, Sep 10, 2020 at 11:05:11PM +0000, Hoernchen [REDMINE] wrote:
There was maybe a slight miscalculation involved, so probably fixed by https://gerrit.osmocom.org/c/osmo-ccid-firmware/+/20071 even though I never ran into any issues.
thanks, I'll try to reproduce the problem on the old firmware first and then try your patch.
I just re-tested, and unfortunately even with a 0.2.40 firmware the problem can still be observed with my SIM card:
(ISO 7816-4) > 00a20104020000 -------------------------------------------------------------------------------- Beginning transaction 4 >> 0000: 00 a2 01 04 02 00 00 ....... <class 'smartcard.Exceptions.CardConnectionException'>: Failed to transmit with protocol T0. Transaction failed.
Updated by laforge over 3 years ago
actually, I can reproduce it with multiple sysmoUSIM-SJS1 cards here, in different slots.
Updated by laforge over 3 years ago
After re-applying my "1s WTIME HACK" patch on top of current gerrit master, I can again successfully read the given file from various sysmoUSIM-SJS1 cards in my sysmoOCTSIM.
Updated by laforge over 3 years ago
some more testing shows that 25ms of additional waiting time is sufficient, but 2.5ms is insufficient.
Updated by laforge over 3 years ago
- Assignee changed from laforge to Hoernchen
the sweet spot seems to be somewhere between 10 and 12.5ms, as far as I could narrow it down.
I will modify my '1s hack' patch to use 100ms and merge that for now, in lack of better options and a clear problem with current master.
Updated by Hoernchen over 3 years ago
I've checked all formulas again but they are fine now - is it possible that PC_to_RDR_SetParameters (->PPS exchange with the card) sets WI too low? I suppose a bit of slack time is fine, too.
Updated by Hoernchen over 3 years ago
Well uh maybe there was something a liiiittle bit off after all: https://gerrit.osmocom.org/c/osmo-ccid-firmware/+/20691
Updated by laforge over 3 years ago
- Status changed from New to Feedback
- Assignee changed from Hoernchen to laforge
- % Done changed from 40 to 60
thanks for the quick follow-up. I reverted my patch and cherry-picked yours.
Unfortunately, already during the first execution:
connecting to sysmocom sysmoOCTSIM [CCID] (ab19180f3335355320202034463a15ff) 00 01
> 00 A4 00 04 02 3F 00
< [] 61 56
> 00 A4 00 04 02 7F 10
< [] 61 32
> 00 A4 00 04 02 5F 3A
< [] 61 32
> 00 A4 00 04 02 4F 09
< [] 61 24
> 00 A2 01 04 02 00 00
< [] 61 FA
> 00 A2 01 04 02 00 00
< [] 61 FA
> 00 A2 01 04 02 00 00
< [] 61 FA
> 00 A2 01 04 02 00 00
< [] 61 FA
> 00 A2 01 04 02 00 00
< [] 61 FA
> 00 A2 01 04 02 00 00
< [] 61 FA
> 00 A2 01 04 02 00 00
< [] 61 FA
> 00 A2 01 04 02 00 00
Traceback (most recent call last):
File "./os4742.py", line 42, in <module>
run_testcase(r[i])
File "./os4742.py", line 32, in run_testcase
response, sw1, sw2 = cardservice.connection.transmit(toBytes("00a20104020000"), cardservice.connection.T0_protocol)
File "/usr/lib/python3/dist-packages/smartcard/CardConnectionDecorator.py", line 82, in transmit
return self.component.transmit(bytes, protocol)
File "/usr/lib/python3/dist-packages/smartcard/CardConnection.py", line 146, in transmit
data, sw1, sw2 = self.doTransmit(bytes, protocol)
File "/usr/lib/python3/dist-packages/smartcard/pcsc/PCSCCardConnection.py", line 200, in doTransmit
raise CardConnectionException(
smartcard.Exceptions.CardConnectionException: Failed to transmit with protocol T0. Transaction failed.
disconnecting from sysmocom sysmoOCTSIM [CCID] (ab19180f3335355320202034463a15ff) 00 01
disconnecting from sysmocom sysmoOCTSIM [CCID] (ab19180f3335355320202034463a15ff) 00 01
I'm running some more tests right now, and on subsequent runs it didn't immediately fail again. Will report back later.
Updated by laforge over 3 years ago
I cannot reproduce the problem anymore. Even after several thousand consecutive test runs. I'll disconnect the board now and give it some time to cool down, then restart.
Updated by laforge over 3 years ago
- Status changed from Feedback to Resolved
- % Done changed from 60 to 100
Updated by laforge over 3 years ago
problem was not possible to reproduce even after several reboots and thousands of cycles.
