Logging corrupts SMP response

[colar]

Hi,

I am trying to run logging and SMP over a single UART interface, which should be supported with CONFIG_UART_CONSOLE_MCUMGR.

However, the responses seem to be disturbed by logging functions (maybe when logging is taking place while the SMP request is coming in).
I use an uBlox Nora-B126 incorporating an nRF5340 and VS Code with nRF Connect SDK 2.3.0. To reproduce, I use these prj.conf options:

CONFIG_LOG=y
CONFIG_LOG_BACKEND_UART=y

CONFIG_UART_CONSOLE_MCUMGR=y
CONFIG_MCUMGR=y
CONFIG_MCUMGR_SMP_UART=y
CONFIG_MCUMGR_CMD_OS_MGMT=y
CONFIG_OS_MGMT_ECHO=y

with a simple main like this:

int main(void)
{

	while(1)
	{
		LOG_INF("test logging output");
		k_sleep(K_MSEC(100));
	}
}

To test the SMP client, I use mcumgr with a simple "echo hello". Usually I receive the answer and when montoring the traffic I can see both the request and response going over the serial interface:

Request:

06 09 41 42 4D 43 41 41 41 4A 41 41 42 44 41 4B 46 68 5A 47 56 6F 5A 57 78 73 62 78 6C 41 0A

..ABMCAAAJAABDAK FhZGVoZWxsbxlA.

Response:

06 09 41 42 51 44 41 41 41 4B 41 41 42 44 41 4C 39 68 63 6D 56 6F 5A 57 78 73 62 2F 2F 65 34 51 3D 3D 0A

..ABQDAAAKAABDAL 9hcmVoZWxsb//e4Q ==.

Sometimes however, the response is incomplete (first few bytes are missing) as this:

41 41 41 4B 41 41 43 65 41 4C 39 68 63 6D 56 6F 5A 57 78 73 62 2F 2B 4C 57 51 3D 3D 0A 5B 30 30 3A 30 39 3A 35 32 2E 39 31 37 2C 38 31 36 5D 20 1B 5B 30 6D 3C 69 6E 66 3E 20 6D 61 69 6E 3A 20 74 65 73 74 20 6C 6F 67 1B 5B 30 6D 0D 0A 5B 30 30 3A 30 39 3A 35 33 2E 30 31 37 2C 39 31 33 5D 20 1B 5B 30 6D 3C 69 6E 66 3E 20 6D 61 69 6E 3A 20 74 65 73 74 20 6C 6F 67 1B 5B 30 6D 0D 0A 5B 30 30 3A 30 39 3A 35 33 2E 31 31 37 2C 39 38 30 5D 20 1B 5B 30 6D 3C 69 6E 66 3E 20 6D 61 69 6E 3A 20 74 65 73 74 20 6C 6F 67 1B 5B 30 6D 0D 0A 5B 30 30 3A 30 39 3A 35 33 2E 32 31 38 2C 30 34 38 5D 20 1B 5B 30 6D 3C 69 6E 66 3E 20 6D 61 69 6E 3A 20 74 65 73 74 20 6C 6F 67 1B 5B 30 6D 0D 0A 5B 30 30 3A 30 39 3A 35 33 2E 33 31 38 2C 31 ... and so on until NMP timeout is reached

AAAKAACeAL9hcmVo ZWxsb/+LWQ==.[00 :09:52.917,816] .[0m<inf> main: test log.[0m..[0 0:09:53.017,913] .[0m<inf> main: test log.[0m..[ 00:09:53.117,980 ] .[0m<inf> main : test log.[0m.. [00:09:53.218,04 8] .[0m<inf> mai n: test log.[0m. .[00:09:53.318,1

Is this a known problem or is there something wrong with the configuration?

Best regards,
Lars

[Einar Thorsrud]

Hi Lars,

I discussed this with some colleagues and tested on my end (then with SMP server sample built with overlay-serial-console.conf and overlay-serial.conf), without being able to reproduce on my end. As you write, the header ("06 09") is missing. Where is the UART traffic dumped? Have you been able to narrow down where the header is lost/not added? Is it so that it is mcumgr that somehow did not add the header on some occasions?

[colar]

Hi Einar,

I use the tool Device Monitoring Studio to capture the trafic on the serial interface. The request from mcumgr is always ok while the response is missing its first few bytes occasionally.

It seems that this happens when there is currently some logging going on. Decreasing the wait time in the main loop makes it happen more often. I think it is not only the header missing but more like some of the first bytes getting lost - If you compare the valid response with the incomplete one in my example, it is not only 0x06 0x09 missing but a few more bytes (06 09 41 42 51 44). This feels like some synchronization issue with both logging and SMP sending bytes over the same interface.

If you could give some hints where (what C files etc.) to look/debug, I may be able to find out more.

Best regards,
Lars

[Einar Thorsrud]

Hi Lars,

I see. The implementation for the multiplexing is in the console implementation in zephyr/drivers/console/uart_console.c.

I should mention that this feature is quite old and a part of Zephyr, and not something we in Nordic has worked on or used, so I do not have any other specific suggestions or pointers at the moment, unfortunately.

Br,

Einar