Bug #5419: cardem errors with higher baud rate - SIMtrace 2 - Open Source Mobile Communications

Actions

Copy link

Bug #5419

open

cardem errors with higher baud rate

Added by laforge about 2 years ago. Updated over 1 year ago.

Status:

Stalled

Priority:

High

Assignee:

laforge

Category:

firmware

Target version:

Start date:

01/25/2022

Due date:

% Done:

60%

Spec Reference:

Description

Setup is as follows:

sysmoISIM-SJA2 in built-in CCID reader of my Thinkpad x260
SIMtrace2 with cardem firmware 'master' (0.8.1.7-ea9a) hooked up via FPC to
CCID reader "Identive CLOUD 2700 F"
simtrace2-cardem-pcsc to forward request from IdentiveCCID -> SIMtrace -> st2-cardem-pcsc -> builtin-CCID

This works fine with F/D ratio 372, and also works fine in most cases with F/D ratio 16.

However, sometimes with ratio 16, things break down at some point.

log output of cardem firmware¶

-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 b2 9d 04 22
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: flush_rx_buffer (5)
-I- 0: flush_rx_buffer (2)
-I- 0: send_tpdu_header: 00 c0 00 00 23
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 b2 9e 04 22
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: flush_rx_buffer (5)
-I- 0: flush_rx_buffer (2)
-I- 0: send_tpdu_header: 00 c0 00 00 23
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 b2 9f 04 22
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: flush_rx_buffer (5)
-I- 0: flush_rx_buffer (2)
-I- 0: send_tpdu_header: 00 c0 00 00 23
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 b2 a0 04 22
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: flush_rx_buffer (5)
-I- 0: flush_rx_buffer (2)
-I- 0: send_tpdu_header: 00 c0 00 00 23
-I- 0: flush_rx_buffer (5)
N-I- 0: send_tpdu_header: 00 b2 a1 04 22
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: flush_rx_buffer (5)
-I- 0: flush_rx_buffer (2)
N-I- 0: send_tpdu_header: 00 c0 00 00 60
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 02 00 a4 00 04
-I- 0: flush_rx_buffer (5)

two things noticable:

the 'N' being printed by card_emu as waiting time extension
the last TPDU header 02 00 a4 00 04 doesn't look like a TPDU header: The 02 seems wrong, the TPDU likely starts with 00 a4.

situation on "Identive CCID reader" side¶

pySim-shell "export" shows:

update_record 159 ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
update_record 160 ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
update_record 161 ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
# bad file: MF/DF.TELECOM/EF.ADN, Failed to transmit with protocol T0. Transaction failed.
EXCEPTION of type 'RuntimeError' occurred with message: '6881: Functions in CLA not supported - Logical channel not supported'
To enable full traceback, run the following command: 'set debug true'

simtrace2-cardem-pcsc¶

=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 9d 04 22 
=> DATA: flags=1, 00 b2 9d 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 9e 04 22 
=> DATA: flags=1, 00 b2 9e 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 9f 04 22 
=> DATA: flags=1, 00 b2 9f 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 a0 04 22 
=> DATA: flags=1, 00 b2 a0 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 a1 04 22 
=> DATA: flags=1, 00 b2 a1 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 60 
=> DATA: flags=1, 00 c0 00 00 60 : SW=0x6c23, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 02 00 a4 00 04 
<0000> apdu_dispatch.c:112 Unknown APDU case 0
=> DATA: flags=1, 02 00 a4 00 04 : SW=0x6881, len_rx=0

it also agrees that this last APDU is somehow wrong and cannot determine the APDU case.

USB communication¶

last message from SIMtrace to host is "RX DATA" with header flag set and 0200a40004. The card still responds with SW 6881 to that, as obviously the APDU header is invalid.

Files

simtrace2-cardem-16-export-error.pcap	simtrace2-cardem-16-export-error.pcap	336 KB	pcap file containig simtrace USB communication	laforge, 01/25/2022 06:24 PM
wireshark.png	View wireshark.png	98.6 KB		laforge, 01/25/2022 06:26 PM
simtrace2-cardem-16-export-error2.pcap	simtrace2-cardem-16-export-error2.pcap	580 KB		laforge, 01/25/2022 06:35 PM
simtrace2-cardem-16-export-error3.pcap	simtrace2-cardem-16-export-error3.pcap	2.16 MB		laforge, 01/25/2022 06:39 PM
simtrace2-cardem-16-export-error5-ctrl.pcap	simtrace2-cardem-16-export-error5-ctrl.pcap	1.3 MB		laforge, 01/25/2022 07:02 PM
simtrace2-cardem-16-export-error6-ctrl.pcap	simtrace2-cardem-16-export-error6-ctrl.pcap	499 KB		laforge, 01/25/2022 07:14 PM
simtrace2-cardem-16-export-error7-ctrl.pcap	simtrace2-cardem-16-export-error7-ctrl.pcap	156 KB		laforge, 01/25/2022 07:28 PM

