NRF52 getting stuck using serial port

[tanoc]

Description

After the merge of pull request #7323, trying to use the serial port before and after the BLE initialization causes the program to freeze.

The following code is working correctly in d3641fd, but hangs on the second printf (the one in bleInitComplete) in faa31de

#include <mbed.h>
#include "ble/BLE.h"

static EventQueue eventQueue(4 * EVENTS_EVENT_SIZE);
void onBleInitError(BLE& ble, ble_error_t error) {}

void bleInitComplete(BLE::InitializationCompleteCallbackContext* params) {
  BLE& ble = params->ble;
  ble_error_t error = params->error;

  MBED_ASSERT(error == BLE_ERROR_NONE);
  MBED_ASSERT(ble.getInstanceID() == BLE::DEFAULT_INSTANCE);

  printf("Init complete\r\n");
}

void scheduleBleEventsProcessing(
    BLE::OnEventsToProcessCallbackContext* context) {
  BLE& ble = BLE::Instance();
  eventQueue.call(Callback<void()>(&ble, &BLE::processEvents));
}

int main() {
  printf("Begin\r\n");
  BLE& ble = BLE::Instance();
  ble.onEventsToProcess(scheduleBleEventsProcessing);
  ble.init(bleInitComplete);

  eventQueue.dispatch_forever();

  return 0;
}

It looks like it is getting stuck in this loop waiting for tx_in_progress:

mbed-os/targets/TARGET_NORDIC/TARGET_NRF5x/TARGET_NRF52/serial_api.c

Line 1500 in faa31de

mutex = core_util_atomic_cas_u8((uint8_t *) &nordic_nrf5_uart_state[instance].tx_in_progress, &expected, desired);

The problem is not present removing the first printf in the main.

I'm using a custom board with an NRF52832, with console-uart-flow-control set to null, compiling with mbed cli using arm-gcc.

Issue request type

[ ] Question
[ ] Enhancement
[X] Bug

[0xc0170]

After the merge of pull request #7323, trying to use the serial port before and after the BLE initialization causes the program to freeze.

@marcuschangarm Please review

[ciarmcom]

ARM Internal Ref: MBOTRIAGE-1065

[cmonr]

@tanoc Would you mind retesting with mbed-os checked out to master? I recall another PR coming in that fixed serial stability issues.

[marcuschangarm]

@tanoc

Can you provide us with a trace of the call stack at the point where it hangs, please? I've noticed that when some asserts are being triggered they get stuck on the line you quoted above.

[marcuschangarm]

Previous discussion for reference: #7323 (comment)

[tanoc]

sure, here it is:

#0  core_util_atomic_cas_u8 (ptr=0x20004f6d <nordic_nrf5_uart_state+33> "\001", expectedCurrentValue=0x200060bd <_main_stack+3213> "", desiredValue=1 '\001') at ./mbed-os/platform/mbed_critical.c:122
#1  0x0004c4f8 in serial_putc (obj=0x20004fb0 <stdio_uart>, character=73) at ./mbed-os/targets/TARGET_NORDIC/TARGET_NRF5x/TARGET_NRF52/serial_api.c:1500
#2  0x00044e8e in DirectSerial::write (this=0x200048a4 <default_console()::console>, buffer=0x20006548, size=15) at ./mbed-os/platform/mbed_retarget.cpp:171
#3  0x00045510 in write (fildes=1, buf=0x20006548, length=15) at ./mbed-os/platform/mbed_retarget.cpp:621
#4  0x00045484 in _write (fh=1, buffer=0x20006548 "Init complete\r\n", length=15, mode=0) at ./mbed-os/platform/mbed_retarget.cpp:591
#5  0x00056b96 in _write_r ()
#6  0x0005186e in __sflush_r ()
#7  0x00051928 in _fflush_r ()
#8  0x0005257e in __sfvwrite_r ()
#9  0x000553e0 in __sprint_r.part.0 ()
#10 0x000567d6 in _vfprintf_r ()
#11 0x000533dc in printf ()
#12 0x000513e8 in bleInitComplete (params=0x20006388 <_main_stack+3928>) at ./source/main.cpp:15
#13 0x00051594 in FunctionPointerWithContext<BLE::InitializationCompleteCallbackContext*>::functioncaller (self=0x200063a0 <_main_stack+3952>, context=0x20006388 <_main_stack+3928>)
    at ./mbed-os/features/FEATURE_BLE/ble/FunctionPointerWithContext.h:274
#14 0x000397be in FunctionPointerWithContext<BLE::InitializationCompleteCallbackContext*>::call (this=0x200063a0 <_main_stack+3952>, context=0x20006388 <_main_stack+3928>)
    at ./mbed-os/features/FEATURE_BLE/ble/FunctionPointerWithContext.h:160
#15 0x000397a4 in FunctionPointerWithContext<BLE::InitializationCompleteCallbackContext*>::call (this=0x200063a0 <_main_stack+3952>, context=0x20006388 <_main_stack+3928>)
    at ./mbed-os/features/FEATURE_BLE/ble/FunctionPointerWithContext.h:170
#16 0x00039420 in nRF5xn::init (this=0x20004390 <getDeviceInstance()::deviceInstance>, instanceID=0, callback=...) at ./mbed-os/features/FEATURE_BLE/targets/TARGET_NORDIC/TARGET_NRF52/source/nRF5xn.cpp:140
#17 0x00024308 in BLE::initImplementation (this=0x20006950, callback=...) at ./mbed-os/features/FEATURE_BLE/source/BLE.cpp:83
#18 0x00051392 in BLE::init (this=0x20006950, completion_cb=0x5139d <bleInitComplete(BLE::InitializationCompleteCallbackContext*)>) at ./mbed-os/features/FEATURE_BLE/ble/BLE.h:288
#19 0x00051472 in main () at ./source/main.cpp:28

[kjbracey]

Which compilation profile(s) are you seeing this on? Can you confirm that it's stuck in the mutex-checking loop because tx_in_progress is 1, not the "wait for STREX to work" loop inside core_util_atomic_cas_u8? (Check by setting a breakpoint in the outer loop, not single-stepping).

(I'm a little paranoid that the atomic functions are potentially unstable due to their use of LDREX/STREX in C code - see http://infocenter.arm.com/help/index.jsp?topic=/com.arm.doc.dui0472m/chr1359124997286.html )

[tanoc]

I'm using the debug profile (mbed-os/tools/profiles/debug.json), and yes, trying with a breakpoint in the outer loop (line 1501), is stuck in there with tx_in_progress set to 1.

I also checked with the 2 other profiles (develop and release), but the result is the same.

[kjbracey]

Cool, atomic paranoia over for another day. And have you tried current master, which incorporates #7369?

[tanoc]

I've tried it now with the current master 93233c4, but same result... just different line :) (serial_api.c:1446)

[marcuschangarm]

There are some major issues with the current serial driver when used with BLE: #7440 (comment)

We'll have to make some redesigns to fix it.