RFAL timeout after switching to gcc 9.4/glibc 2.33.

[MHamm.1]

I have a version of nfcPoller linked against rfal v1.3 on Linux 5.10.17. This has been working fine with gcc 7.5/glibc 2.31. We recently bumped our toolchain to gcc 9.4/glibc 2.33 and now I get timeouts while reading anything with an NDEF field (or anything other than a header). I'm testing with an card that reports as:

xampleRfalPollerActivation[exampleRfalPoller.c:900] INFO NFC-A T2T device activated 
exampleRfalPollerRun[exampleRfalPoller.c:343] INFO atqa_sak: 004400
exampleRfalPollerRun[exampleRfalPoller.c:366] INFO MIFARE Ultralight UID: 04B89DB22F6680

The code that causes this is in st25r3911/rfal_rfst25r3911.c, line 1900:

 /* Only raise Timeout if NRE is detected with no Rx Start (NRT EMV mode) */
 if( (irqs & ST25R3911_IRQ_MASK_NRE) && !(irqs & ST25R3911_IRQ_MASK_RXS) )
 { 
 gRFAL.TxRx.status = ERR_TIMEOUT;
 gRFAL.TxRx.state = RFAL_TXRX_STATE_RX_FAIL;
 break;
 }

It seems I'm getting the NRE interrupt from the ST25R3911B interrupt register. I don't know how I get this or why it's showing up after switching toolchains. I also believe (but can't prove yet) that I'm not getting the same kind of gpio events. I switched the platform code to use libgpiod 1.4.3 since we're running a 5.10.17 kernel. Again, rfal v1.3.0, libgpiod 1.4.3 and kernel 5.10.17 all worked fine with gcc 7.5 / glibc 2.31.

I've tried changing a few timer settings but at best there was no change and at worse the app locked up. I've also tried v1.4.3, v2.1.2, v2.2 and v2.4.0. None of these worked at all - I get no gpio events at all with these. I'm assuming my porting didn't go right with those.

Is there anything I can do to dig deeper into why I'm getting this NRE interrupt? Are there specific timeout settings I can change that might impact what I'm seeing? I'm willing to try v2.4 again but may need help understanding why no gpio interrupts are being seen.

Thanks for any pointers.

[Brian TIDAL]

Hi,

can you try to disable all gcc optimization level (option -O0) with your current rfal v1.3.0 porting +  gcc 9.4/glibc 2.33? I suspect that some registers are not properly set due some compiler optimization.

Can you also connect a logic analyzer on SPI (CLK/MISO/MOSI/CS) + ST25R3911B_INT and trace the various registers accesses when running nfcPoller compiled with gcc 7.5 and then then running nfcPoller compiled with gcc 9.4?

Rgds

BT

[MHamm.1]

Thanks for the quick reply Brian.

I recompiled with -O0 but there was no change. Still get the timeout.

Getting some help with the logic analyzer. Let you know what we find out.

[MHamm.1]

I had one of our HW folks run an analyzer on those lines. I have the analyzer capture files - they are for Saleae Logic 2, which has a free Linux tool to view the captures: https://www.saleae.com/downloads/

Anyway, her summary of the logs are as follows:

-timing does meet the listed spec in the datasheet (at least from what the logic analyzer measured - could do another measurement on the scope to get another point of data to confirm if needed). However with the gcc9.4 build takes about 225microseconds before it gets to the next register where as the gcc7.5 build it's only 20microseconds (these areas are marked with the pink measurement field)
 
-sometimes the addresses aren't incremented as expected with gcc9.4, at least compared to the gcc7.5

If you need copies of the logs let me know and I'll find someplace for you to download them - they are about 93MB each and there are two logs: one for the gcc7.5 and and for gcc9.4.

[Brian TIDAL]

Hi,

I am not sure to understand the statement "sometimes the addresses aren't incremented as expected with gcc9.4, at least compared to the gcc7.5". Can you share more details? Can you also confirm that your application relies on SPI communication (vs. I2C)?

Also, can you share some information about your HW platform: is it a RPI?

If you share the log, I will have a look on it. Feel free also to share your porting to libgpiod or to compare with the implementation being used in STSW-ST25R013

Rgds

BT

[MHamm.1]

Addresses aren't incremented: See below

SPI use: Yes.

• platform.h defines platformSpiTxRx() as spiTxRx() in pltfm_spi.c.
• platformSpiTxRx() is referenced heavily in rfal/Src/st25r3911/st25r3911_com.c
• platformI2CTx (and friends) are NULL definitions in platform.h and are not referenced anywhere else in rfal, common, platform or application code directories.

