RIOT icon indicating copy to clipboard operation
RIOT copied to clipboard
verified publisher icon RIOT-OS

sys/stdio_nimble: Remove periodic callout and update documentation

Open crasbe opened this issue 10 months ago • 15 comments

Contribution description

Following the issue in #21192, I experimented with the stdio_nimble module and essentially I think that the original periodic callout was not required at all.

I would've liked to add a _send_stdout() call to the subscription event, but that will cause a crash which I can't really trace (the STDOUT goes to BLE...). I assume that NimBLE needs some time after the SUBSCRIBE event before it can actually accept data.

Also I put the interrupt disable and enable functions in the _write function into the #ifdef DEBUG block, so that they are only executed when they are actually needed. I'm not sure if the compiler would optimize them away, but the less interrupt interruption, the better.

Speaking of which: At the moment there are multiple places that access the _status variable which is not really nice. It is possible that some race conditions occur, but so far I haven't noticed any. stdio_nimble is still classified as experimental and the potential for race conditions was present before as well, so I don't think this is the place to fix it.

~~Also I had to increase the stack size when debugging is enabled, otherwise the debug messages would sometimes corrupt the threadsafe ringbuffer and it would start to spill out memory content on the BLE shell 😅 I added an in the preprocessor conditional when the stack size is too small. This is open for debate, that's why I didn't squash it yet.~~ The stack size of the periodic thread in tests/sys/shell[_ble] got increased conditionally when stdio_nimble_debug is used, since the printf consumes more stack and led to a stack overflow and _send_stdout printing out memory.

Task List

  • [X] Remove periodic callout.
  • [X] Fix crash for periodic command of tests/sys/shell.
  • [x] Add a while loop around _send_stdout instead of recursive call.
  • [x] Add mutex and two staged variable setting for _status to avoid race conditions. (Set a temporary _status, get mutex and check if global _status still has the right value and set it, release mutex).
  • [X] Add documentation for event->notify_tx.status.
  • [X] Don't clear stdout buffer on connect by default, make it optional.
  • [x] Add documentation for stdio_nimble_debug pseudomodule.
  • [X] ~~In debug mode: Redirect stdout to UART when BLE connection is disconnected. Otherwise crash information won't be readable.~~
  • [x] Squash the two commits regarding the stdio_nimble.h header.

Testing procedure

You can test this with a board that is supported by NimBLE, for example a nrf52dk or nrf52840dk. Some ESP boards should work too, but I don't have any. The nrf52840dongle will not work because it lacks a real serial console (or you have to be dedicated enough to connect your usb to serial adapter :D ) Essentially you can follow this guide to test it: https://doc.riot-os.org/group__sys__stdio__nimble.html This PR shouldn't cause any noticeable differences.

