Random lockup on Serial Activity and BLE Enabled

[innoagg]

Describe the bug

When sending and receiving data over the USB CDC Serial the module will randomly lockup.

Set up (please complete the following information)

• pca10059, pca10056
• Windows 10
• No debug log information available. See steps to reproduce.

To Reproduce
Steps to reproduce the behavior:

1: Run this minimal code on the module:

#include <stdio.h>
#include <Arduino.h>
#include <bluefruit.h>

// the setup function runs once when you press reset or power the board
void setup() {

  Serial.begin(115200);
  //Bluefruit.begin(0, 1);
  
}

// the loop function runs over and over again forever
void loop() {

  if (Serial) { 
    if (Serial.availableForWrite()) {
      Serial.write("|", 1);  
    }
  }
  
}

2. Open the serial port from a PC terminal.

With the "Bluefruit.begin()" commented out you should observe that a stream of data will be received indefinitely as long as the port is open.

When running the code with the Bluefruit.begin() uncommented you should observe that the module will lock up after a short period of time. Sometimes after ~20kb of data sent and sometimes only after a ~100bytes. But it will always lockup in a relatively short amount of time.

In a real-world application I see the lockup occur at random times. Sometime hours and sometimes days. The amount of data transferred over the serial port does not appears to be a factor. The example above creates an extreme condition that produces the same lockup situation reliably in a short amount of time.

The lockup does not appear to coincide with the size of the data sent and it is also preset when simulating data received on the module, not just sending as the example above shows.

Expected behavior

Sending / receiving data over serial should not lockup the module or corrupt the serial buffers.

Additional context

I accept that the root issue may not be directly related to Bluefruit.begin() but this was the way I get the issue to present itself reliably. I do use the BLE library in my application and nothing else.

[innoagg]

Would anyone at least confirm what I am observing even if your board type is not the same as mine? Should my expectation be different?

[pyro9]

Confirmed on a Feather Express 52840.
Adding an explicit yield after the Serial.write does not help.
Replacing write with Serial.printf("|") does not help.

When I define a static variable and do Serial.printf("%u\n",i++); instead, it does not lock up.

Serial.printf("|\n"); locks up.

In all cases, commenting Bluefruit.begin(0, 1); out results in no lock up.

It looks like it is the serial output itself that is locking up rather than the device itself. If I add:
digitalWrite(LED_RED, ((millis()/500)&1));

to the loop outside of if(Serial), the led continues flashing even after serial output stops, showing that loop() is still being called regularly.

#include <bluefruit.h>


void setup() {
  // put your setup code here, to run once:
  Serial.begin(115200);
  pinMode(LED_RED, OUTPUT);
  digitalWrite(LED_RED, 1);
  Bluefruit.begin(0, 1);
  while(!Serial)
    yield;
}

void loop() {
  static int i=0;
  // put your main code here, to run repeatedly:
  if (Serial) {
    if (Serial.availableForWrite()) {
//      Serial.printf("%u\n",i++);
        Serial.printf("|\n");
//      Serial.write("/",1);
    }
  }
  digitalWrite(LED_RED, ((millis()/500)&1));
}

[innoagg]

Thanks for testing this and verifying what I see. I did look closer and I misdiagnosed the effect as a "lockup". My app had some logic that was blocking so when the serial feed stopped it locked up. As you say it appears to be confined to the serial buffers and the processor is still operating.

That said, I could not get any success with the Bluefruit lib added and using printf as you described. Unless I misunderstood your comment.

So, if anyone has ideas for where the issue might originate from ???? Places to look perhaps in the softdevice?

[pyro9]

Not sure about the cause, but I would suggest looking at cores/nRF5/TinyUSB

[innoagg]

I worked backwards through the Bluefruit.Begin and if I comment out the line indicated below the issue goes away...at least for Serial.write() in this simple test. Still have an issue with Serial.read() becoming non-functional after streaming data from the PC to the module, but I wonder if this prompts any thoughts from those much more knowledgeable than me about how the Bluefruit library initializes and how it might be corrupting the CDC buffers?

//NRFX_IRQ_DISABLE(nrfx_get_irq_number(NRF_POWER));