HW Platform: This is a custom board based on RK3399. It is not a Pi.

Here is (most of) the platform_gpio.h file that has the port to libgpiod.

static void gpio_setFlag( int bits )
{
 pthread_mutex_lock( &gpioMutex );
 gpioFlags |= bits;
 pthread_mutex_unlock( &gpioMutex );
}
 
static void gpio_unsetFlag( int bits )
{
 pthread_mutex_lock( &gpioMutex );
 gpioFlags &= ~bits;
 pthread_mutex_unlock( &gpioMutex );
}
 
static int gpio_isFlagSet( int bits )
{
 int status = 0;
 pthread_mutex_lock( &gpioMutex );
 if ( gpioFlags & bits )
 status = 1;
 pthread_mutex_unlock( &gpioMutex );
 return status;
}
ReturnCode gpio_init(void)
{
 char *chipname = QSC_RFAL_GPIO_INTERRUPT_CHIPNAME;
 unsigned int line_num = QSC_RFAL_GPIO_INTERRUPT_PIN; // GPIO2_A7
 int ret;
 
 // printf("GPIOD version: %s\n", gpiod_version_string());
 
 /* Open chip */
 intr_chip = gpiod_chip_open_by_name(chipname);
 if (!intr_chip)
 {
 printf("Open chip failed for %s: %s\n", chipname, strerror(errno));
 goto error;
 }
 
 /* Setup interrupt pin */
 intr_line = gpiod_chip_get_line(intr_chip, line_num);
 if (!intr_line)
 {
 printf("Get line failed for GPIO LED pin %d: %s\n", line_num, strerror(errno));
 gpiod_chip_close(intr_chip);
 intr_chip = NULL;
 goto error;
 }
 
 ret = gpiod_line_request_rising_edge_events(intr_line, QSC_RFAL_INTR);
 if (ret < 0)
 {
 printf("Request event notification failed for GPIO pin %d: %s\n", line_num, strerror(errno));
 gpiod_line_release(intr_line);
 gpiod_chip_close(intr_chip);
 intr_line = NULL;
 intr_chip = NULL;
 goto error;
 }
 
 ret = pthread_mutex_init(&lock, NULL);
 if (ret != 0)
 {
 printf("Error: mutex init to protect interrupt status is failed\n");
 gpiod_line_release(intr_line);
 gpiod_chip_close(intr_chip);
 intr_line = NULL;
 intr_chip = NULL;
 goto error;
 }
 
 isGPIOInit = 1;
 
error:
 if(isGPIOInit)
 return ERR_NONE;
 else
 return ERR_IO;
}
 
/*
 * Read Interrupt pin state.
 * Input arguments were deprecated in STM original code (re: no longer used).
 */
GPIO_PinState gpio_readpin(int port, int pin_no)
{
 int value;
 
 /* First check if GPIOInit is done or not */
 if (!isGPIOInit) {
 printf("GPIO is not initialized\n");
 return ERR_WRONG_STATE;
 }
 
 pthread_mutex_lock( &gpioMutex );
 value = gpiod_line_get_value(intr_line);
 pthread_mutex_unlock( &gpioMutex );
 if ( value == 1 ) {
 return GPIO_PIN_SET;
 }
 else {
 return GPIO_PIN_RESET;
 }
}
 
static void* pthread_func()
{
 struct timespec ts = { 0, 200000000 }; // 200ms timeout waiting on events
 struct gpiod_line_event event;
 int ret = 0;
 
 /* First check if GPIOInit is done or not */
 if (!isGPIOInit) {
 printf("GPIO is not initialized\n");
 return NULL;
 }
 
 /* Wait on an event on the specified GPIO pin. */
 while( true )
 {
 if ( !gpio_isFlagSet(GPIO_RUNNING) )
 break;
 
 ret = gpiod_line_event_wait(intr_line, &ts);
 if (ret < 0)
 {
 // printf("Error waiting on event notification on interrupt line.\n");
 continue;
 }
 else if (ret == 0)
 {
 // printf("Timeout waiting on event notification on interrupt line.\n");
 continue;
 }
 
 ret = gpiod_line_event_read(intr_line, &event);
 if (ret < 0)
 continue;
 if ( event.event_type != GPIOD_LINE_EVENT_RISING_EDGE )
 continue;
 /* Call RFAL Isr */
 // printf("Calling st25r3911Isr\n");
 st25r3911Isr();
 }
 
 return NULL;
}
 
