Calls to app_usbd_cdc_acm_write() fail with NRF_ERROR_BUSY if CDC-ACM device is opened / read from

[daten]

I'm having the issue of where calling app_usbd_cdc_acm_write() more than once within the ble_nus_data_handler fails.

A test case is based on the "examples/peripheral/usbd_ble_uart/main.c"-example (SDK v16).

Diff to above mentioned vanilla example:

diff --git a/examples/peripheral/usbd_ble_uart/main.c b/examples/peripheral/usbd_ble_uart/main.c
index b8d030fa..dfd62b31 100644
--- a/examples/peripheral/usbd_ble_uart/main.c
+++ b/examples/peripheral/usbd_ble_uart/main.c
@@ -243,7 +243,7 @@ static void gap_params_init(void)
 */
 static void nus_data_handler(ble_nus_evt_t * p_evt)
 {
-
+ ret_code_t ret = 1;
 if (p_evt->type == BLE_NUS_EVT_RX_DATA)
 {
 bsp_board_led_invert(LED_BLE_NUS_RX);
@@ -259,14 +259,20 @@ static void nus_data_handler(ble_nus_evt_t * p_evt)
 length += sizeof(ENDLINE_STRING);
 }
 
+ NRF_LOG_INFO("app_usbd_cdc_acm_write() :: about to write to CDC-ACM dev");
+ NRF_LOG_FINAL_FLUSH();
+
 // Send data through CDC ACM
- ret_code_t ret = app_usbd_cdc_acm_write(&m_app_cdc_acm,
- m_nus_data_array,
- length);
- if(ret != NRF_SUCCESS)
- {
- NRF_LOG_INFO("CDC ACM unavailable, data received: %s", m_nus_data_array);
- }
+ do {
+ ret = app_usbd_cdc_acm_write(&m_app_cdc_acm, m_nus_data_array, length);
+ NRF_LOG_INFO("app_usbd_cdc_acm_write() (1) :: ret: %d", ret);
+ NRF_LOG_FINAL_FLUSH();
+ } while (ret == NRF_ERROR_BUSY);
+ do {
+ ret = app_usbd_cdc_acm_write(&m_app_cdc_acm, m_nus_data_array, length);
+ NRF_LOG_INFO("app_usbd_cdc_acm_write() (2) :: ret: %d", ret);
+ NRF_LOG_FINAL_FLUSH();
+ } while (ret == NRF_ERROR_BUSY);
 }
 
 }
@@ -621,7 +627,7 @@ static void buttons_leds_init(void)
 /** @brief Function for initializing the nrf_log module. */
 static void log_init(void)
 {
- ret_code_t err_code = NRF_LOG_INIT(NULL);
+ ret_code_t err_code = NRF_LOG_INIT(app_timer_cnt_get);

Since there's no example for the pca10059 board (nrf52840 USB dongle) I adapted the pca10056 one.

The Makefile only contains changes related to the board definition (PCA10056 -> PCA10059).

The sdk_config.h only has "NRF_LOG_BACKEND_UART_TX_PIN" and "NRF_LOG_USES_TIMESTAMP" changed compared to the pca10056 one.

Procedure:

1. powering up pca10059
2. open /dev/ttyACM0 on host
3. connect via BLE (nrf connect)
4. send string "qwertz"

Log output

[00:00:00.000,000] <info> app_timer: RTC: initialized.
[00:00:00.000,000] <info> app: USBD BLE UART example started.
[00:00:00.000,000] <info> app: USB power detected
[00:00:00.005,004] <info> app: USB ready
[00:00:05.362,487] <info> app: CDC ACM port opened
[00:00:08.517,456] <info> app: BLE NUS connected
[00:00:08.517,517] <info> app: Data len is set to 0x3D(61)
[00:00:13.517,578] <info> app: app_usbd_cdc_acm_write() :: about to write to CDC-ACM dev
[00:00:13.517,578] <info> app: app_usbd_cdc_acm_write() (1) :: ret: 0
[00:00:13.517,578] <info> app: app_usbd_cdc_acm_write() (2) :: ret: 17
[00:00:13.517,578] <info> app: app_usbd_cdc_acm_write() (2) :: ret: 17
[00:00:13.517,578] <info> app: app_usbd_cdc_acm_write() (2) :: ret: 17
[00:00:13.517,578] <info> app: app_usbd_cdc_acm_write() (2) :: ret: 17
[00:00:13.517,578] <info> app: app_usbd_cdc_acm_write() (2) :: ret: 17
[..]

All calls after the first one to app_usbd_cdc_acm_write() result in NRF_ERROR_BUSY being returned - indefinitely.

Everything is fine though, if I skip step 2), hence not opening /dev/ttyACM0 / reading from it on the host:

[00:00:00.000,000] <info> app_timer: RTC: initialized.
[00:00:00.000,000] <info> app: USBD BLE UART example started.
[00:00:00.000,000] <info> app: USB power detected
[00:00:00.005,004] <info> app: USB ready
[00:00:05.965,576] <info> app: BLE NUS connected
[00:00:06.026,123] <info> app: Data len is set to 0x3D(61)
[00:00:11.981,384] <info> app: app_usbd_cdc_acm_write() :: about to write to CDC-ACM dev
[00:00:11.989,624] <info> app: app_usbd_cdc_acm_write() (1) :: ret: 8
[00:00:11.995,971] <info> app: app_usbd_cdc_acm_write() (2) :: ret: 8

Please also note the different return calls from the first call to app_usbd_cdc_acm_write() each.

In the scenario where ttyACM is opened, it's 0, while where it isn't, it's 8.

[Kenneth]

I suggest to check out this thread for some suggestions:
https://devzone.nordicsemi.com/f/nordic-q-a/57011/nrf_cli_write-very-occasionally-hangs-waiting-for-tx_rdy-flag

[daten]

Thanks - I kinda checked out everything already I was able to find, incl. above thread.

Difference in all scenarios however is:

1) it never recovers from NRF_ERROR_BUSY in my case, while all the other threads discuss how to do the retry or wait for the "DONE" callback.

2) it doesn't happen occasionally, but reproducibly all the time at the second write call.

[Kenneth]

In what interrupt priority is nus_data_handler() running? I suggest to move app_usbd_cdc_acm_write() to main() in case the issue is related to interrupt priority level (uart >= usb).

[daten]

As stated above it's based on the peripheral/usbd_ble_uart example from SDK v16 - all modifications mentioned in my initial post. Since it's an official example, I somehow expect that's the way to do it (re moving the write call around)

[Kenneth]

I guess that app_usbd_cdc_acm_write() can be called one time in the default UART interrupt priority level before the implementation rely on the USB interrupt to be executed before next app_usbd_cdc_acm_write() can be called. So if you place more than one app_usbd_cdc_acm_write() in the UART interrupt handler it will be stuck forever, since the USB handler won't be executed. So I suggest to move app_usbd_cdc_acm_write() to main() or set the UART interrupt priority level to 7 (assuming USB interrupt priority level is 6 or below).