If you want to see the effect you can add _debug_printf("Status: %d\n, _status); to the first line of _send_stdout in both master and this PR.

You have to connect to the Devboard via serial console to the PC and you'll receive the following debug output. I typed the help command.

Before applying this PR: 

STDOUT: main(): This is RIOT! (Version: 2024.04-devel-2076-gd630a15)<\n>
<\n>
STDOUT: test_shell.<\n>
<\n>
STDOUT: > <\n>
BLE_GAP_EVENT_CONNECT handle: 1<\n>
STDOUT: <\r><\n>
<\n>
STDOUT: > <\n>
BLE_GAP_EVENT_MTU: mtu = 256<\n>
BLE_GAP_EVENT_SUBSCRIBE 1<\n>
BLE_GAP_EVENT_SUBSCRIBE 1<\n>
STDOUT: h<\n>
STDOUT: e<\n>
STDOUT: l<\n>
Status: 2<\n>
BLE_GAP_EVENT_NOTIFY_TX 1<\n>
6 bytes sent successfully<\n>
Status: 3<\n>
STDOUT: p<\n>
STDOUT: <\r><\n>
<\n>
Status: 3<\n>
STDOUT: Command              Description<\n>
<\n>
Status: 3<\n>
STDOUT: ---------------------------------------<\n>
<\n>
Status: 3<\n>
STDOUT: bufsize              Get the shell's buffer size<\n>
<\n>
Status: 3<\n>
STDOUT: start_test           starts a test<\n>
<\n>
Status: 3<\n>
STDOUT: end_test             ends a test<\n>
<\n>
Status: 3<\n>
STDOUT: echo                 prints the input command<\n>
<\n>
Status: 3<\n>
STDOUT: empty                print nothing on command<\n>
<\n>
Status: 3<\n>
STDOUT: periodic             periodically print command<\n>
<\n>
Status: 3<\n>
STDOUT: xfa_test1            xfa test command 1<\n>
<\n>
Status: 3<\n>
STDOUT: xfa_test2            xfa test command 2<\n>
<\n>
Status: 3<\n>
STDOUT: autoadv              NimBLE autoadv<\n>
<\n>
Status: 3<\n>
STDOUT: app_metadata         Returns application metadata<\n>
<\n>
Status: 3<\n>
STDOUT: pm                   interact with layered PM subsystem<\n>
<\n>
Status: 3<\n>
STDOUT: ps                   Prints information about running threads.<\n>
<\n>
Status: 3<\n>
STDOUT: version              Prints current RIOT_VERSION<\n>
<\n>
Status: 3<\n>
STDOUT: reboot               Reboot the node<\n>
<\n>
Status: 3<\n>
STDOUT: > <\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
BLE_GAP_EVENT_NOTIFY_TX 1<\n>
Status: 2<\n>
BLE_GAP_EVENT_NOTIFY_TX 1<\n>
251 bytes sent successfully<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
BLE_GAP_EVENT_NOTIFY_TX 1<\n>
Status: 2<\n>
BLE_GAP_EVENT_NOTIFY_TX 1<\n>
251 bytes sent successfully<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
BLE_GAP_EVENT_NOTIFY_TX 1<\n>
Status: 2<\n>
BLE_GAP_EVENT_NOTIFY_TX 1<\n>
205 bytes sent successfully<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
Status: 3<\n>
BLE_GAP_EVENT_NOTIFY_TX 1<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
Status: 2<\n>
...
(Status 2 will be printed forever)
With this PR applied: 

STDOUT: main(): This is RIOT! (Version: 2024.04-devel-2077-gbeaf7-pr/nimble_callout)<\n>
<\n>
STDOUT: test_shell.<\n>
<\n>
STDOUT: > <\n>
BLE_GAP_EVENT_CONNECT handle: 1<\n>
STDOUT: <\r><\n>
<\n>
STDOUT: > <\n>
BLE_GAP_EVENT_MTU: mtu = 256<\n>
BLE_GAP_EVENT_SUBSCRIBE 1<\n>
BLE_GAP_EVENT_SUBSCRIBE 1<\n>
STDOUT: h<\n>
Status: 2<\n>
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 0<\n>
5 bytes sent successfully<\n>
STDOUT: e<\n>
Status: 3<\n>
STDOUT: l<\n>
Status: 3<\n>
STDOUT: p<\n>
Status: 3<\n>
STDOUT: <\r><\n>
<\n>
Status: 3<\n>
STDOUT: Command              Description<\n>
<\n>
Status: 3<\n>
STDOUT: ---------------------------------------<\n>
<\n>
Status: 3<\n>
STDOUT: bufsize              Get the shell's buffer size<\n>
<\n>
Status: 3<\n>
STDOUT: start_test           starts a test<\n>
<\n>
Status: 3<\n>
STDOUT: end_test             ends a test<\n>
<\n>
Status: 3<\n>
STDOUT: echo                 prints the input command<\n>
<\n>
Status: 3<\n>
STDOUT: empty                print nothing on command<\n>
<\n>
Status: 3<\n>
STDOUT: periodic             periodically print command<\n>
<\n>
Status: 3<\n>
STDOUT: xfa_test1            xfa test command 1<\n>
<\n>
Status: 3<\n>
STDOUT: xfa_test2            xfa test command 2<\n>
<\n>
Status: 3<\n>
STDOUT: autoadv              NimBLE autoadv<\n>
<\n>
Status: 3<\n>
STDOUT: app_metadata         Returns application metadata<\n>
<\n>
Status: 3<\n>
STDOUT: pm                   interact with layered PM subsystem<\n>
<\n>
Status: 3<\n>
STDOUT: ps                   Prints information about running threads.<\n>
<\n>
Status: 3<\n>
STDOUT: version              Prints current RIOT_VERSION<\n>
<\n>
Status: 3<\n>
STDOUT: reboot               Reboot the node<\n>
<\n>
Status: 3<\n>
STDOUT: > <\n>
Status: 3<\n>
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 14<\n>
Status: 2<\n>
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 0<\n>
251 bytes sent successfully<\n>
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 14<\n>
Status: 2<\n>
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 0<\n>
251 bytes sent successfully<\n>
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 14<\n>
Status: 2<\n>
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 0<\n>
206 bytes sent successfully<\n>
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 14<\n>
Status: 2<\n>

Issues/PRs references

Fixes #21192. Fixes #21234. ~~Depends on #21832.~~Merged.

crasbe avatar Feb 11 '25 18:02 crasbe

Thanks for investigating! I haven't tested it locally yet, but some first comments below.

I would've liked to add a _send_stdout() call to the subscription event, but that will cause a crash which I can't really trace (the STDOUT goes to BLE...). I assume that NimBLE needs some time after the SUBSCRIBE event before it can actually accept data.

Couldn't you trace it with the debug module over uart? I agree that this would be the proper place to call _send_stdout.

The stdio_nimble_debug module only enables the debug messages for the stdio_nimble.c module. Everything else is still sent to the normal STDOUT, which is redirected to the BLE interface. Maybe I could add something to redirect _write to the UART for debugging if _status == STDIO_NIMBLE_DISCONNECTED or something like that.

Is it correct that _send_stdout is currently on master and with this PR only called after a new call to _write and not as soon as the BLE device subscribes?

Yes, that's currently how it's implemented. It doesn't really have any bad effect because the STDOUT buffer is cleared by default on connect.

https://github.com/RIOT-OS/RIOT/blob/7027fd3bbb5af6e799d3d4338b7d059f88cf5226/sys/include/stdio_nimble.h#L44-L48

Since the time between a connect and a subscription is usually short, not a lot of data should accumulate in the buffer.

I'm undecided whether I like that default clearing in general and the subscription behavior (or non-behavior). I'll dig a little bit deeper to see if there's a good solution (like a ready to send flag or perhaps a time delay again).

crasbe avatar Feb 12 '25 10:02 crasbe

Maybe I could add something to redirect _write to the UART for debugging if _status == STDIO_NIMBLE_DISCONNECTED or something like that.

Would probably be nice to have, if not too hacky (and only enabled when stdio_nimble_debug is selected).

I'm undecided whether I like that default clearing in general and the subscription behavior (or non-behavior).

At least its different to the stdio over serial output on other boards that keep the output in a buffer up to a certain length. I think I'd prefer that here, too.

mguetschow avatar Feb 12 '25 12:02 mguetschow

Sorry for "flooding" you with e-mails and fixup commits, I'm currently a bit slow and distracted... I added some tasks above to keep track (I hope).

The default behavior of stdio_nimble is now to retain what's already in the buffer and I updated the documentation accordingly. The tests/sys/shell_ble application does not crash anymore when running the periodic command, so that is resolved as well.

Edit: If you want to, I can squash the commits at this point, it's starting to get a bit fragmented I guess.

crasbe avatar Feb 13 '25 15:02 crasbe

Sorry for "flooding" you with e-mails and fixup commits, I'm currently a bit slow and distracted...

No worries, just ping me when I should have another look :)

