LIBUARTE strange behaviour

[rchaudet]

Hi everyone,

I am trying to solve a bug I am facing for several days now, it is related to LIBUARTE communication with a GPS module

Communication is init at 115200 BAUD and with a timeout of 100us.

The GPS module sends data every second. This data is composed by several frames, all starting with '$' and ending with " *xx " (xx can be any number)

Here is an example of correct data:

$GNRMC,164352.97,V,,,,,,,060421,,,N,V*11
$GNGGA,164352.97,,,,,0,04,8.0,,M,,M,,*7D
$GNGLL,,,,,164352.97,V,N*5D
$GPGSV,16,,,31,26,,,20,27,,,32,1*6D
$GPGSV,2,2,07,08,,,25,26,,,21,27,,,25,8*60
$GLGSV,1,1,02,82,,,20,81,,,24,1*7D
$GNGSA,A,1,,,,,,,,,,,,,16.7,8.0,14.7,4*3C
$GNGSA,A,1,,,,,,,,,,,,,16.7,8.0,14.7,5*3D
$GNGSA,A,1,,,,,,,,,,,,,16.7,8.0,14.7,6*3E

But here is the data I actually receive from GNSS module:

"NEWFRAME" is to indicate the beginning of a new packet of data in the UART handler.

NEWFRAME$PQGNSS,001*15
$PQVER,MODULE_LC79DANR01A04S,2019/12/18,10:17:15*25
$PQVER,SUB_V03*22
$PQVER,GL_20.23*15
$PQVER,GL_ANEWFRAME000100000000000000000000000000000000000000000000000000000000000000000000*42
$PQSWCONFIG,1,2,4,000000000000000000000000NEWFRAME00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000NEWFRAME101010101010000*3E
ER,MODULE_LC79DANR01A04S,2019/12/18,10:17:15*25
$PQVER,SUB_V03*22
$PQVER,GL_20.23*15
$PQVER,GL_ANEWFRAME$GNRMC,164052.86,V,,,,,,,060421,,,N,V*12
$GNGGA,164052.86,,,,,0,00,99.0,,M,,M,,*42
$GNGLL,,,,,164052.86,V,N*5E
$GNGSNEWFRAME99.0,3*01
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,4*06
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,5*07
$GNGSA,A,1,,,,,,,,,,NEWFRAME$GNRMC,164053.86,V,,,,,,,060421,,,N,V*13
$GNGGA,164053.86,,,,,0,00,99.0,,M,,M,,*43
$GNEWFRAMENGLL,,,,,164053.86,V,N*5F
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,1*03
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,2*00
$GNGNEWFRAME,1,,,,,,,,,,,,,99.0,99.0,99.0,6*04
$GNVTG,,T,,M,,N,,K,N*32
$GNRMC,164053.88,V,,,,,,,060421,,,N,V*1D
$GNGGA,164053.88NEWFRAME,1,,,,,,,,,,,,,99.0,99.0,99.0,2*00
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,3*01
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,4NEWFRAME$GNRMC,164054.86,VNEWFRAME,,,,,,,060421,,,N,V*14
$GNGGA,164054.86,,,,,0,00,99.0,,M,,M,,*44
$GNGLL,,,,,164054.86,V,N*58
$GPGSV,1,1,01,08,,,30,1NEWFRAME
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,4*06
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,5*07
$GNGSA,A,1,,,,,,,,,,,,,99.0,99NEWFRAME$GNRMC,164055.86,V,,,,,,,060421,,,N,V*15
$GNGGA,164055.86,,,,,0,00,99.0,,M,,M,,*45
$GNGLL,,,,,1NEWFRAME64055.86,V,N*59
$GPGSV,1,1,01,16,,,24,1*64
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,1*03
$GNGSA,A,1,,,,,,,,,,,,,99.0,99NEWFRAME9.0,5*07
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,6*04
$GNVTG,,T,,M,,N,,K,N*32
64054.86,V,N*58
$GPGSV,1,1,01,08,,,30,1NEWFRAME$GNRMC,164056.86,V,,,,,,,060421,,,N,V*16
$GNGGA,164056.86,,,,,0,00,99.0,,M,,M,,*46
$GNGLL,,,,,164056.86,V,N*5A
$GPGSNEWFRAME0,99.0,99.0,1*03
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,2*00
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,3*01
$GNGSA,A,1,,,NEWFRAME$GNRMC,164057.86,V,,,,,,,060421,,,N,V*17
$GNGGA,164057.86,,,,,0,00,99.0,,M,,M,,*47
$GNGLL,,,,,164057.86,V,N*5B
$GPGSNEWFRAME,,,,,,99.0,99.0,99.0,3*01
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,4*06
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,5*07
$GNGNEWFRAME$GNRMC,164058.86,V,,,,,,,060421,,,N,V*18
$GNGGA,164058.86,,,,,0,00,99.NEWFRAME0,,M,,M,,*48
$GNGLL,,,,,164058.86,V,N*54
$GPGSV,1,1,02,16,,,25,27,,,28,1*69
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,1*NEWFRAME$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,5*07
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,6*04
$GNVTG,,T,,M,,N,,K,N*32
,V,N*5NEWFRAME$GNRMC,164059.86,V,,,,,,,060421,,,N,V*19
$GNGGA,164059.86,,,,,0,00,99.0,,M,,M,,*49
$GNGLL,,,,,164059.86,V,N*55
$GPGSNEWFRAME$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,1*03
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,2*00
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.NEWFRAME.0,6*04
$GNVTG,,T,,M,,N,,K,N*32
,V,N*54
$GPGSV,1,1,02,16,,,25,27,,,28,1*69
$GNGSA,A,1,,,,,,,,,,,,,99.0,99.0,99.0,1*NEWFRAME$GNRMC,164100.86,V,,,,,,,060421,,,N,V*14
$GNGGA,164100.86,,,,,0,00,99.0,,M,,M,,*44