Actions

Copy link

Updated by laforge about 2 years ago

some general notes/observations:

there are quite a number of longer APDUs (larger file reads) happening without any problems
during larger files we always use the waiting time extension mechanism and also see the 'N' character printed without any problem

Actions

Copy link

Updated by laforge about 2 years ago

File simtrace2-cardem-16-export-error2.pcap simtrace2-cardem-16-export-error2.pcap added

Next two stuck situations looked different: The reader sends us the TPDU header 00a4000402 (reported in USB trace and also in cardem-pcsc) to which we respond with the procedure byte 0xa4 (at least in USB trace).

The USB OUT transfer of the 'a4' procedure byte also completes on the bus. However, it looks like the reader never gets it?

simtrace2-cardem-pcsc¶

=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3c 
=> DATA: flags=2, 6f 3c : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 12 04 b0 
=> DATA: flags=1, 00 b2 12 04 b0 : SW=0x9000, len_rx=176
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3c 
=> DATA: flags=2, 6f 3c : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 13 04 b0 
=> DATA: flags=1, 00 b2 13 04 b0 : SW=0x9000, len_rx=176
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3c 
=> DATA: flags=2, 6f 3c : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 14 04 b0 
=> DATA: flags=1, 00 b2 14 04 b0 : SW=0x9000, len_rx=176
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3c 
=> DATA: flags=2, 6f 3c : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 15 04 b0 
=> DATA: flags=1, 00 b2 15 04 b0 : SW=0x9000, len_rx=176
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3c 
=> DATA: flags=2, 6f 3c : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 16 04 b0 
=> DATA: flags=1, 00 b2 16 04 b0 : SW=0x9000, len_rx=176
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3c 
=> DATA: flags=2, 6f 3c : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 17 04 b0 
=> DATA: flags=1, 00 b2 17 04 b0 : SW=0x9000, len_rx=176
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02

so no strange apdu header this time.

Actions

Copy link

Updated by laforge about 2 years ago

File simtrace2-cardem-16-export-error3.pcap simtrace2-cardem-16-export-error3.pcap added

next occurrence looks similar to the first one:

-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: flush_rx_buffer (5)
-I- 0: flush_rx_buffer (2)
-I- 0: send_tpdu_header: 00 c0 00 00 24
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 b2 06 04 80
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: flush_rx_buffer (5)
-I- 0: flush_rx_buffer (2)
-I- 0: send_tpdu_header: 00 c0 00 00 24
-I- 0: flush_rx_buffer (5)
-I- 0: send_tpdu_header: 00 b2 07 04 80
-I- 0: flush_rx_buffer (5)
N-I- 0: send_tpdu_header: 00 02 00 a4 04
-I- 0: flush_rx_buffer (5)

-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 24 
=> DATA: flags=1, 00 c0 00 00 24 : SW=0x9000, len_rx=36
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 03 04 80 
=> DATA: flags=1, 00 b2 03 04 80 : SW=0x9000, len_rx=128
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 04 
=> DATA: flags=2, 6f 04 : SW=0x6124, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 24 
=> DATA: flags=1, 00 c0 00 00 24 : SW=0x9000, len_rx=36
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 04 04 80 
=> DATA: flags=1, 00 b2 04 04 80 : SW=0x9000, len_rx=128
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 04 
=> DATA: flags=2, 6f 04 : SW=0x6124, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 24 
=> DATA: flags=1, 00 c0 00 00 24 : SW=0x9000, len_rx=36
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 05 04 80 
=> DATA: flags=1, 00 b2 05 04 80 : SW=0x9000, len_rx=128
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 04 
=> DATA: flags=2, 6f 04 : SW=0x6124, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 24 
=> DATA: flags=1, 00 c0 00 00 24 : SW=0x9000, len_rx=36
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 06 04 80 
=> DATA: flags=1, 00 b2 06 04 80 : SW=0x9000, len_rx=128
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 04 
=> DATA: flags=2, 6f 04 : SW=0x6124, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 24 
=> DATA: flags=1, 00 c0 00 00 24 : SW=0x9000, len_rx=36
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 07 04 80 
=> DATA: flags=1, 00 b2 07 04 80 : SW=0x9000, len_rx=128
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 02 00 a4 04 
<0000> apdu_dispatch.c:112 Unknown APDU case 0
=> DATA: flags=1, 00 02 00 a4 04 : SW=0x6d00, len_rx=0

so again the strange tpdu header, this time with two extra bytes '00 02'

