nRF9151DK v0.9.0 USB UART stops working

[droberson]

Hello,

I have been developing on a nRF9151DK v0.9.0 for a few weeks now. So far this board is great! However, I have been running some long duration tests recently and logging through the default UART backend that is piped through the USB connector (J6) as a virtual COM port.

The issue I am seeing is that after some random amount of time (less than 24 hours), I no longer receive any UART messages. Yet, the COM port is still connected and open on the PC and the devkit application is still working as expected, indicated by LED activity.

I reproduced this with a simple example in the nRF Connect SDK:

My setup:

• Windows 11 PC
  • This PC never goes to sleep, only turns the screen off. I have another piece of hardware logging on a different COM port on the same machine for over a week now without interruption. It is a dedicated test PC, not my development PC. Thus, it is not being interacted with during my tests.
• nRF9151DK connected to PC via USB-C cable from J6, which is also powering the DK.
• Modem firmware: mfw_nrf91x1_2.0.1
• nRF Connect SDK / Toolchain: 2.9.0
• Terminal app: PuTTY
• nRF Connect Sample App: zephyr/samples/basic/blinky
• Build configuration
  • Board: nRF9151dk/nrf9151/ns
  • Leave the rest of the build configuration settings at their default values

Simply build the application, flash it onto the DK, and open the application COM port. You will see LED1 blink continuously along with the following repeated output:

*** Booting nRF Connect SDK v2.9.0-7787b2649840 ***
*** Using Zephyr OS v3.7.99-1f8f3dc29142 ***
LED state: OFF
LED state: ON
LED state: OFF
LED state: ON
LED state: OFF
LED state: ON
LED state: OFF
LED state: ON
LED state: OFF
LED state: ON
LED state: OFF

Let this run overnight and check it the next day. No more messages are received on the COM port yet the LED is still blinking.

Is this a known issue on this devkit? Seems like there are many points of potential failure. I imagine this UART is piped through the nRF5340 on the DK, maybe it's getting hung up there.

Any input would be appreciated. We plan to use a UART to talk to a co-processor in our final design so I want to mitigate any risks or issues. Hopefully this is an issue with the devkit or something other than the nRF9151 SOC.

Thanks,

Derek

[Sigurd Hellesvik]

Hi,

I assume you try to reconnect Putty right?

Does resetting work?

If you increase the frequency of the logging, will the error happen sooner?

Regards,
Sigurd Hellesvik

[droberson]

Hey Sigurd,

Sigurd Hellesvik said:

I assume you try to reconnect Putty right?

Putty never disconnects, the log messages just stop coming through. If I close putty and reopen it on the same COM port, the log messages start coming through again (Just tested this).

This makes me think the issue lies within the nRF5340 tunneling the UART messages though the USB ACM COM port.

Sigurd Hellesvik said:

Does resetting work?

I will wait another 24 hours to test this since I must wait for the failure to occur again and will report my findings.

Sigurd Hellesvik said:

If you increase the frequency of the logging, will the error happen sooner?

Since I am away from the office when the device fails, it is hard for me to time it. This particular example uses printf() and not the logging module. In light of this, I have updated the blinky sample to use the logging module with timestamps. My code is the following:

prj.conf:

CONFIG_GPIO=y

CONFIG_LOG=y
CONFIG_LOG_BUFFER_SIZE=8192

main.c:

/*
 * Copyright (c) 2016 Intel Corporation
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <stdio.h>
#include <zephyr/kernel.h>
#include <zephyr/drivers/gpio.h>
#include <zephyr/logging/log.h>

/* 1000 msec = 1 sec */
#define SLEEP_TIME_MS   100

/* The devicetree node identifier for the "led0" alias. */
#define LED0_NODE DT_ALIAS(led0)

LOG_MODULE_REGISTER(led,LOG_LEVEL_DBG);

/*
 * A build error on this line means your board is unsupported.
 * See the sample documentation for information on how to fix this.
 */
static const struct gpio_dt_spec led = GPIO_DT_SPEC_GET(LED0_NODE, gpios);

int main(void)
{
	int ret;
	bool led_state = true;

	if (!gpio_is_ready_dt(&led)) {
		return 0;
	}

	ret = gpio_pin_configure_dt(&led, GPIO_OUTPUT_ACTIVE);
	if (ret < 0) {
		return 0;
	}

	while (1) {
		ret = gpio_pin_toggle_dt(&led);
		if (ret < 0) {
			return 0;
		}

		led_state = !led_state;
		// printf("LED state: %s\n", led_state ? "ON" : "OFF");
		LOG_INF("LED state: %s", led_state ? "ON" : "OFF");
		k_msleep(SLEEP_TIME_MS);
	}
	return 0;
}

