Using NFC Library in 'raw' APDU mode : how to set FWI/FWTX?

[BrianW]

Custom device using nrf5340, with NFC card emulation functionality.

To use the NFC, I understand that I should use the supplied nfc_t4t library (binary) and its api. I have this working ok for type 4 card emulation using the NDEF application functionality built in to the library..

I now need to create an application that will emulate other functions, and so I am trying to the use the library in 'raw APDU' mode. This is basically working, but I have run into a timeout issue : certain elements of my APDU processing can take some 10's of ms, and this is apparently causing my nfc reader to timeout its request. This causes the library to have some issues : I get logs like this:

[00:05:13.375,488] <err> nfc_platform: Tried to read data pointer: 4 bytes, read 0.
[00:05:13.375,488] <err> nfc_platform: Reading nfc ring buffer failed, resetting ring buffer.

 I think these are basically when I do the nfc_t4t_response_pdu_send() call to send the response PDU. Any ideas on what this means for my operation?

The reader never manages to get a valid response, this seems to be related to the time it takes for my code to process the APDU (around 35ms for a basic select operation, due to it being sent to a ISO7816 contact card for processing...). In the NFC spec I see this:

"When the Card Emulator needs more time than the defined FWT to process the received block, it uses an S(WTX) request for a waiting time extension. An S(WTX) request contains a 1-byte INF field as specified in Table 84"

How can I tell the library that I want it to send this S(WTX) frame? It seems it needs to be sent for each received command? The only param I see to set is the FWI (which sets the max FWT as I understand it). When I try to set this to the max (before doing nfc_t4t_setup()) :

                uint32_t fwi = NFC_T4T_FWI_MAX_VAL_EMV;

                if ((ret=nfc_t4t_parameter_set(NFC_T4T_PARAM_FWI, &fwi, sizeof(fwi)))!=0) {

                    log_warn("nfcmgr: t4t fwi set fails (%d)",ret);

                }

Then it gives me an error -22

Doing a get of the FWI_MAX says its set to 4.

Is there a way to get the library to tell the reader that I want to increase the waiting timeout for a specific received command?

thanks

[BrianW]

BrianW said:

Then it gives me an error -22

Ok, I have fixed my problem with nfc_t4t_parameter_set(), it needs the parameter value to be a uint8_t.

So now I can set the FWI to be 8 max. By my calculation, this should make the reader apply a FWT of around 77ms

(FWT = (256 x 16/Fc) x 2^FWI, Fc=13.56MHz, FWI=8 -> 77ms)

The FWI is correctly taken into acount on the reader (it reports it as 8, and calculates the FWT=77ms)

However, any delay in responding that is over 2-3ms fail to work.... and gets the same logs:

[00:05:13.375,488] <err> nfc_platform: Tried to read data pointer: 4 bytes, read 0.
[00:05:13.375,488] <err> nfc_platform: Reading nfc ring buffer failed, resetting ring buffer.

So, maybe its not the reader timing out, but the library? Can anyone shed some light on the this lib? As its supplied only as a binary blob, I can't see what is actually happening....

[Marte Myrvold]

Hi,

Great to hear that you fixed the problem with nfc_t4t_parameter_set().

I will ask about the other issue internally. Can you upload the complete device log?

Best regards,
Marte

[BrianW]

Marte Myrvold said:

By default, the frame wait time in the T4T library is set to about 4.8 ms, as the Frame Wait Time (FWI) parameter is 4. If the application does not provide the response PDU within this time, the tag automatically transmits a request to extend the wait time. It will keep sending the request until the response PDU is ready or the reader refuses to accept more extensions. 

ok, this is good news and what I hoped would be the behaviour.

Marte Myrvold said:

You can use a higher FWI by changing it through nfc_t4t_parameter_set(). The max value is defined by NFC_T4T_PARAM_FWI_MAX and should be 8 for the nRF5340.