Edit: If you want to, I can squash the commits at this point, it's starting to get a bit fragmented I guess.

Yes, please squash already, I'll have a look at the combined changes again anyways.

mguetschow avatar Feb 13 '25 15:02 mguetschow

The stdio_nimble_debug module only enables the debug messages for the stdio_nimble.c module. Everything else is still sent to the normal STDOUT, which is redirected to the BLE interface. Maybe I could add something to redirect _write to the UART for debugging if _status == STDIO_NIMBLE_DISCONNECTED or something like that.

I think it was too late when I wrote that. In fact, everything already is sent out via UART 🤣

The "crash" that happens when the stack of the periodic thread is too small does not produce a RIOT crash info either, it just corrupts the ringbuffer and the data size will underflow, making the _send_stdout spill out memory. I still don't know the exact mechanisms of why that happens, but that doesn't really matter since the cause is clear.

crasbe avatar Feb 13 '25 17:02 crasbe

[ ] Add mutex and two staged variable setting for _status to avoid race conditions. (Set a temporary _status, get mutex and check if global _status still has the right value and set it, release mutex).

@crasbe If that's the only remaining thing and you don't come to do it now, I'd say it could also be postponed to a second PR. Just give me a thumbs up and I'll have a look at it as is now.

mguetschow avatar Feb 14 '25 10:02 mguetschow

[ ] Add mutex and two staged variable setting for _status to avoid race conditions. (Set a temporary _status, get mutex and check if global _status still has the right value and set it, release mutex).

@crasbe If that's the only remaining thing and you don't come to do it now, I'd say it could also be postponed to a second PR. Just give me a thumbs up and I'll have a look at it as is now.

I implemented that yesterday too, but couldn't test it, so I did not commit it yet.

