sys/stdio_nimble: Remove periodic callout and update documentation #21206

crasbe · 2025-02-11T18:06:04Z

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

Remove periodic callout.
Fix crash for periodic command of tests/sys/shell.
Add a while loop around _send_stdout instead of recursive call.
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).
Add documentation for event->notify_tx.status.
Don't clear stdout buffer on connect by default, make it optional.
Add documentation for stdio_nimble_debug pseudomodule.
~~In debug mode: Redirect stdout to UART when BLE connection is disconnected. Otherwise crash information won't be readable.~~
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.

mguetschow

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.

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?

mguetschow · 2025-02-12T08:50:30Z

sys/stdio_nimble/stdio_nimble.c

+    if (tsrb_avail(&_tsrb_stdout) > 0 && _status == STDIO_NIMBLE_SUBSCRIBED) {
+        /* retry sending data for anything left in the ringbuffer */
+        _send_stdout();
+    }


Not sure if the compiler would be smart enough to notice this is a tail-recursive function and not actually increase the stack frame for each recursive call. Maybe this could be a while-loop around the whole function content instead?

Yes, a while loop would be a good option. I thought about that but didn't follow through.

sys/stdio_nimble/stdio_nimble.c

crasbe · 2025-02-12T10:02:13Z

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.

RIOT/sys/include/stdio_nimble.h

Lines 44 to 48 in 7027fd3

    
            * By default, stdin and stdout buffers are cleared on a connect event. To keep the 
        
            * content add the following to your makefile: 
        
            * ``` 
        
            * CFLAGS += -DCONFIG_STDIO_NIMBLE_CLEAR_BUFFER_ON_CONNECT=0 
        
            * ```

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

mguetschow · 2025-02-12T12:24:43Z

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.

tests/sys/shell/main.c

crasbe · 2025-02-13T15:30:15Z

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.

mguetschow · 2025-02-13T15:59:29Z

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.

Co-authored-by: mguetschow <[email protected]>

crasbe · 2025-02-13T17:42:10Z

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.

mguetschow · 2025-02-14T10:43:15Z

[ ] 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.

crasbe · 2025-02-14T10:46:36Z

[ ] 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 · 2025-02-14T16:37:35Z

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.

Log 2025-02-14 17_25_22.txt

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

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 · 2025-02-15T01:22:10Z

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 · 2025-02-20T13:13:06Z

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.

mguetschow · 2025-02-20T13:57:44Z

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

crasbe · 2025-02-20T14:36:44Z

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

RIOT/pkg/openwsn/Makefile.include

Lines 62 to 66 in 88f2e45

    
           # In OpenWSN the ISR stack is shared with the network stack. OpenWSN stack is 
        
           # 2Kb, this means that the ISR stack in OpenWSN might have up to 2Kb available. 
        
           # To keep the same marging increase the ISR stack to 2Kb as well. In practice 
        
           # 1Kb should be enough. 
        
           CFLAGS += -DISR_STACKSIZE=2048

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 · 2025-02-20T16:54:37Z

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 requested review from leandrolanzieri, aabadie and MichelRottleuthner as code owners February 11, 2025 18:06

github-actions bot added Area: tests Area: tests and testing framework Area: sys Area: System labels Feb 11, 2025

mguetschow reviewed Feb 12, 2025

View reviewed changes

mguetschow reviewed Feb 13, 2025

View reviewed changes

tests/sys/shell/main.c Outdated Show resolved Hide resolved

crasbe force-pushed the pr/nimble_callout branch from 2a4fa64 to 9e891c0 Compare February 13, 2025 17:22

crasbe and others added 3 commits February 13, 2025 18:26

sys/stdio_nimble: Remove periodic callout

48bdeaa

tests/shell: Increase stack for 'periodic' thread for NimBLE debug

ee066b9

Co-authored-by: mguetschow <[email protected]>

sys/stdio_nimble: set default to retain buffers on connection

6fab309

crasbe force-pushed the pr/nimble_callout branch from 9e891c0 to 6fab309 Compare February 13, 2025 17:32

crasbe added 2 commits February 13, 2025 23:21

fixup! sys/stdio_nimble: Remove periodic callout

f047e35

sys/stdio_nimble: Add documentation about debug module

765d6bb

fixup! fixup! sys/stdio_nimble: Remove periodic callout

4b5b6da

fixup! fixup! sys/stdio_nimble: Remove periodic callout

4aabd6a

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

da17c24

crasbe mentioned this pull request Feb 21, 2025

NimBLE: Replace Deprecated ble_gattc_ Functions #21234

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

sys/stdio_nimble: Remove periodic callout and update documentation #21206

sys/stdio_nimble: Remove periodic callout and update documentation #21206

crasbe commented Feb 11, 2025 •

edited

Loading

mguetschow left a comment

mguetschow Feb 12, 2025

crasbe Feb 12, 2025

crasbe commented Feb 12, 2025

mguetschow commented Feb 12, 2025

crasbe commented Feb 13, 2025 •

edited

Loading

mguetschow commented Feb 13, 2025

crasbe commented Feb 13, 2025

mguetschow commented Feb 14, 2025

crasbe commented Feb 14, 2025 •

edited

Loading

crasbe commented Feb 14, 2025

crasbe commented Feb 15, 2025

crasbe commented Feb 20, 2025

mguetschow commented Feb 20, 2025

crasbe commented Feb 20, 2025

crasbe commented Feb 20, 2025

sys/stdio_nimble: Remove periodic callout and update documentation #21206

Are you sure you want to change the base?

sys/stdio_nimble: Remove periodic callout and update documentation #21206

Conversation

crasbe commented Feb 11, 2025 • edited Loading

Contribution description

Task List

Testing procedure

Issues/PRs references

mguetschow left a comment

Choose a reason for hiding this comment

mguetschow Feb 12, 2025

Choose a reason for hiding this comment

crasbe Feb 12, 2025

Choose a reason for hiding this comment

crasbe commented Feb 12, 2025

mguetschow commented Feb 12, 2025

crasbe commented Feb 13, 2025 • edited Loading

mguetschow commented Feb 13, 2025

crasbe commented Feb 13, 2025

mguetschow commented Feb 14, 2025

crasbe commented Feb 14, 2025 • edited Loading

crasbe commented Feb 14, 2025

crasbe commented Feb 15, 2025

crasbe commented Feb 20, 2025

mguetschow commented Feb 20, 2025

crasbe commented Feb 20, 2025

crasbe commented Feb 20, 2025

crasbe commented Feb 11, 2025 •

edited

Loading

crasbe commented Feb 13, 2025 •

edited

Loading

crasbe commented Feb 14, 2025 •

edited

Loading