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:

Can you upload the complete device log?

There are no other NFC library related related logs. Below you have a complete sequence with my application logs and my notes about what's happening. 

[00:00:33.404,754] <wrn> app: ***** NFC enable T4T APDU ******
[00:00:33.404,876] <wrn> app: nfcmgr : type 4 APDU started, fwi=8

->FWI is set successfully to 8 (==77ms FWT)

[00:00:44.111,541] <wrn> app: nfc_requestor : NFC field on for APDU routing START

->Got NFC_T4T_EVENT_FIELD_ON event in callback

[00:00:44.151,153] <wrn> app: nfcmgr:cmd rx'd

-> NFC_T4T_EVENT_DATA_IND gives us apdu in the callback, the command processing is scheduled on system work queue. Note: the data buffer given in the callback is copied by my application code.

[00:00:44.151,275] <wrn> app: nfcmgr:cmd process start

-> processing the command starts

[00:00:44.186,767] <wrn> app: nfc_requestor : NFC APDU routed OK cmd (00a4040007d276000085010100) response (90:00 le=2)
[00:00:44.186,828] <wrn> app: nfcmgr:cmd process ok, call response_pdu_send()

-> processing of command took 35ms, got a response (9000), calls the nfc lib to send the response.

[00:00:44.186,950] <wrn> app: nfcmgr:cmd rx@44151, process@44151, resp@44186, now@44186

-> some stats after returning from sending response. Note it took 35ms to process the command (on the system work queue), so response sent well within the 77ms timeout.

[00:00:45.261,840] <wrn> app: nfcmgr: free waiting
[00:00:45.261,932] <wrn> app: nfc_requestor : NFC field off for APDU routing END

-> my code frees the response buffer because the callback was called with a NFC_T4T_EVENT_FIELD_OFF event, presumably because the reader gave up! No "data transmitted event" received at this time...  Note the time delta from send to end of field is about 75ms and about 110ms from the command reception.

[00:00:45.521,636] <wrn> app: nfc_requestor : NFC field on for APDU routing START

-> reader tries again

[00:00:45.523,223] <wrn> app: nfcmgr: data tx event

-> and NOW we get the NFC_T4T_EVENT_DATA_TRANSMITTED event !! Why?

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

-> and this error from platform_internal_thread.c/cb_work() because it ran out of ring buffer data somehow?

[00:00:45.562,469] <wrn> app: nfcmgr:cmd rx'd

-> but continues, and we get the new command APDU anyway, which basically repeats the same sequence.

[00:00:45.562,591] <wrn> app: nfcmgr:cmd process start
[00:00:45.598,083] <wrn> app: nfc_requestor : NFC APDU routed OK cmd (00a4040007d276000085010100) response (90:00 le=2)
[00:00:45.598,144] <wrn> app: nfcmgr:cmd process ok, call response_pdu_send()
[00:00:45.598,266] <wrn> app: nfcmgr:cmd rx@45562, process@45562, resp@45598, now@45598
[00:00:46.678,588] <wrn> app: nfcmgr: free waiting
[00:00:46.678,680] <wrn> app: nfc_requestor : NFC field off for APDU routing END

This is what happens every time if the command processing takes longer than about 3ms....

Hopefully someone internally can help to understand what is going on....

Note:

- I have checked that the ring buffer is not full (the assert()s in the platform code do not trigger)

- I had to increase the size for the CONFIG_NFC_LIB_CTX_MAX_SIZE from the default of 16 to 128, otherwise the assert here in cb_work() would also sometimes trigger (but only when this problem of long processing occurred.... maybe a clue?)

    __ASSERT(header.ctx_size <= NFC_LIB_CTX_SIZE, "NFC context is bigger than expected.");

[BrianW]

and just for fun I tried enabling the NFC 'own thread' option (hint: make sure you also increase its default stack size or it will immediately overflow...); this gives me this behaviour:

[00:00:38.544,555] <wrn> app: ***** NFC enable T4T APDU ******
[00:00:38.544,677] <wrn> app: nfcmgr : type 4 APDU started, fwi=8
[00:00:43.544,586] <wrn> app: netmgr : push end : queue full, discarded previous oldest message
[00:00:43.545,989] <inf> app: netmgr: mapped devdata.core.state to 53, l=3
[00:00:50.988,922] <wrn> app: nfc_requestor : NFC field on for APDU routing START
[00:00:51.024,353] <wrn> app: nfcmgr:cmd rx'd
[00:00:51.024,475] <wrn> app: nfcmgr:cmd process start
[00:00:51.059,967] <wrn> app: nfc_requestor : NFC APDU routed OK cmd (00a4040007d276000085010100) response (90:00 le=2)
[00:00:51.060,028] <wrn> app: nfcmgr:cmd process ok, call response_pdu_send()
[00:00:51.060,150] <wrn> app: nfcmgr:cmd rx@51024, process@51024, resp@51059, now@51060
[00:00:52.044,494] <wrn> app: nfcmgr: free waiting
[00:00:52.044,586] <wrn> app: nfc_requestor : NFC field off for APDU routing END
[00:00:52.299,499] <wrn> app: nfc_requestor : NFC field on for APDU routing START
[00:00:52.301,116] <wrn> app: nfcmgr: data tx event
[00:00:52.316,223] <wrn> app: nfcmgr: data tx event
[00:00:52.322,143] <err> nfc_platform: Tried to read ctx: 1 bytes, read 49.
[00:00:52.322,143] <err> nfc_platform: Reading nfc ring buffer failed, resetting ring buffer.
[00:00:53.337,158] <wrn> app: nfc_requestor : NFC field off for APDU routing END
[00:00:53.598,052] <wrn> app: nfc_requestor : NFC field on for APDU routing START
[00:00:53.623,962] <wrn> app: nfcmgr:cmd rx'd
[00:00:53.624,084] <wrn> app: nfcmgr:cmd process start
[00:00:53.659,576] <wrn> app: nfc_requestor : NFC APDU routed OK cmd (00a4040007d276000085010100) response (90:00 le=2)
[00:00:53.659,637] <wrn> app: nfcmgr:cmd process ok, call response_pdu_send()
[00:00:53.659,759] <wrn> app: nfcmgr:cmd rx@53623, process@53624, resp@53659, now@53659
[00:00:54.634,521] <wrn> app: nfcmgr: free waiting
[00:00:54.634,613] <wrn> app: nfc_requestor : NFC field off for APDU routing END

Kind of the same but... different ring buffer error, and I get 2 'data tx' events not 1, but still too late...

The only change was in prj.conf:

CONFIG_NFC_OWN_THREAD=y

CONFIG_NFC_THREAD_STACK_SIZE=1024

 

[BrianW]

So, by fixing up the platform_internal_thread.c code to deal better with processing of requests from the library to nfc_platform_cb_request() when no data is present (eg field on/off events), I can manage to avoid the ring buffer errors, in both the 'use syswork task' and 'use dedicated task' cases.

The modified file here (also has a few debugging flags to try to spot any ring buffer full issues, or re-entry issues... none of which I saw)

/*
 * Copyright (c) 2022 Nordic Semiconductor ASA
 *
 * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
 */
#include <zephyr/kernel.h>
#include <zephyr/sys/ring_buffer.h>
#include <nfc_platform.h>
#include "platform_internal.h"
#include <zephyr/logging/log.h>

LOG_MODULE_DECLARE(nfc_platform, CONFIG_NFC_PLATFORM_LOG_LEVEL);

#ifdef CONFIG_NFC_LOW_LATENCY_IRQ
#define SWI_NAME(number)	SWI_NAME2(number)
#if defined(CONFIG_SOC_SERIES_NRF53X)
#define SWI_NAME2(number)	EGU ## number ## _IRQn
#elif defined(CONFIG_SOC_SERIES_NRF54LX)
#define SWI_NAME2(number)	SWI0 ## number ## _IRQn
#else
#define SWI_NAME2(number)	SWI ## number ## _IRQn
#endif