Here are my two problems:

1- UART handler is not called at the end of the gps module packets, but somewhere in the middle of them

2- Sometimes, even inside one uart handler packet, I can see that NMEA frames are truncated (missing several bytes)

I already tried to increase uart timeout between 100 to 10000 whithout any improvement (I am getting the exact same output)

my UART instance is defined this way: 

NRF_LIBUARTE_ASYNC_DEFINE(libuarte_gnss, 0, 2, NRF_LIBUARTE_PERIPHERAL_NOT_USED, NRF_LIBUARTE_PERIPHERAL_NOT_USED, 255, 3);

Any idea where this issue could come from?

Best regards

[rchaudet]

Here is more talkative logs:

If I enable GGA & RMC frames, here is the log I get:

NEW PACKET AT 55220 ms OF 85 bytes
$GNRMC,100336.39,V,,,,,,,070421,,,N,V*14
$GNGGA,100336.39,,,,,0,00,99.0,,M,,M,,*45

NEW PACKET AT 56220 ms OF 85 bytes
$GNRMC,100337.39,V,,,,,,,070421,,,N,V*15
$GNGGA,100337.39,,,,,0,00,99.0,,M,,M,,*44

NEW PACKET AT 57210 ms OF 45 bytes
$GNRMC,100338.39,V,,,,,,,070421,,,N,V*1A
$GN
NEW PACKET AT 57230 ms OF 40 bytes
GGA,100338.39,,,,,0,00,99.0,,M,,M,,*4B
¬þ
NEW PACKET AT 58230 ms OF 85 bytes
$GNRMC,100339.39,V,,,,,,,070421,,,N,V*1B
$GNGGA,100339.39,,,,,0,00,99.0,,M,,M,,*4A

NEW PACKET AT 59230 ms OF 85 bytes
$GNRMC,100340.39,V,,,,,,,070421,,,N,V*15
$GNGGA,100340.39,,,,,0,00,99.0,,M,,M,,*44

NEW PACKET AT 60220 ms OF 45 bytes
$GNRMC,100341.39,V,,,,,,,070421,,,N,V*14
$GN
NEW PACKET AT 60230 ms OF 40 bytes
GGA,100341.39,,,,,0,00,99.0,,M,,M,,*45
¬þ
NEW PACKET AT 61230 ms OF 85 bytes
$GNRMC,100342.39,V,,,,,,,070421,,,N,V*17
$GNGGA,100342.39,,,,,0,00,99.0,,M,,M,,*46

NEW PACKET AT 62240 ms OF 85 bytes
$GNRMC,100343.39,V,,,,,,,070421,,,N,V*16
$GNGGA,100343.39,,,,,0,00,99.0,,M,,M,,*47

NEW PACKET AT 63230 ms OF 45 bytes
$GNRMC,100344.39,V,,,,,,,070421,,,N,V*11
$GN
NEW PACKET AT 63240 ms OF 40 bytes
GGA,100344.39,,,,,0,00,99.0,,M,,M,,*40
¬þ

