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]

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