ReturnCode interrupt_init(void)
{
 struct sched_param params;
 int ret;
 
 /* create a pthread for interrupt handler */
 gpio_setFlag(GPIO_RUNNING);
 ret = pthread_create(&intr_thread, NULL, pthread_func, NULL);
 if (ret) {
 printf("Error: poll thread creation %d\n", ret);
 return ERR_IO;
 }
 
 /* Assign highest priority to interrupt thread */
 params.sched_priority = sched_get_priority_max(SCHED_FIFO);
 ret = pthread_setschedparam(intr_thread, SCHED_FIFO, &params);
 if (ret) {
 printf("Error: assigning high priority to interrupt thread\n");
 return ERR_IO;
 }
 
 return ERR_NONE;
}
 
void interrupt_shutdown(void)
{
 int cnt=0;
 
 /* Stop thread and wait for it to exit. */
 gpio_unsetFlag( GPIO_RUNNING );
 pthread_join(intr_thread, NULL);
 
 /* Now cleanup. */
 pthread_mutex_lock( &gpioMutex );
 if (intr_line)
 {
 gpiod_line_release(intr_line);
 intr_line = NULL;
 }
 pthread_mutex_unlock( &gpioMutex );
 if (intr_chip)
 {
 gpiod_chip_close(intr_chip);
 intr_chip = NULL;
 }
 // printf("Interrupt thread has shut down.\n");
}
 
void gpio_set_pin(int pin_no, int value)
{
 struct gpiod_chip *gpio_chip = NULL;
 struct gpiod_line *gpio_line;
 int chip_num = -1;
 int line_num = -1;
 char chipname[10];
 int ret;
 
 /* Find the chip and line we need */
 chip_num = pin_no / 32;
 line_num = pin_no % 32 - 1;
 sprintf(chipname, "gpiochip%d", chip_num);
 
 /* Open the chip */
 gpio_chip = gpiod_chip_open_by_name(chipname);
 if (!gpio_chip)
 {
 printf("Open chip failed for %s: %s\n", chipname, strerror(errno));
 return;
 }
 
 /* Get the line */
 gpio_line = gpiod_chip_get_line(gpio_chip, line_num);
 if (!gpio_line)
 {
 printf("Get line failed for chip %d, GPIO pin %d: %s\n", chip_num, line_num, strerror(errno));
 gpiod_chip_close(gpio_chip);
 gpio_chip = NULL;
 return;
 }
 
 /* Request it for output */
 ret = gpiod_line_request_output(gpio_line, QSC_RFAL_GPIO_CONSUMER, 0);
 if (ret != 0)
 {
 printf("Setting GPIO chip %d, line %d as output failed: %s\n", chip_num, line_num, strerror(errno));
 gpiod_line_release(gpio_line);
 gpiod_chip_close(gpio_chip);
 gpio_chip = NULL;
 return;
 }
 
 /* set the value as requested */
 ret = gpiod_line_set_value(gpio_line, value);
 if (ret < 0)
 printf("Failed to %s GPIO chip %d, pin %d.\n", (value==1)?"enable":"disable", chip_num, line_num);
 
 /* Close the chip */
 gpiod_line_release(gpio_line);
 gpiod_chip_close(gpio_chip);
 gpio_chip = NULL;
}
void gpio_set(int port, int pin_no)
{
 gpio_set_pin(pin_no, 1);
}
 
void gpio_clear(int port, int pin_no)
{
 gpio_set_pin(pin_no, 0);
}
 
void pltf_protect_interrupt_status(void)
{
 pthread_mutex_lock(&lock);
}
 
void pltf_unprotect_interrupt_status(void)
{
 pthread_mutex_unlock(&lock);
}

Addresses aren't incremented: I'm not exactly sure what was meant by this, but maybe the following pics will help. The first two show how a short/long timing interval swapped between gcc7.5 and gcc9.4.

The next two show a change in increments:

I sent you a private message with links to download the analyzer .sal files.

[Brian TIDAL]

Hi,

the Logic Analyzer files have be analyzed and it appears that the content of the user transmit buffer is incorrect. Thus, as the transmitted command is invalid, the tag does not reply and an ERR_TIMEOUT error is returned to the user application.

I would suggest to check the content of the txBuf is not modified/corrupted until the completion of the transceive command.

Rgds

BT

[MHamm.1]

The txBuf and a pointer to it were stack variables when initiating a read of TLV (aka NDEF) records. The function where this happens loops multiple times, starting with the transceive request on the first instance and looping waiting for the transceive to complete. I moved txBuf and it's pointer to static module variables and initial tests show gcc9.4 now works with our version of nfcPoller. I'm passing the build on to some others to verify further but at the moment this seems to have fixed the problem.

Many thanks for your help on this Brian!