This is exactly what my code does before calling setup/emulation_start():

                // Increase the wait time for any NFC readers as APDU processing may be slower (especially if talking to ISO7816 card)

                uint8_t fwi = 8;   // NFC_T4T_FWI_MAX_VAL_EMV;     // ==7 for EMV spec. 8 is the max the lib will accept.

                if ((ret=nfc_t4t_parameter_set(NFC_T4T_PARAM_FWI, &fwi, sizeof(fwi)))!=0) {

                    log_warn("nfcmgr: t4t fwi set fails (%d)",ret);

                }

                // register with nfc_t4t

                if ((ret = nfc_t4t_setup(_nfc_t4t_apdu_cb, &_ctx))!=0) {

                    log_warn("nfcmgr : t4t fail setup for APDU (%d)", ret);

                    // This is fatal error

                    return false;

                }

                if ((ret = nfc_t4t_emulation_start())!=0) {

                    log_warn("nfcmgr: t4t apdu emul start fails (%d)",ret);

                }

                size_t plen=sizeof(fwi);

                if ((ret = nfc_t4t_parameter_get(NFC_T4T_PARAM_FWI, &fwi, &plen))!=0) {

                    log_warn("nfcmgr: t4t fwi get fails (%d)",ret);

                }

                log_warn("nfcmgr : type 4 APDU started, fwi=%d", fwi);

And the fwi value is retrieved by the log is indeed set to 8, and the reader confirms this (if I do a read using application code that responds immediately)

However, whenever the response from my code takes longer than around 4-5ms (delay to call nfc_t4t_response_pdu_send()), the reader never seems to get a response at all.... Is there a way to see a log from the library showing its operation?

Maybe it doesn't like the 'requst for extension' message? 

Marte Myrvold said:

If the application does not provide the response PDU within this time, the tag automatically transmits a request to extend the wait time

Is this always sent after 4.8ms, or after the updated FWT (77ms)?

Thanks!

[Marte Myrvold]

Hi,

I will ask the developers about this.

Which version of the nRF Connect SDK are you using?

Best regards,
Marte

[BrianW]

Marte Myrvold said:

Which version of the nRF Connect SDK are you using?

2.9.0

[Marte Myrvold]

Hi,

Thank you, I have forwarded this to the developers. I cannot comment on the schedule since this needs to be prioritized against other tasks. Please get in touch with RSM if this is critical.

Best regards,
Marte

[Marte Myrvold]

Hi,

Regarding logging, you can enable logs from the NFCT driver, which should show most NFC events on the HW interface level. You can use NRFX_NFCT_LOG and set the log level to debug in the system.

Best regards,
Marte

[BrianW]

I enabled the logging

CONFIG_NRFX_NFCT_LOG=y

This gave me this for a test (where it takes around 35ms to process the command):

[00:03:00.368,896] <wrn> app: nfc_requestor : NFC field on for APDU routing START
[00:03:00.368,988] <wrn> app: ISO7816: START - card already open
[00:03:00.369,720] <inf> NRFX_NFCT: Tx start
[00:03:00.370,422] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2028, data_size 20
[00:03:00.370,422] <err> nfc_platform: cb_work: no data.
[00:03:00.385,864] <inf> NRFX_NFCT: Tx start
[00:03:00.395,019] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2028, data_size 20
[00:03:00.395,019] <err> nfc_platform: cb_work: no data.
[00:03:00.395,904] <inf> NRFX_NFCT: Tx start
[00:03:00.408,569] <inf> NRFX_NFCT: Tx start
[00:03:00.408,599] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2015, data_size 33

-> reception of the APDU command

[00:03:00.414,642] <inf> NRFX_NFCT: Tx start
[00:03:00.444,641] <inf> app: iso7816: cmd (00:A4:04:00 lc=7, le=0) sent OK, response (6A:82 le=0) bytes
[00:03:00.444,732] <inf> app: ISO7816: routing PROCESS (next) returns successful response of size 2

[00:03:00.444,976] <wrn> app: nfc_requestor : NFC APDU routed OK cmd (00a4040007d276000085010100) response (6A:82 le=2)
[00:03:00.445,098] <wrn> app: nfcmgr:cmd rx@180408, process@180408, resp@180445, now@180445

-> response sent back to nfct lib (took 37ms to generate)

[00:03:00.493,194] <inf> NRFX_NFCT: Tx start

-> could this be it sent to the reader?

[00:03:01.574,798] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2028, data_size 20
[00:03:01.574,829] <err> nfc_platform: cb_work: no data.
[00:03:01.574,920] <wrn> app: nfc_requestor : NFC field off for APDU routing END

-> but reader doesn't seem to see or process it, and 81ms later it gives up

The only log from the NRFC_NFCT driver appears to be the "Tx start" INFO level one.... Should there be more? why always Tx (and never Rx)?