#define NFC_SWI_IRQN		SWI_NAME(CONFIG_NFC_SWI_NUMBER)
#endif /* CONFIG_NFC_LOW_LATENCY_IRQ */

#define NFC_LIB_CTX_SIZE CONFIG_NFC_LIB_CTX_MAX_SIZE

#define NFC_HDR_FLAG_COPY BIT(0)

struct nfc_item_header {
	uint8_t ctx_size;
	uint8_t flags;
	uint16_t data_size;
};

#ifdef CONFIG_NFC_OWN_THREAD
/* By using a counting semaphore, NFC events interrupt can go faster than the processing thread.
 * All events must be processed.
 */
static K_SEM_DEFINE(cb_sem, 0, K_SEM_MAX_LIMIT);
#endif /* CONFIG_NFC_OWN_THREAD */

static uint32_t msg_dropped_buf_full=0;
static bool _in_request=false;
static nfc_lib_cb_resolve_t nfc_cb_resolve;
RING_BUF_DECLARE(nfc_cb_ring, CONFIG_NFC_RING_SIZE);

static void work_resubmit(struct k_work *work, struct ring_buf *buf)
{
	if (!IS_ENABLED(CONFIG_NFC_OWN_THREAD)) {
		if (!ring_buf_is_empty(buf)) {
			int ret = k_work_submit(work);
			/* In this case, work can be scheduled either from IRQ or to the queue
			 * running work items during the run.
			 */
			__ASSERT_NO_MSG(((ret == 0) || (ret == 2)));
			ARG_UNUSED(ret);
		}
	}
}

static int ring_buf_get_data(struct ring_buf *buf, uint8_t **data, uint32_t size, bool *is_alloc)
{
	uint32_t tmp;
	int err;

	if (!buf || !data || !is_alloc) {
		return -EINVAL;
	}

	*is_alloc = false;

	/* Try to access data without copying.
	 * If this fails (for example, the data wraps in ring buffer), try to allocate a buffer
	 * and copy data into it.
	 */
	tmp = ring_buf_get_claim(buf, data, size);
	if (tmp < size) {
		err = ring_buf_get_finish(&nfc_cb_ring, 0);
		if (err) {
			LOG_DBG("Tried to finish a read with 0 bytes, err %i.", err);
			return err;
		}

		*data = k_malloc(size);
		if (*data == NULL) {
			LOG_DBG("Could not allocate %d bytes.", size);
			return -ENOMEM;
		}

		tmp = ring_buf_get(buf, *data, size);
		if (tmp < size) {
			LOG_DBG("Tried to read %d bytes, but read %d.", size, tmp);
			k_free(*data);
			return -EBADMSG;
		}

		*is_alloc = true;
	}

	return 0;
}

