Replicant

Working Orange SIM:

02-06 13:47:56.903  2786  2786 D SubscriptionInfoUpdater: handleMessage : <EVENT_SIM_LOCKED_QUERY_ICCID_DONE> SIM1
02-06 13:47:56.903  2786  2786 D SubscriptionInfoUpdater: sIccId[0] = 89330178269030170700
02-06 13:47:56.903  2786  2786 D SubscriptionInfoUpdater: All IccIds query complete
02-06 13:47:56.903  2786  2786 D SubscriptionInfoUpdater: updateSubscriptionInfoByIccId:+ Start
02-06 13:47:56.903  2786  2786 D SubscriptionInfoUpdater: insertedSimCount = 1

Whereas on the nonworking SFR SIM we have:

02-06 13:45:10.553  2773  2773 D SubscriptionInfoUpdater: handleMessage : <EVENT_SIM_LOCKED_QUERY_ICCID_DONE> SIM1
02-06 13:45:10.553  2773  2773 D SubscriptionInfoUpdater: Query IccId fail: java.lang.NullPointerException: Attempt to read from null array
02-06 13:45:10.553  2773  2773 D SubscriptionInfoUpdater: sIccId[0] =
02-06 13:45:10.553  2773  2773 D SubscriptionInfoUpdater: All IccIds query complete
02-06 13:45:10.553  2773  2773 D SubscriptionInfoUpdater: updateSubscriptionInfoByIccId:+ Start
02-06 13:45:10.553  2773  2773 D SubscriptionInfoUpdater: insertedSimCount = 0

And for the First STK message on the nonworking SFR SIM we have:

02-06 13:44:53.590  1941  2192 D use-Rlog/RLOG-RIL-IPC: xmm626_sec_modem_fmt_recv: Received FMT message
02-06 13:44:53.590  1941  2192 D use-Rlog/RLOG-RIL-IPC: xmm626_sec_modem_fmt_recv: Message: aseq=0xff, command=IPC_SAT_PROACTIVE_CMD, type=IPC_TYPE_INDI, size=18
02-06 13:44:53.590  1941  2192 D use-Rlog/RLOG-RIL-IPC: ================================= IPC FMT data =================================
02-06 13:44:53.590  1941  2192 D use-Rlog/RLOG-RIL-IPC: [0000]   10 00 D0 0E 81 03 01 05  00 82 02 81 82 99 03 00   ........ ........
02-06 13:44:53.590  1941  2192 D use-Rlog/RLOG-RIL-IPC: [0010]   01 02                                              ..
02-06 13:44:53.590  1941  2192 D use-Rlog/RLOG-RIL-IPC: ================================================================================
02-06 13:44:53.590  1941  2192 D use-Rlog/RLOG-RIL-IPC: Unhandled IPC FMT message: IPC_SAT_PROACTIVE_CMD

I looked rapidely at the log of the Orange SIM, however I didn't find IccID (89330178269030170700) in the samsung-ipc messages (I tried to look for 33 and 9833 as this is how it appears in simtrace traces). I'll have to investigate more on this side. I also looked at the Java side of the RIL but didn't find enough information yet on how the SIM filesystem abstraction work.

Here we can find the ICCID (98:33:10:87:62:09:03:71:70:00):

02-06 13:47:56.902  1942  2203 D use-Rlog/RLOG-RIL-IPC: xmm626_sec_modem_fmt_recv: Received FMT message
02-06 13:47:56.902  1942  2203 D use-Rlog/RLOG-RIL-IPC: xmm626_sec_modem_fmt_recv: Message: aseq=0x26, command=IPC_SEC_RSIM_ACCESS, type=IPC_TYPE_RESP, size=13
02-06 13:47:56.902  1942  2203 D use-Rlog/RLOG-RIL-IPC: ================================= IPC FMT data =================================
02-06 13:47:56.902  1942  2203 D use-Rlog/RLOG-RIL-IPC: [0000]   90 00 0A 98 33 10 87 62  09 03 71 70 00            ....3..b ..qp.
02-06 13:47:56.902  1942  2203 D use-Rlog/RLOG-RIL-IPC: ================================================================================