[BrianW]

BrianW said:

The only log from the NRFC_NFCT driver appears to be the "Tx start" INFO level one.... Should there be more? why always Tx (and never Rx)?

Ok,because the other logs are all debug level. I updated them to INFO, and also added the size of the tx or rx data block. This gives me:

[00:01:21.869,384] <inf> NRFX_NFCT: Field detected
[00:01:21.870,422] <inf> NRFX_NFCT: Field detected
[00:01:21.870,483] <inf> NRFX_NFCT: Field detected
[00:01:21.884,185] <inf> NRFX_NFCT: Selected
[00:01:21.884,216] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2028, data_size 20
[00:01:21.884,216] <err> nfc_platform: cb_work: no data.
[00:01:21.884,307] <wrn> app: nfc_requestor : NFC field on for APDU routing START
[00:01:21.884,368] <wrn> app: ISO7816: START - card already open
[00:01:21.885,131] <inf> NRFX_NFCT: Tx start2 (5)
[00:01:21.885,131] <inf> NRFX_NFCT: Rx fend evt (2)
[00:01:21.885,162] <inf> NRFX_NFCT: Tx start evt (5)
[00:01:21.885,803] <inf> NRFX_NFCT: Tx fend evt (5)
[00:01:21.885,803] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2028, data_size 20
[00:01:21.885,833] <err> nfc_platform: cb_work: no data.
[00:01:21.896,820] <inf> NRFX_NFCT: Tx start2 (1)
[00:01:21.896,850] <inf> NRFX_NFCT: Rx fend evt (1)
[00:01:21.896,881] <inf> NRFX_NFCT: Tx start evt (1)
[00:01:21.897,155] <inf> NRFX_NFCT: Tx fend evt (1)
[00:01:21.905,944] <inf> NRFX_NFCT: Selected
[00:01:21.905,975] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2028, data_size 20
[00:01:21.905,975] <err> nfc_platform: cb_work: no data.
[00:01:21.906,890] <inf> NRFX_NFCT: Tx start2 (5)
[00:01:21.906,890] <inf> NRFX_NFCT: Rx fend evt (2)
[00:01:21.906,951] <inf> NRFX_NFCT: Tx start evt (5)
[00:01:21.907,562] <inf> NRFX_NFCT: Tx fend evt (5)
[00:01:21.913,787] <inf> NRFX_NFCT: Tx start2 (2)
[00:01:21.913,787] <inf> NRFX_NFCT: Rx fend evt (14)
[00:01:21.913,818] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2015, data_size 33
[00:01:21.918,579] <inf> NRFX_NFCT: Tx start evt (2)
[00:01:21.918,945] <inf> NRFX_NFCT: Tx fend evt (2)
[00:01:21.919,860] <inf> NRFX_NFCT: Tx start2 (2)
[00:01:21.919,860] <inf> NRFX_NFCT: Rx fend evt (2)
[00:01:21.949,890] <inf> app: iso7816: cmd (00:A4:04:00 lc=7, le=0) sent OK, response (6A:82 le=0) bytes
[00:01:21.949,981] <inf> app: ISO7816: routing PROCESS (next) returns successful response of size 2

[00:01:21.950,225] <wrn> app: nfc_requestor : NFC APDU routed OK cmd (00a4040007d276000085010100) response (6A:82 le=2)
[00:01:21.950,347] <wrn> app: nfcmgr:cmd rx@81913, process@81913, resp@81950, now@81950
[00:01:21.997,161] <inf> NRFX_NFCT: Tx start evt (2)
[00:01:21.997,497] <inf> NRFX_NFCT: Tx fend evt (2)
[00:01:21.998,413] <inf> NRFX_NFCT: Tx start2 (3)
[00:01:21.998,413] <inf> NRFX_NFCT: Rx fend evt (2)
[00:01:21.998,474] <inf> NRFX_NFCT: Tx start evt (3)
[00:01:21.998,901] <inf> NRFX_NFCT: Tx fend evt (3)
[00:01:21.999,816] <inf> NRFX_NFCT: Rx fend evt (2)
[00:01:22.943,023] <inf> NRFX_NFCT: Field lost
[00:01:22.943,084] <err> nfc_platform: cb_work entry : ring buffer size 2048, free space 2028, data_size 20
[00:01:22.943,084] <err> nfc_platform: cb_work: no data.
[00:01:22.943,176] <wrn> app: nfc_requestor : NFC field off for APDU routing END
[00:01:22.943,237] <inf> app: ISO7816: routing END

