nRF52DK nRF52832 UART asynchronous receive

[zazas321]

I am working through the Nordic Developer Academy and got stuck at lesson 4 (UART receive)

https://academy.nordicsemi.com/courses/nrf-connect-sdk-fundamentals/lessons/lesson-4-serial-communication-uart/topic/uart-driver/

In particular, I am confused about this part:

I have created a sample project and connected external CP2102 USB->Serial adapter to P0.06 and P0.08 pins.

The code that I use:

/*
 * Copyright (c) 2012-2014 Wind River Systems, Inc.
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr/kernel.h>
#include <zephyr/drivers/gpio.h>
#include "stdio.h"
#include "zephyr/drivers/uart.h"

const struct device *uart = DEVICE_DT_GET(DT_NODELABEL(uart0));

static uint8_t tx_buf[] =  {"nRF Connect SDK Fundamentals Course \n\r"};
static uint8_t rx_buf[10] = {0}; //A buffer to store incoming UART data 

const struct uart_config uart_cfg = {
		.baudrate = 115200,
		.parity = UART_CFG_PARITY_NONE,
		.stop_bits = UART_CFG_STOP_BITS_1,
		.data_bits = UART_CFG_DATA_BITS_8,
		.flow_ctrl = UART_CFG_FLOW_CTRL_NONE
	};

static void uart_cb(const struct device *dev, struct uart_event *evt, void *user_data)
{
	switch (evt->type) {
	
	case UART_TX_DONE:
		printf("transmission complete \n");
		break;

	case UART_TX_ABORTED:
		// do something
		break;
		
	case UART_RX_RDY:
		printf("rx rdy \n");
		if((evt->data.rx.len) != 0){
			printf("data received = %s \n", evt->data.rx.buf[evt->data.rx.offset]);
		}


		
		break;

	case UART_RX_BUF_REQUEST:
		printf("requesting buffer \n");
		// do something
		break;

	case UART_RX_BUF_RELEASED:
		printf("buffer released \n");
		// do something
		break;
		
	case UART_RX_DISABLED:
		printf("rx disabled \n");
		uart_rx_enable(dev, rx_buf, sizeof(rx_buf), 100);
		break;

	case UART_RX_STOPPED:
		// do something
		break;
		
	default:
		break;
	}
}


int main(void)
{	

	if (!device_is_ready(uart)) {
    	return;
	}

	int err;
	err = uart_callback_set(uart, uart_cb, NULL);
	if (err) {
		return err;
	}

	uart_rx_enable(uart, rx_buf, sizeof(rx_buf), 100);


	err = uart_tx(uart, tx_buf, sizeof(tx_buf), SYS_FOREVER_US);
	if (err) {
		return err;
	}



	while(1){
		k_msleep(1000);
	}
	return 0;
}

I am having issues understanding how to properly print out all the received data:

I tried to do:

	case UART_RX_RDY:
		printf("rx rdy \n");
		if((evt->data.rx.len) != 0){
			printf("data received = %s \n", evt->data.rx.buf[evt->data.rx.offset]);
		}

		break;

but when I send the data via UART (using Termite) , the following is printed:

I would appreciate if someone could clarify how to correctly print out all the received data.  Thanks in advance

Just for testing, I have also tried to print:

    case UART_RX_RDY:
        printf("rx rdy \n");
        printf("data: %s \n", rx_buf);
        break;

 

and the logs are as following: (captured using Termite):

 

As you can see, it receives the first message (ping) correctly, but after that, the buffer overflows (rx_buf is 10 bytes size) and then it cannot print out the data correctly)

[AHaug]

Hi,

Could you check the solution in the github repo and see if you're able to resolve what is wrong and then let me know if you're still having issues with resolving it and we'll get right back at to find you a solution? 

https://github.com/NordicDeveloperAcademy/ncs-fund 

Kind regards,
Andreas

[zazas321]

The solution in the repository shows how to toggle an LED when a serial message is received but it does not really show how to receive and print a longer serial message. I am interested in being able to receive and parse a longer serial message. For example when I receive messsage "ping", I want to respond with message "pong".

When I send message "toggle_led1" I want to turn ON the LED1 and so on...  In order for this to work I need to be able to receive and learn how to print the full received message.

The solution uses the following method to check what serial data has been received:

if(evt->data.rx.buf[evt->data.rx.offset] == '1')

So I try something simillar just for testing purposes:

	case UART_RX_RDY:
		printf("received message =  %s",evt->data.rx.buf[evt->data.rx.offset]);
		break;

The serial console logs when I send 2 messages (ping and hello):

As you can see from above, it does not work properly

[AHaug]

Thank you,

I finally had the time to look at your code. Apologies for why it took so long and to the frustration you must've felt. Response times gets a bit longer when we're nearing release of a new major version of the SDK (v2.5.0).

Your code works as expected when you're using asynch UART with static buffers (the central and peripheral_uart samples uses dynamically allocated buffers)

Why, you ask? 
This is the quick and dirty explanation: The uart-cb triggers either when the timeout you've set runs out (100ms) or when the buffer you've declared (16 bit) is filled. When you enter new messages and you the timeout expires before you're finished writing the message, you will be left with a message that is separated. In theory if the timeout is sufficiently small and you match your writing speed with the timeout, the callback can trigger 16 times and separate the message into 16 characters instead of 1.

Hello (6) + ping (5) + message1 (expected to be 9)  > 16: You see the callback trigger when both the timeout expires and the buffer length limit is reached

For further observation
Increase the timeout so you have time to write the new messages, and or play around with the buffer length (which is currently set to 16)

Please feel free to ask follow up questions if anything is unclear! 

Kind regards,
Andreas

[zazas321]

Thanks for your help. It is getting a little bit more clear, but I do not think my issues are related to the timeout. I really appreciate you taking your time to look into this!

However, I believe it is related to the way ring buffer works in Async UART.

I have increased UART_BUF_SIZE to 50, see the logs below:

What happens is that when I send messages via serial, the evt->data.rx.buf is slowly filling up. When it reaches the declared size (UART_BUF_SIZE), the condition:

memcpy(new_message.bytes, evt->data.rx.buf + evt->data.rx.offset, evt->data.rx.len);

 

will no longer be correct as half of the message can be at the end of the evt->data.rx.buf and the rest rolled over to the beginning of the buffer. Then pretty much all other messages after the ring buffer has been filled will be trashed (thats exactly what we see from the logs) . Do you see what I mean? 

Zephyr states that Async UART is the most efficient way to use UART but I cannot see a single real world application where it could be used since it is not capable of receiving a full message properly (unless there is an issue in my code and below is not correct). 

	case UART_RX_RDY:
		memcpy(new_message.bytes, evt->data.rx.buf + evt->data.rx.offset, evt->data.rx.len);
		new_message.length = evt->data.rx.len;
		if (k_msgq_put(&uart_rx_msgq, &new_message, K_NO_WAIT) != 0)
		{
			printk("Error: Uart RX message queue full!\n");
		}
		break;

Most UART applications relies on being able to receive and transmit a required size message length at once.

I was under the impression that the reason why we use double buffer is to avoid this problem and ensure that when the data rolled over, we can still get the full message at once but perhaps that is not the case.

Please tell me if that makes sense or I am completely misunderstanding how this works or how this supposed to work.

[AHaug]

Hi,

zazas321 said:

will no longer be correct as half of the message can be at the end of the evt->data.rx.buf and the rest rolled over to the beginning of the buffer. Then pretty much all other messages after the ring buffer has been filled will be trashed (thats exactly what we see from the logs) . Do you see what I mean? 

Yes, I see what you mean here. But the message is not trashed, you are simply starting to fill the other buffer (in the case of double buffer). What is missing here is some logic to determine if the complete message has been received and to combine the data from the two buffers into one. What you need to determine is among the following (could be other ways to do this as well, but this is at least one way to do it):

1. To determine the message has been completely transmitted (for instance if there is a termination on the final bit)
2. To determine if the message has been split, which is what you observe.
   1. In this case you will need to combine the messages from both buffers, i.e find where the split message ends in the second buffer to combine the messages into one message

In Torbjørns sample (ncs 1.9.1), the one I linked to earlier, you will still have to do this combining of the message. To do this, it is typically normal to use a messaging protocol such as SLIP. SLIP uses what is called an end of frame to determine when this occurs. Instead/in addition to using a start-of-field and/or end-of-field, you can also use a length field in your data making sure that you wait until you've received all your data that consists of the complete message and then do the missing logic I've described to combine the message. 

 async UART coming in broken packets Is another case that somewhat describes the same thing as you see that briefly mentions what the other developer has done

zazas321 said:

Please tell me if that makes sense or I am completely misunderstanding how this works or how this supposed to work.

So to summarize: you've not misunderstood this, but we're rather missing some steps in the implementation to make the double buffering work properly and to combine the messages that starts in one buffer and ends in the other

Kind regards,
Andreas

[zazas321]

Thanks again for your insights. I understand what you said. I am determined to get to the bottom of this. Once we are done here, this can then become official Async UART sample project as there is currently no complete Async projects out there to look at. I am sure there are more people like myself who are confused about Async UART and how to get it to behave properly.

Lets dive a little deeper into this please. I have modified my Async UART program a little bit (removed unnecessary code) and I have added extra printf statements to see what is happening under the hood and I am slighty confused about how uart_event.rx works. In particular uart_event.rx.len and uart_event.rx.offset

Full code can be found below:

/*
 * Copyright (c) 2012-2014 Wind River Systems, Inc.
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr/kernel.h>
#include <zephyr/drivers/gpio.h>
#include "stdio.h"
#include "my_gpio.h"
#include "zephyr/drivers/uart.h"
#include <zephyr/sys/ring_buffer.h>

#define LOG_LEVEL 4
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(nrf52_learning);

#define UART_BUF_SIZE 8

#define UART_RX_TIMEOUT_MS 1000
K_SEM_DEFINE(rx_disabled, 0, 1);



// UART RX primary buffers
uint8_t uart_double_buffer[2][UART_BUF_SIZE];

uint8_t *uart_buf_next = uart_double_buffer[1];

uint8_t complete_message[UART_BUF_SIZE];
uint8_t complete_message_counter = 0;
bool currently_active_buffer = 1; // 0 - uart_double_buffer[0] is active, 1 - uart_double_buffer[1] is active



static const struct device *dev_uart;

static void uart_cb(const struct device *dev, struct uart_event *evt, void *user_data)
{

	switch (evt->type)
	{

	case UART_TX_DONE:
		printf("transmission complete \n");
		break;

	case UART_TX_ABORTED:
		// do something
		break;

	case UART_RX_RDY:

		printf("Received %i bytes \n", evt->data.rx.len);
		printf("Offset = %i  \n", evt->data.rx.offset);

		printf("evt->data.rx.buf: [");
		for (int i = 0; i < UART_BUF_SIZE; i++)
		{
			printf("%u, ", evt->data.rx.buf[i]);
		}
		printf("] \n");

		printf("uart_double_buffer[0]: [");
		for (int i = 0; i < UART_BUF_SIZE; i++)
		{
			printf("%u, ", uart_double_buffer[0][i]);
		}
		printf("] \n");

		printf("uart_double_buffer[1]: [");
		for (int i = 0; i < UART_BUF_SIZE; i++)
		{
			printf("%u, ", uart_double_buffer[1][i]);
		}
		printf("] \n");

		printf("Constructing a complete message \n");
			if (currently_active_buffer == 0)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[0][i];
				complete_message_counter++;
				if (uart_double_buffer[0][i] == '\n')
				{
					printf("new line found at buffer 0 index = %i \n", i);
					complete_message_counter = 0;
					printf("complete_message = %s \n", complete_message);
					memset(&complete_message, 0, sizeof(complete_message)); // clear out the buffer to prepare for next read.
					break;
				}
			}
		}

		if (currently_active_buffer == 1)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[1][i];
				complete_message_counter++;
				if (uart_double_buffer[1][i] == '\n')
				{
					printf("new line found at buffer 1 index = %i \n", i);
					complete_message_counter = 0;
					printf("complete_message = %s \n", complete_message);
					memset(&complete_message, 0, sizeof(complete_message)); // clear out the buffer to prepare for next read.
					break;
				}
			}
		}



		break;

	case UART_RX_BUF_REQUEST:
		uart_rx_buf_rsp(dev_uart, uart_buf_next, UART_BUF_SIZE);
		currently_active_buffer = !currently_active_buffer;
		if (currently_active_buffer == 0)
		{
			printf("currently active buffer is uart_double_buffer[0] \n");
		}
		else
		{
			printf("currently active buffer is uart_double_buffer[1] \n");
		}
		break;

	case UART_RX_BUF_RELEASED:
		printf("Old buffer has been released \n");
		uart_buf_next = evt->data.rx_buf.buf;
		break;

	case UART_RX_DISABLED:
		printf("rx disabled \n");
		k_sem_give(&rx_disabled);
		break;

	case UART_RX_STOPPED:
		// do something
		break;

	default:
		break;
	}
}

void app_uart_init()
{
	dev_uart = DEVICE_DT_GET(DT_NODELABEL(uart0));

	if (!device_is_ready(dev_uart))
	{
		return 0;
	}

	int err;
	err = uart_callback_set(dev_uart, uart_cb, NULL);
	if (err)
	{
		return err;
	}
	uart_rx_enable(dev_uart, uart_double_buffer[0], UART_BUF_SIZE, UART_RX_TIMEOUT_MS);
}

int main(void)
{
	app_uart_init();

}

and also my git repository (I updated main branch):

github.com/.../nrf52_learning

I will briefly explain the logic of my code:

I use uart_double_buffering and I have also created a new variable complete_message. I will be using combination of uart_double_buffering[0] (first buffer) and uart_double_buffering[1] (second buffer) to keep track of when the received message has rolled over as you have suggested.

I always keep track of currently active buffer by using variable currently_active_buffer.

In my UART_RX_RDY, I do the following:

	case UART_RX_RDY:

		printf("Received %i bytes \n", evt->data.rx.len);
		printf("Offset = %i  \n", evt->data.rx.offset);

		printf("evt->data.rx.buf: [");
		for (int i = 0; i < UART_BUF_SIZE; i++)
		{
			printf("%u, ", evt->data.rx.buf[i]);
		}
		printf("] \n");

		printf("uart_double_buffer[0]: [");
		for (int i = 0; i < UART_BUF_SIZE; i++)
		{
			printf("%u, ", uart_double_buffer[0][i]);
		}
		printf("] \n");

		printf("uart_double_buffer[1]: [");
		for (int i = 0; i < UART_BUF_SIZE; i++)
		{
			printf("%u, ", uart_double_buffer[1][i]);
		}
		printf("] \n");

		printf("Constructing a complete message \n");
		if (currently_active_buffer == 0)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[0][i];
				complete_message_counter++;
				if (uart_double_buffer[0][i] == '\n')
				{
					printf("new line found at buffer 0 index = %i \n", i);
					complete_message_counter = 0;
					break;
				}
			}
		}

		if (currently_active_buffer == 1)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[1][i];
				complete_message_counter++;
				if (uart_double_buffer[1][i] == '\n')
				{
					printf("new line found at buffer 1 index = %i \n", i);
					complete_message_counter = 0;
					break;
				}
			}
		}
		printf("complete_message = %s \n", complete_message);

		// memcpy(new_message.bytes, evt->data.rx.buf + evt->data.rx.offset, evt->data.rx.len);
		// new_message.length = evt->data.rx.len;
		// if (k_msgq_put(&uart_rx_msgq, &new_message, K_NO_WAIT) != 0)
		// {
		// 	printk("Error: Uart RX message queue full!\n");
		// }

		break;

 

As you can see from the code above, I looking for an endline termination to determine where is the end of the message. I also use the evt->data.rx.offset to ensure that I start reading from the last end line detected.

Please look at the logs below:

I think we are slowly but surely moving forwards to finding proper solution for this.

At this point, I am not sure how exactly  uart_event.rx.len and uart_event.rx.offset works as it does not seem to show proper values once I change to second dual buffer.

I would highly appreciate if you could look at my code and the logs to see if you can make any sense out of it and understand what I am trying to achieve here 

[Achim Kraus]

Using empty UART_RX_BUF_REQUEST is causing the irritation. Once you implement the required callback uart_rx_buf_rsp, I guess the behavior will change.  

[zazas321]

Hello. What makes you think that my UART_RX_BUF_REQUEST is empty?

My UART_RX_BUF_REQUEST is as following:

	case UART_RX_BUF_REQUEST:
		uart_rx_buf_rsp(dev_uart, uart_buf_next, UART_BUF_SIZE);
		currently_active_buffer = !currently_active_buffer;
		if (currently_active_buffer == 0)
		{
			printf("currently active buffer is uart_double_buffer[0] \n");
		}
		else
		{
			printf("currently active buffer is uart_double_buffer[1] \n");
		}
		break;

And by debugging, I can see that it is switching the buffers as required. But the length and offset is still not correct.

If you have nrf52DK nRF52832 or nRF52840 NRF25840DK you can easily recreate the issue by using my code in main branch.

[Achim Kraus]

Unfortunately this forum doesn't really allow to answer to a specific comment. My answer was for the comment 2 days ago with the red lines.

[Achim Kraus]

I'm not sure, if the irritation you see is caused by a very short DMA buffer. I would try to use a larger ones. At least in my experience, the async UART works well. I use buffers with 256 bytes.

[AHaug]

 Achim Kraus  Thank you for the input, it's been very valuable to the discussion

Regarding answering directly to a specific comment, you can use the quote funcitonality. 
 

zazas321 said:

AHaug Hello. It has been a while. Perhaps you had some time to look at our latest discussion with Achim Kraus ?

We have discovered some interesting things about ASYNC UART and it would be really nice to get to the bottom of this.

@zazas321, I've seen the discussion that has been ongoing here and I have nothing more to contribute to it other than the items that has already been discussed.

I find in my own experiments as well that a larger buffer is required to allow for enough time to pass so that the buffers can fill, send, swap and empty properly

Kind regards,
Andreas

[zazas321]

It has been a while but I still believe some things are not fully clear regarding ASYNC UART. Perhaps some things will be clarified at some point:

POINT 1

The async UART lesson in the code academy (https://academy.nordicsemi.com/courses/nrf-connect-sdk-fundamentals/lessons/lesson-4-serial-communication-uart/topic/exercise-1-5/)
can only be used in cases where the fixed length serial data is being received which is not what most UART use cases are like.

POINT 2

In order to use async UART when trying to receive varying length serial data (strings) with terminator, double buffer approach should be used because we need to handle a scenario where the buffer fills up but the full message hasnt been received and we need to stitch 2 buffers together to build a complete message.

I have created some test code to test this out:

/*
 * Copyright (c) 2012-2014 Wind River Systems, Inc.
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr/kernel.h>
#include <zephyr/drivers/gpio.h>
#include "stdio.h"
#include "my_gpio.h"
#include "zephyr/drivers/uart.h"
#include <zephyr/sys/ring_buffer.h>

#define LOG_LEVEL 4
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(nrf52_learning);

#define UART_BUF_SIZE 24

#define UART_RX_TIMEOUT_MS 1000
K_SEM_DEFINE(rx_disabled, 0, 1);

// UART RX primary buffers
uint8_t uart_double_buffer[2][UART_BUF_SIZE];

uint8_t *uart_buf_next = uart_double_buffer[1];

uint8_t complete_message[UART_BUF_SIZE];
uint8_t complete_message_counter = 0;
bool currently_active_buffer = 1; // 0 - uart_double_buffer[0] is active, 1 - uart_double_buffer[1] is active

static const struct device *dev_uart;

static void uart_cb(const struct device *dev, struct uart_event *evt, void *user_data)
{

	switch (evt->type)
	{

	case UART_TX_DONE:
		printf("transmission complete \n");
		break;

	case UART_TX_ABORTED:
		// do something
		break;

	case UART_RX_RDY:

		printf("Received %i bytes \n", evt->data.rx.len);
		printf("Offset = %i  \n", evt->data.rx.offset);

		printf("Constructing a complete message \n");
		if (currently_active_buffer == 0)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[0][i];
				complete_message_counter++;
				if (uart_double_buffer[0][i] == '\n')
				{
					printf("new line found at buffer 0 index = %i \n", i);
					complete_message_counter = 0;
					printf("complete_message = %s \n", complete_message);
					memset(&complete_message, 0, sizeof(complete_message)); // clear out the buffer to prepare for next read.
					break;
				}
			}
		}

		if (currently_active_buffer == 1)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[1][i];
				complete_message_counter++;
				if (uart_double_buffer[1][i] == '\n')
				{
					printf("new line found at buffer 1 index = %i \n", i);
					complete_message_counter = 0;
					printf("complete_message = %s \n", complete_message);
					memset(&complete_message, 0, sizeof(complete_message)); // clear out the buffer to prepare for next read.
					break;
				}
			}
		}

		break;

	case UART_RX_BUF_REQUEST:
		uart_rx_buf_rsp(dev_uart, uart_buf_next, UART_BUF_SIZE);
		currently_active_buffer = !currently_active_buffer;
		if (currently_active_buffer == 0)
		{
			printf("currently active buffer is uart_double_buffer[0] \n");
		}
		else
		{
			printf("currently active buffer is uart_double_buffer[1] \n");
		}
		break;

	case UART_RX_BUF_RELEASED:
		printf("Old buffer has been released \n");
		uart_buf_next = evt->data.rx_buf.buf;
		break;

	case UART_RX_DISABLED:
		printf("rx disabled \n");
		k_sem_give(&rx_disabled);
		break;

	case UART_RX_STOPPED:
		// do something
		break;

	default:
		break;
	}
}

void app_uart_init()
{
	dev_uart = DEVICE_DT_GET(DT_NODELABEL(uart0));

	if (!device_is_ready(dev_uart))
	{
		return 0;
	}

	int err;
	err = uart_callback_set(dev_uart, uart_cb, NULL);
	if (err)
	{
		return err;
	}
	uart_rx_enable(dev_uart, uart_double_buffer[0], UART_BUF_SIZE, UART_RX_TIMEOUT_MS);
}

int main(void)
{
	app_uart_init();
}

and prj.conf

CONFIG_SERIAL=y
CONFIG_UART_ASYNC_API=y
CONFIG_LOG=y

And I have tested it out on the nRF52840DK NRF52840

The problem with the above code is that once the buffer fills up (UART_BUF_SIZE set to 24), the complete message will not be constructed properly out of 2 buffers. This can be easily observed here:

POINT 3

After many hours of debugging the code above, I have figured out what was causing the issues. It turned out to be printf staments. I have removed most of the printf statements and only left the complete_message print. The full code:

/*
 * Copyright (c) 2012-2014 Wind River Systems, Inc.
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr/kernel.h>
#include <zephyr/drivers/gpio.h>
#include "stdio.h"
#include "my_gpio.h"
#include "zephyr/drivers/uart.h"
#include <zephyr/sys/ring_buffer.h>

#define LOG_LEVEL 4
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(nrf52_learning);

#define UART_BUF_SIZE 24

#define UART_RX_TIMEOUT_MS 1000
K_SEM_DEFINE(rx_disabled, 0, 1);

// UART RX primary buffers
uint8_t uart_double_buffer[2][UART_BUF_SIZE];

uint8_t *uart_buf_next = uart_double_buffer[1];

uint8_t complete_message[UART_BUF_SIZE];
uint8_t complete_message_counter = 0;
bool currently_active_buffer = 1; // 0 - uart_double_buffer[0] is active, 1 - uart_double_buffer[1] is active

static const struct device *dev_uart;

static void uart_cb(const struct device *dev, struct uart_event *evt, void *user_data)
{

	switch (evt->type)
	{

	case UART_TX_DONE:
		//printf("transmission complete \n");
		break;

	case UART_TX_ABORTED:
		// do something
		break;

	case UART_RX_RDY:

		//printf("Received %i bytes \n", evt->data.rx.len);
		//printf("Offset = %i  \n", evt->data.rx.offset);

		//printf("Constructing a complete message \n");
		if (currently_active_buffer == 0)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[0][i];
				complete_message_counter++;
				if (uart_double_buffer[0][i] == '\n')
				{
					//printf("new line found at buffer 0 index = %i \n", i);
					complete_message_counter = 0;
					printf("complete_message = %s \n", complete_message);
					memset(&complete_message, 0, sizeof(complete_message)); // clear out the buffer to prepare for next read.
					break;
				}
			}
		}

		if (currently_active_buffer == 1)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[1][i];
				complete_message_counter++;
				if (uart_double_buffer[1][i] == '\n')
				{
					//printf("new line found at buffer 1 index = %i \n", i);
					complete_message_counter = 0;
					printf("complete_message = %s \n", complete_message);
					memset(&complete_message, 0, sizeof(complete_message)); // clear out the buffer to prepare for next read.
					break;
				}
			}
		}

		break;

	case UART_RX_BUF_REQUEST:
		uart_rx_buf_rsp(dev_uart, uart_buf_next, UART_BUF_SIZE);
		currently_active_buffer = !currently_active_buffer;
		if (currently_active_buffer == 0)
		{
			//printf("currently active buffer is uart_double_buffer[0] \n");
		}
		else
		{
			//printf("currently active buffer is uart_double_buffer[1] \n");
		}
		break;

	case UART_RX_BUF_RELEASED:
		//printf("Old buffer has been released \n");
		uart_buf_next = evt->data.rx_buf.buf;
		break;

	case UART_RX_DISABLED:
		//printf("rx disabled \n");
		k_sem_give(&rx_disabled);
		break;

	case UART_RX_STOPPED:
		// do something
		break;

	default:
		break;
	}
}

void app_uart_init()
{
	dev_uart = DEVICE_DT_GET(DT_NODELABEL(uart0));

	if (!device_is_ready(dev_uart))
	{
		return 0;
	}

	int err;
	err = uart_callback_set(dev_uart, uart_cb, NULL);
	if (err)
	{
		return err;
	}
	uart_rx_enable(dev_uart, uart_double_buffer[0], UART_BUF_SIZE, UART_RX_TIMEOUT_MS);
}

int main(void)
{
	app_uart_init();
}

and prj.conf:

CONFIG_SERIAL=y
CONFIG_UART_ASYNC_API=y
CONFIG_LOG=y

And when I try to send the exact same sequence of messages using serial terminal, it seems to work fine even after the UART buffer fills up:

POINT 4

4. Additionally, I have found out that if you add options :

CONFIG_UART_0_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC_TIMER=2
CONFIG_NRFX_TIMER2=y

in the prj.conf, then the complete messages will be received even if I use many printf statements. I do not fully understand why and how which is quite frustrating.

The full code:

/*
 * Copyright (c) 2012-2014 Wind River Systems, Inc.
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr/kernel.h>
#include <zephyr/drivers/gpio.h>
#include "stdio.h"
#include "my_gpio.h"
#include "zephyr/drivers/uart.h"
#include <zephyr/sys/ring_buffer.h>

#define LOG_LEVEL 4
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(nrf52_learning);

#define UART_BUF_SIZE 24

#define UART_RX_TIMEOUT_MS 1000
K_SEM_DEFINE(rx_disabled, 0, 1);

// UART RX primary buffers
uint8_t uart_double_buffer[2][UART_BUF_SIZE];

uint8_t *uart_buf_next = uart_double_buffer[1];

uint8_t complete_message[UART_BUF_SIZE];
uint8_t complete_message_counter = 0;
bool currently_active_buffer = 1; // 0 - uart_double_buffer[0] is active, 1 - uart_double_buffer[1] is active

static const struct device *dev_uart;

static void uart_cb(const struct device *dev, struct uart_event *evt, void *user_data)
{

	switch (evt->type)
	{

	case UART_TX_DONE:
		printf("transmission complete \n");
		break;

	case UART_TX_ABORTED:
		// do something
		break;

	case UART_RX_RDY:

		printf("Received %i bytes \n", evt->data.rx.len);
		printf("Offset = %i  \n", evt->data.rx.offset);

		printf("Constructing a complete message \n");
		if (currently_active_buffer == 0)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[0][i];
				complete_message_counter++;
				if (uart_double_buffer[0][i] == '\n')
				{
					printf("new line found at buffer 0 index = %i \n", i);
					complete_message_counter = 0;
					printf("complete_message = %s \n", complete_message);
					memset(&complete_message, 0, sizeof(complete_message)); // clear out the buffer to prepare for next read.
					break;
				}
			}
		}

		if (currently_active_buffer == 1)
		{
			// read all characters one by one till new line is found
			for (int i = 0 + evt->data.rx.offset; i < UART_BUF_SIZE; i++)
			{
				complete_message[complete_message_counter] = uart_double_buffer[1][i];
				complete_message_counter++;
				if (uart_double_buffer[1][i] == '\n')
				{
					printf("new line found at buffer 1 index = %i \n", i);
					complete_message_counter = 0;
					printf("complete_message = %s \n", complete_message);
					memset(&complete_message, 0, sizeof(complete_message)); // clear out the buffer to prepare for next read.
					break;
				}
			}
		}

		break;

	case UART_RX_BUF_REQUEST:
		uart_rx_buf_rsp(dev_uart, uart_buf_next, UART_BUF_SIZE);
		currently_active_buffer = !currently_active_buffer;
		if (currently_active_buffer == 0)
		{
			printf("currently active buffer is uart_double_buffer[0] \n");
		}
		else
		{
			printf("currently active buffer is uart_double_buffer[1] \n");
		}
		break;

	case UART_RX_BUF_RELEASED:
		printf("Old buffer has been released \n");
		uart_buf_next = evt->data.rx_buf.buf;
		break;

	case UART_RX_DISABLED:
		printf("rx disabled \n");
		k_sem_give(&rx_disabled);
		break;

	case UART_RX_STOPPED:
		// do something
		break;

	default:
		break;
	}
}

void app_uart_init()
{
	dev_uart = DEVICE_DT_GET(DT_NODELABEL(uart0));

	if (!device_is_ready(dev_uart))
	{
		return 0;
	}

	int err;
	err = uart_callback_set(dev_uart, uart_cb, NULL);
	if (err)
	{
		return err;
	}
	uart_rx_enable(dev_uart, uart_double_buffer[0], UART_BUF_SIZE, UART_RX_TIMEOUT_MS);
}

int main(void)
{
	app_uart_init();
}

and prj.conf:

CONFIG_SERIAL=y
CONFIG_UART_ASYNC_API=y
CONFIG_LOG=y



CONFIG_UART_0_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC_TIMER=2
CONFIG_NRFX_TIMER2=y

Despite the solution being found, it is still not fully clear to me what is the best way to handle ASYNC UART varying length data reception. I could not find enough information/examples available to fully understand the different methods of handling ASYNC UART reception and I am hoping to get some clarifications regarding this.

• Is this expected behaviour that a few printf statements in uart_cb causes weird behaviour as have been shown above?

•  If above is true, I am concerned about other high priority tasks or callbacks interrupting the UART reception and causing similar issues even when all print statements are removed from the callback itself. Is ASYNC UART affected by other Zephyr RTOS threads running or it is independent and not affected at all?

• During the discussion above it has been mentioned that it is recommended to use larger UART_BUF_SIZE but that did not help in any way. The only thing that does is just simply requires more serial data to be received before it fills up and eventually breaks.

• Throughout this discussion, other things have been suggested such as using additional config options:

CONFIG_UART_0_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC_TIMER=2
CONFIG_NRFX_TIMER2=y

which seem to help when having multiple print statements in the callback. 

I would highly appreciate if someone with good Zephyr and ASYNC UART knowledge could shed some light here and cover the issues that I have encountered and the solutions that I have found. I believe the solutions that I have discovered are not the most optimal and not the best way to handle UART ASYNC data reception. I also believe that this should be relevant for other developers who are working with ASYNC UART.