Here's (still for the Orange SIM) the command to select the EF.ICCID file (0x2fe2):

02-06 13:47:56.895  1942  2207 D use-Rlog/RLOG-RIL-IPC: xmm626_sec_modem_fmt_send: Sent FMT message
02-06 13:47:56.895  1942  2207 D use-Rlog/RLOG-RIL-IPC: xmm626_sec_modem_fmt_send: Message: mseq=0x26, command=IPC_SEC_RSIM_ACCESS, type=IPC_TYPE_GET, size=6
02-06 13:47:56.895  1942  2207 D use-Rlog/RLOG-RIL-IPC: ================================= IPC FMT data =================================
02-06 13:47:56.895  1942  2207 D use-Rlog/RLOG-RIL-IPC: [0000]   B0 E2 2F 00 00 0A                                  ../...
02-06 13:47:56.895  1942  2207 D use-Rlog/RLOG-RIL-IPC: ================================================================================

I'm not totally sure about the last one. I'll look into the code to confirm. The ril_request_sim_io has some insights on how it works:

int ril_request_sim_io(void *data, size_t size, RIL_Token token)
{
[...]
    memset(&request_header, 0, sizeof(request_header));
    request_header.command = sim_io->command;
    request_header.file_id = sim_io->fileid;
    request_header.p1 = sim_io->p1;
    request_header.p2 = sim_io->p2;
    request_header.p3 = sim_io->p3;

    sim_io = NULL;

    request_size = ipc_sec_rsim_access_size_setup(&request_header, sim_io_data, sim_io_size);
    if (request_size == 0)
        goto error;

    request_data = ipc_sec_rsim_access_setup(&request_header, sim_io_data, sim_io_size);
    if (request_data == NULL)
        goto error;
[...]
    rc = ipc_fmt_send(ipc_fmt_request_seq(token), IPC_SEC_RSIM_ACCESS, IPC_TYPE_GET, request_data, request_size);
    if (rc < 0)
        goto error;
}

After reading more about the protocol, I found out that the packets order didn't make any sense in the trace I got, because I didn't notice that wireshark didn't order them by time by default for some reason.

This is why I had a hard time understanding the link between them.

Once fixed, here's now what the part that the interesting part from the pcap trace:

No    Time        Protocol    Length    Info
13    25.070965442    GSM SIM        67    ISO/IEC 7816-4 SELECT File EF.ICCID : Response ready, Response length is 27 
14    25.071061474    GSM SIM        92    ISO/IEC 7816-4 GET RESPONSE 
15    25.081092359    GSM SIM        75    ISO/IEC 7816-4 READ BINARY Offset=0 

In the third packet/TPDU we can see in wireshark the following as APDU payload wihich is the SIM ID (ICCID): 98330163019072174071
which is transmited as 98 33 01 63 01 90 72 17 40 71 on the wire.

We also see more clearly that the SIM ID is queried right at the beginning, so it most probably cannot be related to Sim Toolkit(STK) as it appear way later in the conversation between the SIM and the modem.

The trace has precise timestamps in the Ethernet encapsulation. I'll use that to corelate it with the logcat -b radio.

Here's the trace from the very beginning:

No    Time        Protocol    Length    Info
8    23.809625449    GSM SIM    79    3 9e : 00f5 
9    25.048405378    GSM SIM    67    ISO/IEC 7816-4 SELECT File MF 
10    25.062601808    GSM SIM    67    ISO/IEC 7816-4 SELECT /EF.ELP : Response ready, Response length is 30 
11    25.062696862    GSM SIM    95    ISO/IEC 7816-4 GET RESPONSE 
12    25.062775503    GSM SIM    75    ISO/IEC 7816-4 READ BINARY Offset=0 
13    25.070965442    GSM SIM    67    ISO/IEC 7816-4 SELECT File EF.ICCID : Response ready, Response length is 27 
14    25.071061474    GSM SIM    92    ISO/IEC 7816-4 GET RESPONSE 
15    25.081092359    GSM SIM    75    ISO/IEC 7816-4 READ BINARY Offset=0 
[...]