If I enable GGA frames only:

NEW PACKET AT 13110 ms OF 43 bytes
$GNGGA,101954.00,,,,,0,00,99.0,,M,,M,,*40

NEW PACKET AT 14110 ms OF 43 bytes
$GNGGA,101955.00,,,,,0,00,99.0,,M,,M,,*41

NEW PACKET AT 15120 ms OF 43 bytes
$GNGGA,101956.00,,,,,0,00,99.0,,M,,M,,*42

NEW PACKET AT 16120 ms OF 43 bytes
$GNGGA,101957.00,,,,,0,00,99.0,,M,,M,,*43

NEW PACKET AT 17140 ms OF 43 bytes
$GNGGA,101958.00,,,,,0,00,99.0,,M,,M,,*4C

NEW PACKET AT 18130 ms OF 37 bytes
$GNGGA,101959.00,,,,,0,00,99.0,,M,,M,
NEW PACKET AT 18140 ms OF 6 bytes
,*4D

NEW PACKET AT 19140 ms OF 43 bytes
$GNGGA,102000.00,,,,,0,00,99.0,,M,,M,,*4B

NEW PACKET AT 20150 ms OF 43 bytes
$GNGGA,102001.00,,,,,0,00,99.0,,M,,M,,*4A

NEW PACKET AT 21150 ms OF 43 bytes
$GNGGA,102002.00,,,,,0,00,99.0,,M,,M,,*49

NEW PACKET AT 22150 ms OF 43 bytes
$GNGGA,102003.00,,,,,0,00,99.0,,M,,M,,*48

NEW PACKET AT 23150 ms OF 43 bytes
$GNGGA,102004.00,,,,,0,00,99.0,,M,,M,,*4F

NEW PACKET AT 24150 ms OF 34 bytes
$GNGGA,102005.00,,,,,0,00,99.0,,M,
NEW PACKET AT 24160 ms OF 9 bytes
,M,,*4E

NEW PACKET AT 25150 ms OF 43 bytes
$GNGGA,102006.00,,,,,0,00,99.0,,M,,M,,*4D

NEW PACKET AT 26160 ms OF 43 bytes
$GNGGA,102007.00,,,,,0,00,99.0,,M,,M,,*4C

NEW PACKET AT 27160 ms OF 43 bytes
$GNGGA,102008.00,,,,,0,00,99.0,,M,,M,,*43

NEW PACKET AT 28170 ms OF 43 bytes
$GNGGA,102009.00,,,,,0,00,99.0,,M,,M,,*42

NEW PACKET AT 29030 ms OF 43 bytes
$GNGGA,102009.79,,,,,0,00,99.0,,M,,M,,*4C

NEW PACKET AT 29160 ms OF 31 bytes
$GNGGA,102010.00,,,,,0,00,99.0,
NEW PACKET AT 29170 ms OF 12 bytes
,M,,M,,*4A


Basically, clean frames are periodically received (85 bytes in the first example, 43 bytes in the second example),

Then a truncated  frame is received in two parts, then several clean frames are received again, and so on.

I don't get any UART error, and I call nrf_libuarte_async_rx_free() at the end of every NRF_LIBUARTE_ASYNC_EVT_RX_DATA event

[Jørgen Holmefjord]

Hi,

libUARTE have been configured with buffer size of 255 bytes in your application. You will receive a RX event whenever the timeout is hit, or the buffer have been filled completely. If you receive 40 bytes, then 85 two times, you will only be able to bit 255-85--85-40 = 45 bytes before the buffer is full. libUARTE will then switch to the next buffer for the last 45 bytes of the 85 bytes transfer.

If you only receive 85 bytes packets, you should be able to fit 3 full packets in the buffer, but you may have received some other initial (shorter) data before getting into this situation where the transfers are splitted into different buffers. You will have to re-assemble the packets yourself in the application.

Best regards,
Jørgen

[rchaudet]

Hi, 

Thank you for your feedback.

When looking at the nrf_libuarte_async_rx_free() function, I can see that it actually frees the buffer only when it is full. In other case, there is a log displaying "Freeing partial buffer" which actually does not perform anything.

Would it be possible to actually free the buffer before it is full (i.e. after every packet reception) to avoid truncated frames, considering that every packet size won't ever exceed buffer size?

Best regards

[Jørgen Holmefjord]

Unfortunately, that is not possible. The full RX buffer is still assigned to the UARTE peripheral to receive more data, the transfer is not stopped due to a timeout, it is first stopped when the full buffer is filled.