Actions

Copy link

Updated by laforge about 2 years ago

File simtrace2-cardem-16-export-error5-ctrl.pcap simtrace2-cardem-16-export-error5-ctrl.pcap added
% Done changed from 0 to 10

It seems like I can very clearly trigger the behavior if I send random control requests like those generated by simtrace2-list or lsusb -v while the cardem session is in progress.

-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: send_tpdu_header: 00 c0 00 00 24
-I- 0: send_tpdu_header: 00 b2 07 04 0f
-I- 0: send_tpdu_header: 00 a4 00 04 02
-W- Sta 0x888A8 [0] -W- _ -W- USBDDriver_GetDescriptor: Unknown descriptor type (10)
-W- Sta 0x888A8 [0] -W- _ -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
-E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
-E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX

seems like we might want to process thos requests at a lower priority?

Actions

Copy link

Updated by laforge about 2 years ago

laforge wrote in #note-4:

It seems like I can very clearly trigger the behavior if I send random control requests like those generated by simtrace2-list or lsusb -v while the cardem session is in progress.

[...]

seems like we might want to process thos requests at a lower priority?

Interestingly, the CCID reader seems to be making up random status words?

update_record 7 ffffffffffffffffffffffffffffff
# bad file: MF/DF.TELECOM/EF.ECCP, Failed to transmit with protocol T0. Transaction failed.
EXCEPTION of type 'SwMatchError' occurred with message: 'SW match failed! Expected 9000 and got 6a60.'
To enable full traceback, run the following command: 'set debug true'

but the last status word as seen in the USB protocol trace of simtrace was 6a82!

Actions

Copy link

Updated by laforge about 2 years ago

File simtrace2-cardem-16-export-error6-ctrl.pcap simtrace2-cardem-16-export-error6-ctrl.pcap added

even at fi/di=372 I can generate a communication break-down when executing 4-5x simtrace-list while 'export' is running. So clearly something is severely broken here. there is nothing actually going wrong on the 7816 UART side, at least not that I can tell.

No weird messed up TPDU headers, no waiting time extension, ...

-I- 0: send_tpdu_header: 00 c0 00 00 23
-I- 0: send_tpdu_header: 00 b2 f9 04 22
-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: send_tpdu_header: 00 c0 00 00 23
-I- 0: send_tpdu_header: 00 b2 fa 04 22
-I- 0: send_tpdu_header: 00 a4 00 04 02

=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 f7 04 22 
=> DATA: flags=1, 00 b2 f7 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 f8 04 22 
=> DATA: flags=1, 00 b2 f8 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 f9 04 22 
=> DATA: flags=1, 00 b2 f9 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 fa 04 22 
=> DATA: flags=1, 00 b2 fa 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 7f 10 
=> DATA: flags=2, 7f 10 : SW=0x612e, len_rx=0

Actions

Copy link

Updated by laforge about 2 years ago

File simtrace2-cardem-16-export-error7-ctrl.pcap simtrace2-cardem-16-export-error7-ctrl.pcap added

This becomes even more bizarre the more I play with it.

The application via the CCID reader executes:

-> 00a4000402 6f3a
<- 6123: 
-> 00c0000023 
<- 9000: 6221820542210022fa83026f3aa506d00130d2010f8a01058b036f0603800221348800
-> 00b23a0422 
<- 9000: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
update_record 58 ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
-> 00a4000402 6f3a
<- 6123: 
-> 00c0000023 
<- 9000: 6221820542210022fa83026f3aa506d00130d2010f8a01058b036f0603800221348800
-> 00b23b0422 
<- 9000: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
update_record 59 ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
-> 00a4000402 6f3a
<- 6123: 
-> 00c0000023 
<- 9000: 6221820542210022fa83026f3aa506d00130d2010f8a01058b036f0603800221348800
-> 00b23c0422 
<- 9000: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
update_record 60 ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
-> 00a4000402 6f3a
<- 6123: 
# bad file: MF/DF.TELECOM/EF.ADN, Failed to transmit with protocol T0. Transaction failed.
-> 00a4000402 7f10
<- 6b00: 
EXCEPTION of type 'RuntimeError' occurred with message: '6b00: Checking errors - Wrong parameter(s) P1-P2'

On the simtrace side, we see:

=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 39 04 22 
=> DATA: flags=1, 00 b2 39 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 3a 04 22 
=> DATA: flags=1, 00 b2 3a 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 3b 04 22 
=> DATA: flags=1, 00 b2 3b 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 00 00 23 
=> DATA: flags=1, 00 c0 00 00 23 : SW=0x9000, len_rx=35
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 b2 3c 04 22 
=> DATA: flags=1, 00 b2 3c 04 22 : SW=0x9000, len_rx=34
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 a4 00 04 02 
=> DATA: flags=1, 00 a4 00 04 02 : -> 01 06 00 00 00 00 10 00 02 00 00 00 02 00 6f 3a 
=> DATA: flags=2, 6f 3a : SW=0x6123, len_rx=0
-> 01 06 00 00 00 00 13 00 01 00 00 00 05 00 00 c0 23 00 a4 
=> DATA: flags=1, 00 c0 23 00 a4 : SW=0x6b00, len_rx=0

So the last APDU header should be 00a4000402 but the carem firmware reports it as 00c02300a4, if there is are some control endpoint requests happening concurrently.

Actions

Copy link

Updated by laforge about 2 years ago

ok, at least the control-endpoint induced problems seem to be avoidable by setting reasonable interrupt priorities: ISO7816-UARTs highest, console lowest, USB,ADC,GPIO in-between.

Actions

Copy link

Updated by laforge about 2 years ago

% Done changed from 10 to 60

I cannot reproduce the problems anymore in my laforge/202201 branch of simtrace2.git using the exact identical hardware setup (not jut models, but exact parts).

One patch that makes a big difference here is https://gerrit.osmocom.org/c/simtrace2/+/26995 (using IRQ priorities to make sure UART always has highest priority and USB/console lowest).

Actions

Copy link

#10

Updated by laforge about 2 years ago

Trying some low-level UART debugging rXX and tXX for each received/transmitted byte:

successful case:

r00 rA4 r00 r04 r02 -I- 0: send_tpdu_header:(00 a4 00 04 02) tA4 r6F r3C t61 t23 
r00 rC0 r00 r00 r23 -I- 0: send_tpdu_header:(00 c0 00 00 23) tC0 t62 t21 t82 t05 t42 t21 t00 tB0 t1E t83 t02 t6F t3C tA5 t06 tD0 t01 t30 tD2 t01 t0F t8A t01 t05 t8B t03 t6F t06 t05 t80 t02 t14 tA0 t88 t00 t90 t00 
r00 rB2 r13 r04 rB0 -I- 0: send_tpdu_header:(00 b2 13 04 b0) tB2 t00 Nt60 tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF tFF t90 t00

unsuccessful case:

r00 rA4 r00 r04 r02 -I- 0: send_tpdu_header:(00 a4 00 04 02) tA4 rA0 rA4 r00 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
r00 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
r02 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
r3F -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
r00 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
t6A Nt60 t82 
rA0 rA4 r00 r00 r02 -I- 0: send_tpdu_header:(a0 a4 00 00 02) tA4 rA0 rA4 r00 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
r00 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
r02 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
r3F -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
r00 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
t6E t00

So it clearly shows

APDU header is succesfully received and handed to host
procedure byte is transmitted
but then we receive "A0 A4 00 00 02 3F 00" instead of just "3F 00"
- we were waiting for two bytes (expecting 3F 00) but received more
- A0 A4 were the first, so we pass them to the host
- further bytes are ignored as they are invalid in the WAIT_TX TPDU state
we then get "6E 00" from the host (A0 A4 is not a file) and transmit it to the UART (modem/phone/reader)

It looks almost as if the UART receiver would be receiving the APDU header which we had already received before. but A0 A4 instad of "00 A4".

We already wait for completion of the transmit before enabling the Rx.

I'm doing the "rXX" printing from card_emu_process_rx_byte() which is in the main thread, which drains the ring buffer between Rx interrupt and main thread. So those bytes could also be in the ring buffer.

Actions

Copy link

#11

Updated by laforge about 2 years ago

shifting the printf directly into the UART interrupt handler shows that the ringbuffer-induced delay is not to be blamed:

r00 rA4 r00 r04 r02 -I- 0: send_tpdu_header:(00 a4 00 04 02) tA4 rA0 rA4 r00 r00 r02 r3F r00 -E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
-E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
-E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
-E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
-E- 0: process_byte_tpdu() in invalid TPDU state WAIT_TX
t6A Nt60 t82

so we really receive those extra 5 bytes "A0 A4 00 00 02" on the uart before we receive the expected "3F 00" !

Actions

Copy link

#12

Updated by laforge over 1 year ago

Status changed from In Progress to Stalled

Actions

Copy link

Also available in: Atom PDF

Project

General

Profile

SIM card related Projects » SIMtrace 2

Custom queries

Bug #5419

cardem errors with higher baud rate

log output of cardem firmware¶

situation on "Identive CCID reader" side¶

simtrace2-cardem-pcsc¶

USB communication¶

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

simtrace2-cardem-pcsc¶

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

Updated by laforge about 2 years ago

Updated by laforge over 1 year ago