In the last part of the trace it tries a second time to get the ICCID but fails:

No    Time        Protocol    Length    Info
732    42.471309922    GSM SIM        67    ISO/IEC 7816-4 SELECT /EF.ICCID 
733    42.471375572    GSM SIM        92    ISO/IEC 7816-4 GET RESPONSE 

Then nothing happens. To work a "READ BINARY Offset=0" would be required.

• For the working Orange SIM, Reading a second time the ICCID works (it does a "READ BINARY Offset=0"). It is also the last SIM file read in the trace.
• The non-working trace in the bug #1868 exibit a similar behavior: the "READ BINARY Offset=0" is not present in the second read of the ICCID file. It's also the last file read in the trace.

The SIM tookkit messages names make me think that the card is probably waiting for an answer from the modem for one of the SIM initiated STK commands

How to diff the files easily:

$ tshark -r maguro-takju-imm76i.pcapng.gz | sed 's#.*GSM SIM ##' > maguro-takju-imm76i.pcapng.txt
$ tshark -r maguro-replicant.pcapng.gz | sed 's#.*GSM SIM ##' > maguro-replicant.pcapng.txt
$ meld maguro-takju-imm76i.pcapng.txt maguro-replicant.pcapng.txt

I've got some malformed packets in the stock capture, I'll re-do it. Normally the only diff that should show up would be that one which is at the very end as it was in previous capture (where I forgot to capture a logcat -b radio at the same time) :

For the stock image:

67 ISO/IEC 7816-4 SELECT File EF.ECC 
98 ISO/IEC 7816-4 GET RESPONSE 
85 ISO/IEC 7816-4 READ RECORD RecordNr=1 
85 ISO/IEC 7816-4 READ RECORD RecordNr=2 

For Replicant image:

67 ISO/IEC 7816-4 SELECT /EF.ICCID 
92 ISO/IEC 7816-4 GET RESPONSE 

I ended up using a grep -v to compare the two traces:

.PHONY: all

all: maguro-replicant.pcapng.txt maguro-takju-imm76i.pcapng.txt
    meld $^ &

%.txt: %.gz
    tshark -r $< -V \
           | grep -v "^ *Arrival Time: " \
           | grep -v "^ *Epoch Time: " \
           | grep -v "^ *Identification: " \
           | grep -v "^ *Header checksum: " \
           | grep -v "^User Datagram Protocol, Src Port: [0-9]\+, Dst Port: [0-9]\+" \
           | grep -v "^ *Source Port: [0-9]\+" \
           | grep -v "^ *\[Time delta from previous captured frame: .*\]" \
           | grep -v "^ *\[Time delta from previous displayed frame: .*\]" \
           | grep -v "^ *\[Time since reference or first frame: .*\]" \
           > $@

It has shown me that there is no difference at all in the traces before it asking again for the EF.ECCID when using Replicant (whereas with the stock OS, it asks for EF.ECC) as it was said before in the note 20 of this bugreport.

I tried with a stock Replicant 4.2, and the GUI was asking for a PIN.

=> The way to go is to try to bisect that.

There is a strange part of code that does some parsing of TLVs in the data coming from the SIM in file hardware/ril/samsung-ril/sim.c, which is completely unnecessary.
In the function ipc_sec_rsim_access, in the switch(sim_io->command) part, in the SIM_COMMAND_GET_RESPONSE case.
It thinks tag 0x88 exists, and then assumes that the TLV right before it is the size tag. These two assumptions are sometimes wrong.
The fix is to get rid of all that code and just send the data as-is to the java RIL because it can parse TLVs by itself.

So I guess bug fixed. We should get this tested on more devices. I will make a patch tomorrow.

Edit:

The problematic code was commited by PaulK here a7ff1df1869ce543171a6ee92cbf821647b1bf7d.
I suspect it was done to override some file permissions or something, must ask Paul.