There is no support for timeouts in the UARTE peripheral, so libUARTE uses timers and PPI to detect timeouts and count received bytes. Whenever a byte is received by the UARTE peripheral, it will generate a RXRDY event. This event is connected to a TIMER in count mode, to count the number of received bytes. In addition, the event is connect to another TIMER/RTC to reset the timer to prevent it from timing out and generate a timeout event. if not bytes are received during the timeout period, the timeout-timer will time out and report an RX event to the application, with the given amount of received bytes. When the next byte is received, it will continue to fill the same buffer until it is full and the UARTE peripheral will generate a END event. When the END event is generated, this will automatically start a new RX operation with the next available 255 byte buffer (a minimum of 3 RX buffers are used), to prevent loss of data. Automatic buffer switching is possible due to the double-buffering support in the UARTE peripheral, which allows you to prepare a new buffer pointer as soon as the STARTED event is generated. Stopping the transfer and resetting the buffer pointer to the start of the buffer, like you are asking, will cause a small period where the peripheral may miss incoming data, as it is busy with preparing the new buffer pointer in the firmware, without the UARTE RX mode being enabled.

If you know that you will only be receiving data at regular intervals, or that there will be a "safe period" after a transfer where you can handle buffer-switching in the application before next incoming stream of data is expected, you could possibly do what you are asking using the NRFX UARTE driver directly. This may require some more work to get up and running correctly, so it may be easier to handle the re-assembly of the packets from libUARTE in your application yourself.

[rchaudet]

Hi,

Thank you for this complete explanation. 

The truncated frames when buffer is full are no longer an issue. I managed to complete them properly.

I still have a weird behaviour: 

some data in the libuarte buffer seems to be "ghosted": I have old datas (from previous buffers) which are still shown in next buffers, as you can see in these logs:

First field in $GNXXX frames is supposed to be incremented, and I get previous frames mixed up with the new ones (in this case it starts at 000024 and ends at 000042)