[nrfx_power.c]

void nrfx_power_uninit(void)
{
    NRFX_ASSERT(m_initialized);

#if NRFX_CHECK(NRFX_CLOCK_ENABLED)
    if (!nrfx_clock_irq_enabled)
#endif
    {
        //NRFX_IRQ_DISABLE(nrfx_get_irq_number(NRF_POWER));
    }

#if NRF_POWER_HAS_POFCON
    nrfx_power_pof_uninit();
#endif
#if NRF_POWER_HAS_SLEEPEVT
    nrfx_power_sleepevt_uninit();
#endif
#if NRF_POWER_HAS_USBREG
    nrfx_power_usbevt_uninit();
#endif
    m_initialized = false;
}

The Bluefruit library does not operate without the line above so its not a workaround to my issue, just used to perhaps shed light on the root cause. I tried increasing the CDC buffer sizes also without success.

#define CFG_TUD_CDC_RX_BUFSIZE      512
#define CFG_TUD_CDC_TX_BUFSIZE      512
#define CFG_TUD_CDC_EPSIZE          512

[hathach]

thank for filing the issue, please also provide the BSP version where this bug is found and update your post to put all the code inside code/quote block for readability

[innoagg]

Updated posts. Thanks.

I originally discovered issues on 0.14.0, but verified the same behavior on the latest 0.20.1 before I posted (well...was the latest until yesterday).

As indicated above it was also reproduced on a Feather Express 52840.

In my case I created support for the PCA10059 because I did not see it in the BSP list. It is a just variant of the PCA10056.

Variant I used below:

[variant.cpp]

#include "variant.h"
#include "wiring_constants.h"
#include "wiring_digital.h"
#include "nrf.h"


const uint32_t g_ADigitalPinMap[] =
{
  // P0
  0 , 1 , 2 , 3 , 4 , 5 , 6 , 7 ,
  8 , 9 , 10, 11, 12, 13, 14, 15,
  16, 17, 18, 19, 20, 21, 22, 23,
  24, 25, 26, 27, 28, 29, 30, 31,

  // P1
  32, 33, 34, 35, 36, 37, 38, 39,
  40, 41, 42, 43, 44, 45, 46, 47,
  48, 49, 50, 51, 52, 53, 54, 55,
  56, 57, 58, 59, 60, 61, 62, 63
};


void initVariant()
{
  // LED1 & LED2
  pinMode(PIN_LED1, OUTPUT);
  ledOn(PIN_LED1);

  pinMode(PIN_LED2_R, OUTPUT);
  ledOn(PIN_LED2_R);

  pinMode(PIN_LED2_G, OUTPUT);
  ledOn(PIN_LED2_G);

  pinMode(PIN_LED2_B, OUTPUT);
  ledOn(PIN_LED2_B);

  // Init External Flash
  //flash_qspi_init();  // Dongle does not have external flash

  // USB init  TODO may have trouble with ISR when SD is enabled
  //usb_init();
}

[variant.h]

#ifndef _VARIANT_PCA10059_
#define _VARIANT_PCA10059_

/** Master clock frequency */
#define VARIANT_MCK       (64000000ul)

#define USE_LFXO      // Board uses 32khz crystal for LF
// define USE_LFRC    // Board uses RC for LF

/*----------------------------------------------------------------------------
 *        Headers
 *----------------------------------------------------------------------------*/

#include "WVariant.h"