static void cb_work(struct k_work *work)
{
	struct nfc_item_header header;
	uint32_t ctx[(ROUND_UP(NFC_LIB_CTX_SIZE, 4) / 4)];
	uint8_t *data;
	uint32_t size;
	bool is_alloc = false;
	int err = 0;
	// Check if we had to drop messages 
	if (msg_dropped_buf_full>0) {
		LOG_ERR("Dropped %d messages as ring was full", msg_dropped_buf_full);
		msg_dropped_buf_full=0;		// reset counter
	}
	if (_in_request) {
		LOG_ERR("Tried to read but ring buffer being written");
		work_resubmit(work, &nfc_cb_ring);
		return;
	}
	/* Data from ring buffer is always processed in pairs - context + data in order
	 * to avoid double copying
	 */
	LOG_ERR("cb_work entry : ring buffer size %d, free space %d, data_size %d", ring_buf_capacity_get(&nfc_cb_ring), ring_buf_space_get(&nfc_cb_ring), ring_buf_size_get(&nfc_cb_ring));												  
	size = ring_buf_get(&nfc_cb_ring, (uint8_t *)&header, sizeof(header));
	if (size != sizeof(header)) {
		LOG_ERR("Tried to read header: %d bytes, read %d.", sizeof(header), size);
		goto error;
	}

	__ASSERT(header.ctx_size <= NFC_LIB_CTX_SIZE, "NFC context is bigger than expected.");
	if (header.ctx_size>0) {
		size = ring_buf_get(&nfc_cb_ring, (uint8_t *)&ctx, header.ctx_size);
		if (size != header.ctx_size) {
			LOG_ERR("Tried to read ctx: %d bytes, read %d.", header.ctx_size, size);
			goto error;
		}
	} else {
		LOG_ERR("cb_work : no CTX.");
		memset((void*)&ctx[0], 0, (ROUND_UP(NFC_LIB_CTX_SIZE, 4)));
	}
	if (header.data_size>0) {
		if (!(header.flags & NFC_HDR_FLAG_COPY)) {
			size = ring_buf_get(&nfc_cb_ring, (uint8_t *)&data, sizeof(uint8_t*));
			if (size != sizeof(uint8_t*)) {
				LOG_ERR("Tried to read data pointer: %d bytes, read %d.", sizeof(data),
													size);
				LOG_ERR("hdr ctx_size %d, data_size %d", header.ctx_size, header.data_size);												  
				goto error;
			}
		} else {
			err = ring_buf_get_data(&nfc_cb_ring, &data, header.data_size, &is_alloc);
			if (err) {
				LOG_ERR("Reading nfc data failed, err %i.", err);
				goto error;
			}
		}
	} else {
		LOG_ERR("cb_work: no data.");
		data = NULL;
	}

	__ASSERT(nfc_cb_resolve != NULL, "nfc_cb_resolve is not set");
	nfc_cb_resolve(ctx, data);
//	k_msleep(30);

	if ((header.flags & NFC_HDR_FLAG_COPY)) {
		if (is_alloc) {
			k_free(data);
		} else {
			err = ring_buf_get_finish(&nfc_cb_ring, header.data_size);
			if (err) {
				LOG_ERR("Tried to finish a read with %u bytes, err %i.",
										header.data_size, err);
				ring_buf_reset(&nfc_cb_ring);
			}
		}
	}
	work_resubmit(work, &nfc_cb_ring);

	return;

error:
	LOG_ERR("Reading nfc ring buffer failed, resetting ring buffer.");
	ring_buf_reset(&nfc_cb_ring);
}

#ifdef CONFIG_NFC_OWN_THREAD
static void nfc_cb_wrapper(void)
{
	while (1) {
		k_sem_take(&cb_sem, K_FOREVER);
		cb_work(NULL);
	}
}

K_THREAD_DEFINE(nfc_cb_thread, CONFIG_NFC_THREAD_STACK_SIZE, nfc_cb_wrapper,
		 NULL, NULL, NULL, CONFIG_NFC_THREAD_PRIORITY, 0, 0);
#else
static K_WORK_DEFINE(nfc_cb_work, cb_work);
#endif /* CONFIG_NFC_OWN_THREAD */

static void schedule_callback(void)
{
#ifdef CONFIG_NFC_OWN_THREAD
	k_sem_give(&cb_sem);
#else
	k_work_submit(&nfc_cb_work);
#endif /* CONFIG_NFC_OWN_THREAD */
}

#ifdef CONFIG_NFC_LOW_LATENCY_IRQ
ISR_DIRECT_DECLARE(nfc_swi_handler)
{
	schedule_callback();

	ISR_DIRECT_PM();

	return 1;
}
#endif /* CONFIG_NFC_LOW_LATENCY_IRQ */

