Project

General

Profile

Actions

Bug #4742

closed

TPDU failure in 00a20104020000

Added by laforge over 3 years ago. Updated over 3 years ago.

Status:
Resolved
Priority:
High
Assignee:
Target version:
-
Start date:
09/02/2020
Due date:
% Done:

100%

Spec Reference:

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

os4742.py os4742.py 975 Bytes laforge, 10/16/2020 08:34 PM
Actions #1

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

Actions #2

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>

Actions #3

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?

Actions #4

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

Actions #5

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

Actions #6

Updated by Hoernchen over 3 years ago

I've just tried to reproduce this, but I can't - it just works for me...

Actions #7

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.

Actions #8

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/...

Actions #9

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.

Actions #10

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.

Actions #11

Updated by Hoernchen over 3 years ago

Ping - presumably fixed by my patch that was merged?

Actions #12

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.
Actions #13

Updated by laforge over 3 years ago

actually, I can reproduce it with multiple sysmoUSIM-SJS1 cards here, in different slots.

Actions #14

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.

Actions #15

Updated by laforge over 3 years ago

some more testing shows that 25ms of additional waiting time is sufficient, but 2.5ms is insufficient.

Actions #16

Updated by laforge over 3 years ago

attaching a test program for reproduction

Actions #17

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.

Actions #18

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.

Actions #19

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

Actions #20

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.

Actions #21

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.

Actions #22

Updated by laforge over 3 years ago

  • Status changed from Feedback to Resolved
  • % Done changed from 60 to 100
Actions #23

Updated by laforge over 3 years ago

problem was not possible to reproduce even after several reboots and thousands of cycles.

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)