nRFSDK v17 libuarte cli example and logging float numbers

[Franz]

Dear all,

The forum is full of questions around printing floating point numbers, however, I have a rather strange issue where maybe someone can help.

I have a project based on the libuarte cli example (set up in VisualGDB using v17 of the SDK). cli with libuarte was chosen because the forum suggests that libuarte is the proper choice for exchanging rather big amounts of data.

I do some code profiling and for this, I have to print out floating point numbers (with as many digits "as possible") via the uart.

Since the logging backend uses libuarte cli as setup in the example, i have to send floats as strings, because sending "raw" data via cli is not possible. I could use a second UART to do so, but it is much easier to control the program and get debug data over the same interface.

Now, since NRF_LOG_FLOAT with the respective float markers is very limited in the number of digits, i use an approach like:

void write_out(float* float_array_p)
{
	char floatchar[15];
	
	for (int ii = 0; ii < 1024; ii++)
	{
		memset(floatchar, 0, sizeof(floatchar));
		sprintf(floatchar, "%14.9f", (float_array_p[ii]));
		NRF_LOG_RAW_INFO("%s,", NRF_LOG_PUSH(floatchar));
		while(NRF_LOG_PROCESS());
		cli_process();
	}
}

The code runs in the main context. While not elegant, it should work fine.

Now, I trigger the function and receive the data on the PC side where i interpret the numbers as floats again. This essentially works, but not all numbers receive with the specified number of digits. It seems that NRF_LOG_RAW_INFO does not always dela correctly with the (as it seems correct) string provided by sprintf.

For example, I receive something like

['0.261669427', '0.25', '0.251542121', '0.247047648', '0.242788866', '0.238817886', '0.235065147', '0.231475547', '0.228071377', '0.224838212', '0.22', '0.208597437', '0.199891493', '0.193471178', '0.188196659', '0.183472663']

 You can see the second number and in this case the 11th one just show 2 digits after the comma.

As far as I can tell (it is hard to debug, because even using the very same numbers as input, not always the same numbers are truncated in the received data!), the strings passed to the NRF_LOG_RAW functions are correct.

Any idea?

[Einar Thorsrud]

Hi,

You convert the floating point to string yourself, so that should not be related. Also, you write that all the strings passed to NRF_LOG_RAW is correct. If that is the case, then the issue could be related to buffer overflows so that strings are cropped, either on the nRF side or the receiving end.

Do you see the same behavior of you logg less or with a lower frequency? What happens if you set NRF_LOG_ALLOW_OVERFLOW to 0 in sdk_config.h (assuming it is not already)?

[Franz]

Hi Einar,

NRF_LOG_ALLOW_OVERFLOW is already at 0

If I look at the requested data directly in putty (i.e. in the terminal", i do not get any "logs dropped" messages.

Since I write the data from the uC to the PC in the loop as shown above, the uC should never run into a buffer overflow because in each iteration it has time to process the logs, right?

Also, since in the example I have shown above, the second value is already corrupted and the firmware has nothing else to do, this also does not seem like a buffer overflow. What else could I check?

//EDIT: Is it possible, that the cli module somehow "overwrites" data before inserting the "terminal style escape sequences"?

A snapshot of the raw string received on the PC side is e.g.

 

 0.025194759,cli:~$\x1b[6D\x1b[J   0.025259649,cli:~$\x1b[6D\x1b[J   0.025324948,cli:~$\x1b[6D\x1b[J   0.02,cli:~$\x1b[6D\x1b[J   0.025456227,cli:~$\x1b[6D\x1b[J

//EDIT 2:
It seems like the issues can be "solved" with a ridiculously big buffer for NRF_LOG_STR_PUSH_BUFFER_SIZE of 2048 and slight modification of the code to every time call log and cli process, i.e.

		NRF_LOG_RAW_INFO("%s,", NRF_LOG_PUSH(floatchar));
		while (NRF_LOG_PROCESS())
		{
			cli_process();
		}

Can you maybe tell me how (i.e. how often) I have to cavv NRF_LOG_PROCESS() and or cli_process per loop iteration? In my code portion I posted initially, It seems that the string cannot be processed by a single call to NRF_LOG_PROCESS() and that NRF_LOG_PROCESS does "more work" than a single call of cli_process can handle. Still, I would not suspect that I have to increase NRF_LOG_STR_PUSH_BUFFER_SIZE , because the doc says that NRF_LOG_PUSH just overwrites the existing string in the buffer, so I should get garbage values but the buffer should not increase. Instead It looks like something is filling up anf then starts overwriting data in the buffer.

Maybe you can give me some more insights on how to fix that problem. I suspect I have to add some kind of delay in the loop since cli somhow makes use of APP_TIMER for log processing?

[Einar Thorsrud]

Hi,

Regarding NRF_LOG_PROCESS() that only processes one entry at a time. And so it also makes sense to call cli_process() for every call, like you do now. I do not have full overview of the CLI module though, but I have asked one of the authors to look at it.