int nfc_platform_internal_init(nfc_lib_cb_resolve_t cb_rslv)
{
	if (!cb_rslv) {
		return -EINVAL;
	}

#ifdef CONFIG_NFC_LOW_LATENCY_IRQ
	IRQ_DIRECT_CONNECT(NFC_SWI_IRQN, CONFIG_NFCT_IRQ_PRIORITY,
			   nfc_swi_handler, 0);
	irq_enable(NFC_SWI_IRQN);
#endif /* CONFIG_NFC_LOW_LATENCY_IRQ */

	nfc_cb_resolve = cb_rslv;

	return 0;
}

void nfc_platform_cb_request(const void *ctx,
			     size_t ctx_len,
			     const uint8_t *data,
			     size_t data_len,
			     bool copy_data)
{
	struct nfc_item_header header;
	uint32_t size;
	uint32_t exp_size;

	header.ctx_size = ctx_len;
	header.flags = copy_data ? NFC_HDR_FLAG_COPY : 0;
	header.data_size = data_len;
	__ASSERT(_in_request==false,"cb request but already in request??");
_in_request=true;
	// Check can fit header+data in the ring buf, and discard if not - don't want to put bits of header/data in there when its full
	if (ring_buf_space_get(&nfc_cb_ring) < (sizeof(header)+ctx_len+(copy_data?data_len:sizeof(data)))) {
		// Failed, buffer too full for this to fit, but its still processable as we didn't put incomplete message in it...
		msg_dropped_buf_full++;
		goto end;
	}
	if (ctx_len==0) {
		// Flag it
		msg_dropped_buf_full=252;
	}
	if (data==NULL && data_len>0) {
		// Flag it
		msg_dropped_buf_full=249;
	}
	/*
	if (data_len==0) {
		// Flag it
		msg_dropped_buf_full=251;
	}
	if (data==NULL) {
		// Flag it
		msg_dropped_buf_full=250;
	}
*/
	size = ring_buf_put(&nfc_cb_ring, (uint8_t *)&header, sizeof(header));
	if (size != sizeof(header)) {
//		__ASSERT(false, "NFC ring buffer overflow (hdr)");
		msg_dropped_buf_full=255;
		ring_buf_reset(&nfc_cb_ring);		// as its got bits in it
		goto end;
	}

	size = ring_buf_put(&nfc_cb_ring, (uint8_t *)ctx, header.ctx_size);
	if (size != header.ctx_size) {
//		__ASSERT(false, "NFC ring buffer overflow (ctx)");
		msg_dropped_buf_full=254;
		ring_buf_reset(&nfc_cb_ring);		// as its got bits in it
		goto end;
	}

	if (data_len>0 && data!=NULL) {
		if (copy_data) {
			size = ring_buf_put(&nfc_cb_ring, data, header.data_size);
			exp_size = header.data_size;
		} else {
			size = ring_buf_put(&nfc_cb_ring, (uint8_t *)&data, sizeof(data));
			exp_size = sizeof(data);
		}

		if (size != exp_size) {
	//		__ASSERT(false, "NFC ring buffer overflow (data)");
			msg_dropped_buf_full=253;
			ring_buf_reset(&nfc_cb_ring);		// as its got bits in it
		}
	}
end:
	_in_request=false;
#ifdef CONFIG_NFC_LOW_LATENCY_IRQ
	NVIC_SetPendingIRQ(NFC_SWI_IRQN);
#else
	schedule_callback();
#endif /* CONFIG_NFC_LOW_LATENCY_IRQ */
}

However, in both scheduling cases, any delay in generating the response to the APDU command seems to mean it doesn't get sent to the reader, which times out (despite the FWT being correct communicated as 77ms).

I see no difference if the delay is in the actual command callback thread directly, or on a seperate processing thread before it calls the nfc_t4t_response_pdu_send() method.

Its easy to replicate; just add a k_msleep(30); to the cb_work() function before or after calling the "nfc_cb_resolve" function.

I hope that someone in the library dev team can understand why this is happening... and suggest a fix/workaround. It's blocking our release of the NFC / smartcard ISO7816 functionality right now...