#ifdef __cplusplus
extern "C"
{
#endif // __cplusplus

// Number of pins defined in PinDescription array
#define PINS_COUNT           (64)
#define NUM_DIGITAL_PINS     (64)
#define NUM_ANALOG_INPUTS    (6)
#define NUM_ANALOG_OUTPUTS   (0)

// LEDs
#define PIN_LED1             (6)      // Primary LED in Bootloader
#define PIN_LED2_R           (8)
#define PIN_LED2_G           (41)     //P1.09
#define PIN_LED2_B           (12)     //P0.12 // Secondary in Bootloader

#define LED_BUILTIN          PIN_LED1
#define LED_CONN             PIN_LED2_B

#define LED_RED              PIN_LED2_R
#define LED_BLUE             PIN_LED2_B
#define LED_GREEN            PIN_LED2_G

#define LED_STATE_ON         0         // State when LED is litted

/*
 * Analog pins
 */
#define PIN_A0               (2)       //P0.02 
#define PIN_A1               (0xff)    //P0.03 not connected
#define PIN_A2               (4)       //P0.04
#define PIN_A3               (0xff)    //P0.05 not connected
#define PIN_A4               (0xff)    //P0.28 not connected
#define PIN_A5               (29)      //P0.29
#define PIN_A6               (0xff)    //P0.30 not connected
#define PIN_A7               (31)      //P0.31

static const uint8_t A0  = PIN_A0 ;
static const uint8_t A1  = PIN_A1 ;
static const uint8_t A2  = PIN_A2 ;
static const uint8_t A3  = PIN_A3 ;
static const uint8_t A4  = PIN_A4 ;
static const uint8_t A5  = PIN_A5 ;
static const uint8_t A6  = PIN_A6 ;
static const uint8_t A7  = PIN_A7 ;
#define ADC_RESOLUTION    14

// Other pins
#define PIN_AREF           (2)       //P0.02           
#define PIN_DFU            (38)      //P1.06
#define PIN_NFC1           (9)       //P0.09 
#define PIN_NFC2           (10)      //P0.10 

static const uint8_t AREF = PIN_AREF;

/*
 * Serial interfaces
 */

#define PIN_SERIAL_RX       (33) // P1.01
#define PIN_SERIAL_TX       (34) // P1.02

// Arduino Header D0, D1
#define PIN_SERIAL1_RX      (33) // P1.01
#define PIN_SERIAL1_TX      (34) // P1.02

// Connected to Jlink CDC
#define PIN_SERIAL2_RX      (8)
#define PIN_SERIAL2_TX      (6)

/*
 * SPI Interfaces
 */
#define SPI_INTERFACES_COUNT 1

#define PIN_SPI_MISO         (46)            //P1.10
#define PIN_SPI_MOSI         (45)            //P1.13
#define PIN_SPI_SCK          (47)            //P1.15

static const uint8_t SS   = 40;              //P1.08  
static const uint8_t MOSI = PIN_SPI_MOSI ;
static const uint8_t MISO = PIN_SPI_MISO ;
static const uint8_t SCK  = PIN_SPI_SCK ;

/*
 * Wire Interfaces
 */
#define WIRE_INTERFACES_COUNT 1

#define PIN_WIRE_SDA         (13)             //P0.13
#define PIN_WIRE_SCL         (15)             //P0.15

/*
 * QSPI interface for external flash
 */
#define PIN_QSPI_SCK         16               //not connected
#define PIN_QSPI_CS          5                //not connected
#define PIN_QSPI_DATA0       3                //not connected
#define PIN_QSPI_DATA1       7                //not connected
#define PIN_QSPI_DATA2       34               //not connected
#define PIN_QSPI_DATA3       27               //not connected

// On-board QSPI Flash
// If EXTERNAL_FLASH_DEVICES is not defined, all supported devices will be used
#define EXTERNAL_FLASH_DEVICES   GD25Q16C

#ifdef __cplusplus
}
#endif

/*----------------------------------------------------------------------------
 *        Arduino objects - C++ only
 *----------------------------------------------------------------------------*/

#endif

[hathach]

I am able to reproduce the issue. This one is rather troublesome, it is not too clear to me where it is stuck. Any LOG message probably mess up the timing for lockup. Unfortunately It may take a bit of time to fix this. I will post if there is any update.

[innoagg]

I appreciate the feedback very much. If there is anything I can do to help let me know. This is a critical issue for us at the moment. I wish we had discovered it earlier in our development, but we are where we are. I'm not sure how this group works, but any incentive I can offer I am open to it.

[hathach]

If I have the time to analyze this, I will start with ozone
https://learn.adafruit.com/introducing-the-adafruit-nrf52840-feather/faqs#faq-2860855
to see where the CPU is hanged. If not, it probably due to FreeRTOS deadblock due to mutex/semaphore etc ... We could enable the Debug Level 3 and try to analyze the freeRTOS event with Segger Sysview software.