There's one other thing to consider: The behavior of stdio_nimble without the callout and without ztimer is now blocking for stdout. This is typical behavior, but it has to be at least documented. Also I would like to add a non-blocking option with ztimer: Essentially just enable a timer in _write, so that _send_stdout can be called asynchronously. The while loop can stay, because the _send_stdout is running separately now anyway.

crasbe avatar Feb 14 '25 10:02 crasbe

There's one other thing to consider: The behavior of stdio_nimble without the callout and without ztimer is now blocking for stdout. This is typical behavior, but it has to be at least documented. Also I would like to add a non-blocking option with ztimer: Essentially just enable a timer in _write, so that _send_stdout can be called asynchronously. The while loop can stay, because the _send_stdout is running separately now anyway.

This is not exactly true either. At the moment it blocking and non-blocking.

The first call is blocking because it will call the NimBLE functions as well. Immediately following calls are non-blocking because _send_stdout won't do anything if _status != STDIO_NIMBLE_SUBSCRIBED. This is probably the worst way to do it.

I think the best way going forward is doing it totally non-blocking with ztimer and add a blocking mode with a mutex in a separate PR. With this approach we can add a time-delayed send after the subscribe event.

Sending the stdout buffer directly after subscribing will lead to this error. ble-serial experiences a similar error.

image Log 2025-02-14 17_25_22.txt

This is how it looks like when I sent a help\n = 0x68656C700A

image Log 2025-02-14 17_23_38.txt

So yeah, it seems like there is not enough time and not all the descriptors are exchanged yet and then the indication hits.

Maybe I'll do something like a 200ms delay before triggering the _send_stdout.

crasbe avatar Feb 14 '25 16:02 crasbe

I think the stack keeps on giving. Adding ztimer_set again caused the program to never call _send_stdout at all and it would crash without any further messages. I suspect that the printf of the debug module causes the ISR stack to overflow, since now _send_stdout is called from the ISR that ztimer set up for it.

Unfortunately that idea only came to my head after I left the office and I left the devboard there... so I earliest I can test that hypothesis it is Monday.

crasbe avatar Feb 15 '25 01:02 crasbe

I think the stack keeps on giving. Adding ztimer_set again caused the program to never call _send_stdout at all and it would crash without any further messages. I suspect that the printf of the debug module causes the ISR stack to overflow, since now _send_stdout is called from the ISR that ztimer set up for it.

Well... this was (partly) my own stupidity 🤣

I called ztimer_set(ZTIMER_MSEC, &_send_stdout_timer, ztimer_now(ZTIMER_MSEC) + 2);, not remembering that ztimer_set wants a relative time not an absolute time. So if the program had an uptime of 20s, the delay was 20s (plus 2ms).

However the ISR stack will still overflow with and without the debug messages enabled. This is no issue because the ISR_STACKSIZE can just be increased, however I'm not sure where to do this best. Adding CFLAGS += ISR_STACKSIZE=1024 to the sys/stdio_nimble/Makefile will increase the stack for stdio_nimble only but not for the application or ztimer.

