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]

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).

[daten]

Thanks for your pointers - I'll definitely give it a try.

Please mind though, that i'm *not* calling app_usbd_cdc_acm_write() in the *UART* interrupt handler (at least not as far as I know), but in the ble_nus_handler() - when I revćeive data via BLE.

This might have to do with it. Will check now and report back.

[Kenneth]

Sorry, in that case you likely need to move the USB interrupt priority to level 2 or 3:
https://infocenter.nordicsemi.com/topic/sds_s140/SDS/s1xx/processor_avail_interrupt_latency/exception_mgmt_sd.html 

[daten]

As a follow-up - with the following diff to the original example I can call nus_data_handler() - and within it app_usbd_cdc_acm_write() twice - without any issue.

So the it seems my issue is related to app_usbd_cdc_acm_write() being called within the BLE NUS interrupt.

diff --git a/examples/peripheral/usbd_ble_uart/main.c b/examples/peripheral/usbd_ble_uart/main.c 
index b8d030fa..87213ff2 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,22 @@ static void nus_data_handler(ble_nus_evt_t * p_evt) 
             length += sizeof(ENDLINE_STRING); 
         } 
 
+        NRF_LOG_INFO("app_usbd_cdc_acm_writer() :: 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); 
+            ret = app_usbd_cdc_acm_write(&m_app_cdc_acm, "foobar\r\n", 8); 
+            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); 
+            ret = app_usbd_cdc_acm_write(&m_app_cdc_acm, "foobar\r\n", 8); 
+            NRF_LOG_INFO("app_usbd_cdc_acm_write() (2) :: ret: %d", ret); 
+            NRF_LOG_FINAL_FLUSH(); 
+        } while (ret == NRF_ERROR_BUSY); 
     } 
 
 } 
@@ -861,6 +870,13 @@ int main(void) 
     ret = app_usbd_power_events_enable(); 
     APP_ERROR_CHECK(ret); 
 
+    ble_nus_evt_t * p_evt; 
+    memset(&p_evt, 0, sizeof(ble_nus_evt_t)); 
+    p_evt->type = BLE_NUS_EVT_RX_DATA; 
+ 
+    NRF_LOG_INFO("Entering main loop"); 
+    NRF_LOG_FINAL_FLUSH(); 
+ 
     // Enter main loop. 
     for (;;) 
     { 
@@ -869,6 +885,8 @@ int main(void) 
             /* Nothing to do */ 
         } 
         idle_state_handle(); 
+        nrf_delay_ms(500); 
+        nus_data_handler(p_evt); 
     } 
 } 
 

[daten]

I can confirm that changing the USB interrupt priority solves my problem. Thanks a lot!