$GNRMC,000024.00,V,,,,,,,020712,,,N,V*19
$GNGGA,000024.00,,,,,0,00,99.0,,M,,M,,*4E
$GNRMC,000016.00,V,,,,,,,020712,,,N,V*18
$GNGGA,000016.00,,,,,0,00,99.0,,M,,M,,*4F
$G$GNRMC,000025.00,V,,,,,,,020712,,,N,V*18
$GNGGA,000025.00,,,,,0,00,99.0,,M,,M,,*4F
$GNRMC,000017.00,V,,,,,,,020712,,,N,V*19
$GNRMC,000026.00,V,,,,,,,020712,,,N,V*1B
$GNGGA,000026.00,,,,,0,00,99.0,,M,,M,,*4C
$GNRMC,000018.00,V,,,,,,,020712,,,N,V*16
$GNRMC,000027.00,V,,,,,,,020712,,,N,V*1A
$GNGGA,000027.00,,,,,0,00,99.0,,M,,M,,*4D
$GNRMC,000019.00,V,,,,,,,020712,,,N,V*17
$GNGGA,000019.00,,,,,0,00,99.0,,M,,M,,*40
$G$GNRMC,000028.00,V,,,,,,,020712,,,N,V*15
$GNGGA,000028.00,,,,,0,00,99.0,,M,,M,,*42
$GNRMC,000020.00,V,,,,,,,020712,,,N,V*1D
$GNRMC,000029.00,V,,,,,,,020712,,,N,V*14
$GNGGA,000029.00,,,,,0,00,99.0,,M,,M,,*43
$GNRMC,000021.00,V,,,,,,,020712,,,N,V*1C
$GNRMC,000030.00,V,,,,,,,020712,,,N,V*1C
$GNGGA,000030.00,,,,,0,00,99.0,,M,,M,,*4B
$GNRMC,000022.00,V,,,,,,,020712,,,N,V*1F
$GNGGA,000022.00,,,,,0,00,99.0,,M,,M,,*48
$G$GNRMC,000031.00,V,,,,,,,020712,,,N,V*1D
$GNGGA,000031.00,,,,,0,00,99.0,,M,,M,,*4A
$GNRMC,000023.00,V,,,,,,,020712,,,N,V*1E
$GNRMC,000032.00,V,,,,,,,020712,,,N,V*1E
$GNGGA,000032.00,,,,,0,00,99.0,,M,,M,,*49
$GNRMC,000024.00,V,,,,,,,020712,,,N,V*19
$GNRMC,000033.00,V,,,,,,,020712,,,N,V*1F
$GNGGA,000033.00,,,,,0,00,99.0,,M,,M,,*48
$GNRMC,000025.00,V,,,,,,,020712,,,N,V*18
$GNGGA,000025.00,,,,,0,00,99.0,,M,,M,,*4F
$G$GNRMC,000034.00,V,,,,,,,020712,,,N,V*18
$GNGGA,000034.00,,,,,0,00,99.0,,M,,M,,*4F
$GNRMC,000026.00,V,,,,,,,020712,,,N,V*1B
$GNRMC,000035.00,V,,,,,,,020712,,,N,V*19
$GNGGA,000035.00,,,,,0,00,99.0,,M,,M,,*4E
$GNRMC,000027.00,V,,,,,,,020712,,,N,V*1A
$GNRMC,000036.00,V,,,,,,,020712,,,N,V*1A
$GNGGA,000036.00,,,,,0,00,99.0,,M,,M,,*4D
$GNRMC,000028.00,V,,,,,,,020712,,,N,V*15
$GNGGA,000028.00,,,,,0,00,99.0,,M,,M,,*42
$G$GNRMC,000037.00,V,,,,,,,020712,,,N,V*1B
$GNGGA,000037.00,,,,,0,00,99.0,,M,,M,,*4C
$GNRMC,000029.00,V,,,,,,,020712,,,N,V*14
$GNRMC,000038.00,V,,,,,,,020712,,,N,V*14
$GNGGA,000038.00,,,,,0,00,99.0,,M,,M,,*43
$GNRMC,000030.00,V,,,,,,,020712,,,N,V*1C
$GNRMC,000039.00,V,,,,,,,020712,,,N,V*15
$GNGGA,000039.00,,,,,0,00,99.0,,M,,M,,*42
$GNRMC,000031.00,V,,,,,,,020712,,,N,V*1D
$GNGGA,000031.00,,,,,0,00,99.0,,M,,M,,*4A
$G$GNRMC,000040.00,V,,,,,,,020712,,,N,V*1B
$GNGGA,000040.00,,,,,0,00,99.0,,M,,M,,*4C
$GNRMC,000032.00,V,,,,,,,020712,,,N,V*1E
$GNRMC,000041.00,V,,,,,,,020712,,,N,V*1A
$GNGGA,000041.00,,,,,0,00,99.0,,M,,M,,*4D
$GNRMC,000033.00,V,,,,,,,020712,,,N,V*1F
$GNRMC,000042.00,V,,,,,,,020712,,,N,V*19
$GNGGA,000042.00,,,,,0,00,99.0,,M,,M,,*4E
$GNRMC,000034.00,V,,,,,,,020712,,,N,V*18
$GNGGA,000034.00,,,,,0,00,99.0,,M,,M,,*4F

I managed to get rid of the ghosted bytes by copying  received data in a different buffer:

char frame_buffer[p_evt->data.rxtx.length];
strncpy(frame_buffer,p_evt->data.rxtx.p_data,p_evt->data.rxtx.length);

But it is still not reliable and I get random bytes appearing at some point. 

I would like to avoid ghost bytes in the first place. Any clue about the cause of this issue?

[Jørgen Holmefjord]

Hi,

How are you printing the strings? Could it be that you are missing string terminator character in the buffer, causing the print-function to continue printing the old string in the buffer until it hits a string terminator character?

Best regards,
Jørgen

[rchaudet]

You rock.

Indeed I deal with all those datas as strings and I parse them before use. 

I still had to add string terminator character manually to avoid dealing with garbage values:

p_event->data.rxtx.p_data[p_event->data.rxtx.length] = '\0';

Now everything works like a charm

[Jørgen Holmefjord]

Great to hear that it is working! Note that you may possibly overwrite other data or go out of bounds in the buffer when writing the string terminator to the libUARTE buffer itself, i.e., if the full libUARTE buffer is not full, the index where you write '\0' is also the index where the next byte will be written by the UARTE peripheral. If you are at the end of the buffer, you will write into the next address in RAM. This may work well now, but may generate unpredictable behavior in the future.

[rchaudet]

This is working fine as well:

    char frame_buffer[p_evt->data.rxtx.length+1];
    strncpy(frame_buffer,p_evt->data.rxtx.p_data,p_evt->data.rxtx.length);
    frame_buffer[p_evt->data.rxtx.length] = '\0';

I work with a copy so that I leave the libUARTE buffer alone