I guess the 2 byte tx messages are the 'please wait' generated automatically by the library?

And it seems like the response (3 bytes) is transmitted at 00:01:21.998,413-901 (Tx start evt, Tx fend evt); but the reader isn't seeing it. Any ideas?

[BrianW]

With a little more logging info (including the contents of the buffers), I think the library is not accepting my response, and the tx of size 3 is in fact a WTX S-block of some kind around the timeout time (occurs 85ms after the reception of the command).

[00:04:09.985,107] <inf> NRFX_NFCT: Field detected
[00:04:09.998,809] <inf> NRFX_NFCT: Selected
[00:04:09.998,901] <wrn> app: nfc_requestor : NFC field on for APDU routing START
[00:04:09.998,992] <wrn> app: ISO7816: START - card already open
[00:04:09.999,786] <inf> NRFX_NFCT: Rx fend evt (2) [05 78 ]
[00:04:09.999,877] <inf> NRFX_NFCT: Tx start evt (5) [05 78 80 82 02 ]
[00:04:10.000,427] <inf> NRFX_NFCT: Tx fend evt (5)
[00:04:10.010,345] <inf> NRFX_NFCT: Rx fend evt (1) [c2 ]
[00:04:10.010,375] <inf> NRFX_NFCT: Tx start evt (1) [c2 ]
[00:04:10.010,620] <inf> NRFX_NFCT: Tx fend evt (1)
[00:04:10.019,409] <inf> NRFX_NFCT: Selected
[00:04:10.020,385] <inf> NRFX_NFCT: Rx fend evt (2) [05 78 ]
[00:04:10.020,477] <inf> NRFX_NFCT: Tx start evt (5) [05 78 80 82 02 ]
[00:04:10.020,996] <inf> NRFX_NFCT: Tx fend evt (5)
[00:04:10.027,130] <inf> NRFX_NFCT: Rx fend evt (14) [02 00 a4 04 00 07 d2 76 00 00 85 01 01 00 ]
[00:04:10.031,799] <inf> NRFX_NFCT: Tx start evt (2) [f2 01 ]
[00:04:10.032,104] <inf> NRFX_NFCT: Tx fend evt (2)
[00:04:10.033,050] <inf> NRFX_NFCT: Rx fend evt (2) [f2 01 ]
[00:04:10.063,293] <inf> app: iso7816: cmd (00:A4:04:00 lc=7, le=0) sent OK, response (6A:82 le=0) bytes
[00:04:10.063,385] <inf> app: ISO7816: routing PROCESS (next) returns successful response of size 2

[00:04:10.063,629] <wrn> app: nfc_requestor : NFC APDU routed OK cmd (00a4040007d276000085010100) response (6A:82 le=2)
[00:04:10.063,751] <wrn> app: nfcmgr:cmd rx@250027, process@250027, resp@250063, now@250063
[00:04:10.110,351] <inf> NRFX_NFCT: Tx start evt (2) [f2 01 ]
[00:04:10.110,656] <inf> NRFX_NFCT: Tx fend evt (2)
[00:04:10.111,633] <inf> NRFX_NFCT: Rx fend evt (2) [f2 01 ]
[00:04:10.111,694] <inf> NRFX_NFCT: Tx start evt (3) [f2 01 91 ]
[00:04:10.112,091] <inf> NRFX_NFCT: Tx fend evt (3)
[00:04:10.113,037] <inf> NRFX_NFCT: Rx fend evt (2) [f2 11 ]
[00:04:11.049,316] <inf> NRFX_NFCT: Field lost
[00:04:11.049,438] <wrn> app: nfc_requestor : NFC field off for APDU routing END
[00:04:11.049,530] <inf> app: ISO7816: routing END

I see the ATS being sent (twice...) as TL T0 TA TB TC ( values 05 78 80 82 02 look reasonable, and set the FWI to 8 as expected)

Then the tx of [f2 02] and rx of same are the S-block WTX request and responses...

But I can't understand 

- why no sending of the response I submit to the library (at 4:10:063 timestamp, 36ms after the command was received)

- the last S-block of length 3  [f2 01 91] - what is the extra byte of 0x91? and the response of [f2 11] is a protocol error for me!