For this example I just added _debug_printf("[init] ISR_STACKSIZE: %d\n, ISR_STACKSIZE");to the_initfunction instdio_nimbleandprintf("[shell_ble] ISR_STACKSIZE %d\n, ISR_STACKSIZE);to themain.cofshell_ble(or rathershell`, since they share the file).

[_init] ISR_STACKSIZE: 1024
STDOUT: main(): This is RIOT! (Version: 2025.04-devel-106-g4b5b6-pr/nimble_callout)

STDOUT: test_shell.

STDOUT: [shell_ble] ISR_STACKSIZE: 512

STDOUT: >
BLE_GAP_EVENT_CONNECT handle: 1
BLE_GAP_EVENT_MTU: mtu = 256
BLE_GAP_EVENT_SUBSCRIBE 1
BLE_GAP_EVENT_SUBSCRIBE 1

*crash before the _debug_printf in [_send_stdout] is executed*

Adding it to tests/sys/shell_ble/Makefile or to the make command (BOARD=nrf52840dk CFLAGS+="-DISR_STACKSIZE=1024" make -C tests/sys/shell_ble) will increase the stacksize for everything, but obviously it's unfavorable to force all applications to increase the ISR stacksize manually.

[_init] ISR_STACKSIZE: 1024
STDOUT: main(): This is RIOT! (Version: 2025.04-devel-106-g4b5b6-pr/nimble_callout)

STDOUT: test_shell.

STDOUT: [shell_ble] ISR_STACKSIZE: 1024

STDOUT: > 
BLE_GAP_EVENT_CONNECT handle: 1
BLE_GAP_EVENT_MTU: mtu = 256
BLE_GAP_EVENT_SUBSCRIBE 1
BLE_GAP_EVENT_SUBSCRIBE 1
[_send_stdout] ISR_STACKSIZE: 1024
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 0
122 bytes sent successfully
BLE_GAP_EVENT_NOTIFY_TX 1: Status: 14
[_send_stdout] ISR_STACKSIZE: 1024

Could this be an issue where the ISR_STACKSIZE variable (or rather the CFLAGS variable) is not exported by the build system? Oh how I missed a good build system rabbithole 🫠

But on a positive note: With some delay, the "send everything that's still in the buffer after the SUBSCRIBE event" feature works now. 500ms is very conservative, 200ms worked as well. I'm not sure which value to choose yet.

crasbe avatar Feb 20 '25 13:02 crasbe

Adding CFLAGS += ISR_STACKSIZE=1024 to the sys/stdio_nimble/Makefile will increase the stack for stdio_nimble only but not for the application or ztimer.

I think that is expected behavior, if you want to set something for the whole build you would need to do so in Makefile.include of the module. I'm however not sure either whether hardcoding the ISR stacksize there would be a good idea, what would happen if another module chooses to specify a different one? Ha, dependency modeling....

mguetschow avatar Feb 20 '25 13:02 mguetschow

The only other example I could find which requires increasing the ISR_STACKSIZE is openwsn:

https://github.com/RIOT-OS/RIOT/blob/88f2e451ca9936a51804246e647e91e3959d6aa9/pkg/openwsn/Makefile.include#L62-L66

Ideally we would get away without increasing the ISR stack at all and I'm not really sure why that's necessary in the first place. The previous version with the periodic callouts essentially came down to ztimer as well, so it should've been in an ISR as well? I guess? Maybe it was just a tiiiiny bit slimmer and fit and the new version does not fit anymore.

A non-invasive solution would be to re-add the #if that throws a compile error when the stack size is too small and add documentation that the user is required to increase the ISR stacksize for stdio_nimble.

crasbe avatar Feb 20 '25 14:02 crasbe

I learned that ps requires DEVELHELP = 1 in the Makefile to show the stack usage (I always wondered why it didn't do that in the tests/sys/shell_ble application).

This might explain why the ISR stack overflows.

main(): This is RIOT! (Version: 2025.04-devel-107-g4aabd6-pr/nimble_callout)
test_shell.
> help
Command              Description
---------------------------------------
bufsize              Get the shell's buffer size
start_test           starts a test
end_test             ends a test
echo                 prints the input command
empty                print nothing on command
periodic             periodically print command
xfa_test1            xfa test command 1
xfa_test2            xfa test command 2
autoadv              NimBLE autoadv
app_metadata         Returns application metadata
pm                   interact with layered PM subsystem
ps                   Prints information about running threads.
version              Prints current RIOT_VERSION
reboot               Reboot the node
> ps
pid | name                 | state    Q | pri | stack  ( used) ( free) | base addr  | current     
  - | isr_stack            | -        - |   - |   1024 (  736) (  288) | 0x20000000 | 0x200003c8
  1 | main                 | running  Q |   7 |   1536 (  568) (  968) | 0x20000b00 | 0x20000ffc 
  2 | nimble_host          | bl anyfl _ |   5 |   1024 (  932) (   92) | 0x20002c44 | 0x20002ee4 
  3 | nimble_ctrl          | bl anyfl _ |   0 |   1024 (  260) (  764) | 0x20002844 | 0x20002b84 
    | SUM                  |            |     |   4608 ( 2496) ( 2112)
>

I added a commit which introduces a Makefile.include that conditionally sets the stacksize. This is far from beautiful, but probably the best you can do with Make.

crasbe avatar Feb 20 '25 16:02 crasbe

Murdock results

:heavy_check_mark: PASSED

def204a7c420aa008698096073feb2ab85ab83d1 fixup! fixup! fixup! fixup! fixup! sys/stdio_nimble: Remove periodic callout

Success Failures Total Runtime
10559 0 10560 10m:44s

Artifacts

riot-ci avatar Jun 12 '25 21:06 riot-ci

I decided to add a commit to replace the deprecated functions, as mentioned in #21234 too. Surprisingly it did not give a merge conflict in the rebase :D

crasbe avatar Oct 30 '25 10:10 crasbe