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]

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

[Marte Myrvold]

Hi,

Thank you for the additional information. I have forwarded it internally and am waiting for a response.

Best regards,
Marte

[Marte Myrvold]

Hi,

I got an update from the developers.

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. 

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.

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?