Note that I reduced SLEEP_TIME_MS from 1000 to 100. I will report the findings of my tests as mentioned above.

Thanks,

Derek

[droberson]

Hey Sigurd Hellesvik 

I let the devkit run overnight, and I see that it stopped logging again, but the COM port is still open as previously observed. The last series of log messages are:

[00:11:27.816,375] <inf> led: LED state: ON
[00:11:27.916,473] <inf> led: LED state: OFF
[00:11:28.016,571] <inf> led: LED state: ON
[00:11:28.116,668] <inf> led: LED state: OFF

Thus, it ran for 11 hours and 28 minutes with SLEEP_TIME_MS set to 100.

Sigurd Hellesvik said:

Does resetting work?

Pushing the reset button (SW5) does not resolve the issue. I see the nRF9151 SOC reset indicated by a momentary pause in the blinking of LED1. The COM port remains open but nothing comes through.

Closing and reopening the COM port resolves the issue as previously observed.

Sigurd Hellesvik said:

If you increase the frequency of the logging, will the error happen sooner?

Since my last test was the first one where I was logging timestamps, I have reverted SLEEP_TIME_MS from 100 to 1000 and will run another overnight test to see if it takes longer to occur. I will report my findings once I have them.

Edit: It could be PuTTY. My next test after this one will be to use a different terminal app.

Thanks,

Derek

[Sigurd Hellesvik]

Thanks for doing extensive testing here Derek!

droberson said:

Edit: It could be PuTTY. My next test after this one will be to use a different terminal app.

If it is not putty, I will report this as a bug internally and try to reproduce this myself as well.

[droberson]

Hey Sigurd,

I have completed some additional testing and here are my results.

SLEEP_TIME_MS 1000 with Putty last few messages received:

[00:14:44.556,427] <inf> led: LED state: OFF
[00:14:45.556,640] <inf> led: LED state: ON
[00:14:46.556,793] <inf> led: LED state: OFF

It ran for 14 minutes

SLEEP_TIME_MS 1000 with YAT (Yet Another Terminal):

[00:09:14.503,021] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[00:09:15.503,234] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[00:09:16.503,387] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[00:09:17.503,601] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[00:09:18.503,753] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[00:09:19.503,967] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[00:09:20.504,119] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[00:09:21.504,333] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[00:09:22.504,486] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[00:09:23.504,699] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[00:09:24.504,852] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[00:09:25.505,065] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[00:09:26.505,218] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m

<Closed and re-opened COM port here>

[36:00:21.127,136] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:22.127,288] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[36:00:23.127,502] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:24.127,655] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[36:00:25.127,868] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:26.128,021] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[36:00:27.128,234] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:28.128,387] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[36:00:29.128,601] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:30.128,753] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[36:00:31.128,967] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:32.129,119] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[36:00:33.129,333] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:34.129,486] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[36:00:35.129,699] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:36.129,852] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m
[36:00:37.130,065] <ESC>[0m<inf> led: LED state: ON<ESC>[0m
[36:00:38.130,218] <ESC>[0m<inf> led: LED state: OFF<ESC>[0m

It ran for 9 minutes. Note that I closed and reopened the COM port and it resumed logging, hence the gap in timestamps above.

I have compiled all test results below thus far for concise reference.

• SLEEP_TIME_MS 100
  • Logged via Putty
  • Stopped receiving UART messages after 11 hours and 28 minutes
• SLEEP_TIME_MS 1000
  • Logged via Putty
  • Stopped receiving UART messages after 14 minutes
• SLEEP_TIME_MS 1000
  • Logged via YAT (Yet Another Terminal)
  • Stopped receiving UART messages after 9 minutes

I thought of one more test to run to rule out any potential power saving stuff that Windows 11 might be doing on this USB port, and to rule out the devkit. I am going to run an overnight test on a nRF52840 devkit using the same blinky application with a 52840 build configuration and will report my findings.

Thanks,

Derek

[Sigurd Hellesvik]

Maybe I should have done this already, but better late than never:
I will get my hands on a nRF9151DK today and leave a test on over the night myself.

I run on Linux, so it will be a bit different at least.