you could try to dive into that direction, though both USB and Bluetooth can be a bit comprehensive to make sense at the same time. Though I could help with analysis if you could spot anything obvious.

[innoagg]

Running the serial test with Ozone I don't see anything out of place right up to the moment the xQueueGenericSendFromISR stops firing. The CPU never locks up. I think we clarified in the earlier posts that we did not see CPU lockup as I had originally thought. Did you?

[innoagg]

Correction, I had written "Ozone" above...that was from SystemView.

[pyro9]

Agree with @innoagg, CPU is still running, loop() in application still running.
As a further data point, I connected a battery to the feather express so I could force a complete reset of USB. Each time I unplug then replug the USB, I get another burst of output bytes then output stalls again.

[pyro9]

Digging deeper, The interaction at the heart of this seems to be receipt of DCD_EVENT_XFER_COMPLETE in tud_task clears the busy flag, the busy flag set in usbd_edpt_xfer, and usbd_edpt_xfer called in tud_cdc_n_write_flush and the busy flag set there.

bool usbd_edpt_xfer(uint8_t rhport, uint8_t ep_addr, uint8_t * buffer, uint16_t total_bytes)
{
  uint8_t const epnum = tu_edpt_number(ep_addr);
  uint8_t const dir   = tu_edpt_dir(ep_addr);

  TU_VERIFY( dcd_edpt_xfer(rhport, ep_addr, buffer, total_bytes) );
  _usbd_dev.ep_status[epnum][dir].busy = true;

  TU_LOG2("  XFER Endpoint: 0x%02X, Bytes: %d\r\n", ep_addr, total_bytes);

  return true;
}

Any chance of a race between tud_task getting the DCD_EVENT_XFER_COMPLETE event and usbd_edpt_xfer setting the busy flag (leaving the busy flag set with nothing to clear it)?

[pyro9]

@innoagg , @hathach , Please try the following patch:

diff --git a/tinyusb/src/device/usbd.c b/tinyusb/src/device/usbd.c
index 80f7dcc..2c65d15 100644
--- a/tinyusb/src/device/usbd.c
+++ b/tinyusb/src/device/usbd.c
@@ -960,8 +960,8 @@ bool usbd_edpt_xfer(uint8_t rhport, uint8_t ep_addr, uint8_t * buffer, uint16_t
   uint8_t const epnum = tu_edpt_number(ep_addr);
   uint8_t const dir   = tu_edpt_dir(ep_addr);
 
-  TU_VERIFY( dcd_edpt_xfer(rhport, ep_addr, buffer, total_bytes) );
   _usbd_dev.ep_status[epnum][dir].busy = true;
+  TU_VERIFY( dcd_edpt_xfer(rhport, ep_addr, buffer, total_bytes) );^M
 
   TU_LOG2("  XFER Endpoint: 0x%02X, Bytes: %d\r\n", ep_addr, total_bytes);

Setting the busy flag in anticipation of making it busy seems to resolve the problem. The lockup test program has been running for a few minutes now without the serial output stalling.

My guess is that Bluefruit.begin was just providing some scheduling noise that allowed dcd_edpt_xfer to win the race (and the rest of us to lose).

Meanwhile, it looks like dcd_edpt_xfer will always return true, so no point in checking it's return and possibly unsetting busy on false.

If we're agreed that this is a real fix, I'll submit a PR to Adafruit_TinyUSB_ArduinoCore.

[hathach]

@innoagg , @hathach , Please try the following patch:

diff --git a/tinyusb/src/device/usbd.c b/tinyusb/src/device/usbd.c
index 80f7dcc..2c65d15 100644
--- a/tinyusb/src/device/usbd.c
+++ b/tinyusb/src/device/usbd.c
@@ -960,8 +960,8 @@ bool usbd_edpt_xfer(uint8_t rhport, uint8_t ep_addr, uint8_t * buffer, uint16_t
   uint8_t const epnum = tu_edpt_number(ep_addr);
   uint8_t const dir   = tu_edpt_dir(ep_addr);
 
-  TU_VERIFY( dcd_edpt_xfer(rhport, ep_addr, buffer, total_bytes) );
   _usbd_dev.ep_status[epnum][dir].busy = true;
+  TU_VERIFY( dcd_edpt_xfer(rhport, ep_addr, buffer, total_bytes) );^M
 
   TU_LOG2("  XFER Endpoint: 0x%02X, Bytes: %d\r\n", ep_addr, total_bytes);

Setting the busy flag in anticipation of making it busy seems to resolve the problem. The lockup test program has been running for a few minutes now without the serial output stalling.

My guess is that Bluefruit.begin was just providing some scheduling noise that allowed dcd_edpt_xfer to win the race (and the rest of us to lose).

Meanwhile, it looks like dcd_edpt_xfer will always return true, so no point in checking it's return and possibly unsetting busy on false.

If we're agreed that this is a real fix, I'll submit a PR to Adafruit_TinyUSB_ArduinoCore.

Ah yes, this is the real fix,and it is an real race condition. This issue actually is already fixed with the tinyusb stack repo previously. But I didn't update the arduino core port. It is due to the Arduino build-all source that prevent tinyusb stack to be included as submodule --> therefore a manual sync has to be done.

hathach/tinyusb#383

@pyro9 Thank you very much for putting effort into debugging and troubleshooting this. @innoagg If you could verify the fix, I will do a tinyusb update in a few days. Though release may take more time to roll out.

[innoagg]

A few points:

1. I applied the patch and it does indeed work for writing data from module -> PC.
2. The patch also appears to work for data from PC -> module.
3. The throughput is 1/2 what is was. 9KB/s vs 18KB/s.
4. A new issue comes when data is sent in both directions at the same time. Data is lost either on the receive or the send. Not sure.
5. Following on the above issue, the serial functionality stops working if data is traded in both directions at the same time.

Can you confirm this with the loop-back example below? Open the serial and while it is streaming data into the PC send data chunk > 64 bytes (what I assume to be the endpoint buffer size) and observe truncation of the reply. Also observe the RX buffer at some point will not longer accept data from the PC.

#include <stdio.h>
#include <Arduino.h>
#include <bluefruit.h>

// the setup function runs once when you press reset or power the board
void setup() {
  Serial.begin(115200);
  Bluefruit.begin(0, 4);
}

uint8_t d[1];
void serialEvent() {

  while (Serial.available()) {
    d[0] = Serial.read();
    Serial.write(d, 1);
  }
}

void serialEventRun(void) {
  serialEvent();
}

// the loop function runs over and over again forever
static uint8_t o[1];
static uint8_t i = 0;
void loop() {
  
  if (Serial) {
    if (Serial.availableForWrite()) {
      Serial.write("|", 1);
    }
  }
}

[innoagg]

I played with buffer sizes for the endpoint and that does change the behavior a bit, but the issue is the same. Truncation and ultimate failure of the receive functionality.

The capture below illustrates the truncation is inconsistent when streaming from module -> PC and sending 238 byte packets from the PC -> module.

Blue = PC -> module
Green = module -> PC

[innoagg]

The example code I posted was also simultaneously sending "|" characters on the loop(). Not necessary to see the issue. You can comment those out.

[pyro9]

Thinking out loud, this looks like a lack of flow control causing serial buffer overflow. I'll give it a look.

[pyro9]

@innoagg
There appears to be a second bug. I simplified the loopback to:

#include <bluefruit.h>

// the setup function runs once when you press reset or power the board
void setup() {
  Serial.begin(115200);
  pinMode(LED_RED, OUTPUT);
  digitalWrite(LED_RED, 1);
  Bluefruit.begin(0, 4);
}

uint8_t d[1];
void serialEvent() {

  while (Serial.available()) {
    d[0] = Serial.read();
    Serial.write(d, 1);
  }
}

void serialEventRun(void) {
  serialEvent();
}

// the loop function runs over and over again forever
static uint8_t o[1];
static uint8_t i = 0;
void loop() {
  digitalWrite(LED_RED, ((millis()/500)&1));
}

and on the host side, I'm using:

#!/usr/bin/python

import serial
import sys
from time import sleep

s = serial.Serial(sys.argv[1], 115200, timeout=10)


ts = "abcdefghijklmnopqrstuvwxyz"
sz = int(sys.argv[2])


#print "Block size is %u bytes\n"%(sz*len(ts))
print "Block size is %u bytes\n"%(sz)

err = False
while not err:
	sys.stdout.write('w')
	sys.stdout.flush()
	s.write('*'*sz)

	sys.stdout.write('r')
	sys.stdout.flush()
	buf = s.read(sz)

	if len(buf) != sz:
		print "Error: %u of %u\n"%(len(buf), sz)
		err=True

to exercize it. Up to size 512, I never see it fail. Above that, writing from host to device freezes up. As in the previous case, the red LED continues flashing, so loop continues to be called regularly. Unlike the last case, unplugging and re-plugging the USB cable unfreezes serial comms.

@hathach , please let me know when you get a chance to update tinyUSB in the Adafruit_TinyUSB_ArduinoCore repo, with any luck, that will happen to include the fix for this.

[innoagg]

@pyro9, I agree with your last post except 64 bytes is the most I can send without issue. I also see that Serial.available() always returns true. Is that expected?

[pyro9]

@innoagg, I'm not seeing the problem with Serial.available. If it was always true, the red light would stop flashing since the loop in serialEvent would never exit. Also, the subsequent read would return -1 and result in sending 0xff back to serial test. I added:

        if '\xff' in buf:
                print "Error, 0xff"

and I'm not seeing that. The code for available definitely checks the buffer and only returns True when there's a non-zero number of bytes available.

[hathach]

Thinking out loud, this looks like a lack of flow control causing serial buffer overflow. I'll give it a look.

yeah. It does looks like the flow control to me as well

@hathach , please let me know when you get a chance to update tinyUSB in the Adafruit_TinyUSB_ArduinoCore repo, with any luck, that will happen to include the fix for this.

I will try to do the sync this week. It may come with more fixes to other issues as well.

[innoagg]

Agree, serial.available is fine. I have played with the code so much I broke it. Hopefully the sync this week will address the original issues. I appreciate the help.

[hathach]

please try out the #542 to see if that fixes your issue.

[pyro9]

This seems to improve the situation, but at write size 2048, I can still get the occasional hang.
Since it solves the original issue, and at least helps the current case, it should probably be committed so we can work from there.

[innoagg]

I am trying to verify this myself and having trouble....

So @pyro9 if you go back to the original post you are not seeing that issue anymore? Sending "|" in the loop after Bluefruit.begin() works for you?

[pyro9]

Correct. That works without issue now. The second issue is merely improved, but something still goes wrong if I write in chunks of 2048 bytes.

[innoagg]

Thanks, I should be seeing what you are so give me a little more time to figure it out. I must have not pulled the correct thing...

[innoagg]

Am I going to have a problem running this with an older bootloader 0.14.0? Should not matter right?

In any case, I just don't see what you see. Its the end of a long day and I will look at this again in the AM fresh. Sorry.

[hathach]

@pyro9 @innoagg Since it fixed the original issue, i will merge the PR for now. Please open an separate issue for the 2nd one if needed, it makes things easier to follow. To be honest, I haven't checked it out so far. Since I want to get the sync first.

[pyro9]

@innoagg Make sure you have pulled both the master branch here AND the master branch of the sub-repository Adafruit_TinyUSB_ArduinoCore (in cores/nRF5/TinyUSB/Adafruit_TinyUSB_ArduinoCore). It's worth re-pulling the master here since the needed patch to allow TinyUSB to compile correctly has now been merged.

[innoagg]

Apologies for the late reply. Struggling a bit here. I guess I need some handholding...

Compiling with the master branches of Adafruit_TinyUSB_ArduinoCore and Adafruit_nRF52_Arduino I can't get the device to be recognized. I can blink the lights so code runs but USB is not functioning.

USB does function with the released 0.20.5.

[hathach]

@innoagg this issue is tested and fixed, please open a separated issue regarding your new one. The issue is preferrably reprorducible with one of the stock example.