l2cap coc: send() broken since #414

[haukepetersen]

Issue

As happy as I was when it got merged, it seems that #414 introduced some problems for sending data via l2cap_(coc_)send(). The STALLED state is not resolved properly, leading to the sending node getting stuck in an endless loop sending out some random packet.

Test setup

• running Nimble@RIOT
• branch: https://github.com/haukepetersen/RIOT/tree/opt_nimble_ver370305a -> ble/nimble: bump version to 9d4bda2 RIOT-OS/RIOT#11273
• two nrf52dk nodes, running Nimble host and controller
  Node A:
• l2cap echo server -> https://github.com/haukepetersen/RIOT/tree/opt_nimble_ver370305a/tests/nimble_l2cap_server
• any payload that is received via the configured l2cap coc is echoed on the same channel
  Node B:
• l2cap 'sender' -> https://github.com/haukepetersen/RIOT/tree/opt_nimble_ver370305a/tests/nimble_l2cap
• 'floods' the configured l2cap coc by sending out data as fast as possible

The send function looks as following

    do {
        res = ble_l2cap_send(_coc, txd);
        if (res == BLE_HS_ESTALLED) {
            thread_flags_wait_all(FLAG_TX_UNSTALLED);
        }
    } while ((res == BLE_HS_EBUSY) || (res == BLE_HS_ESTALLED));

The thread_flags_wait_all() is simply a RIOT specific IPC function, and the flag itself is set whenever the BLE_L2CAP_EVENT_COC_TX_UNSTALLED is triggered:

[in the l2cap event callback]
        case BLE_L2CAP_EVENT_COC_TX_UNSTALLED:
            thread_flags_set(_main, FLAG_TX_UNSTALLED);
            break;

(Bad) results

Trying to send 100 chunks or 100byte each (similar results for different sized chunks), the nodes end up in the following state:
Node A (echo server):

2019-05-16 12:20:19,090 - INFO # main(): This is RIOT! (Version: 2019.07-devel-289-g8ccf8-opt_nimble_ver370305a)
2019-05-16 12:20:19,092 - INFO # NimBLE L2CAP test server
2019-05-16 12:20:19,094 - INFO # # now advertising
2019-05-16 12:20:26,780 - INFO # # GAP event 0
2019-05-16 12:20:26,833 - INFO # # L2CAP: CONNECTED
2019-05-16 12:20:26,836 - INFO # # MTUs: our 250, remote 250
2019-05-16 12:20:30,386 - INFO # # Received: len   100, seq     1
2019-05-16 12:20:30,389 - INFO # # Received: len   100, seq     2
2019-05-16 12:20:30,393 - INFO # # Received: len   100, seq     3
2019-05-16 12:20:30,396 - INFO # # Received: len   100, seq     4
2019-05-16 12:20:30,400 - INFO # # Received: len   100, seq     5
2019-05-16 12:20:30,403 - INFO # # Received: len   100, seq     6
2019-05-16 12:20:30,406 - INFO # # Received: len   100, seq     7
2019-05-16 12:20:30,410 - INFO # # Received: len   100, seq     8
2019-05-16 12:20:30,413 - INFO # # Received: len   100, seq     9
2019-05-16 12:20:30,417 - INFO # # Received: len   100, seq    10
2019-05-16 12:20:30,420 - INFO # # Received: len   100, seq    11
2019-05-16 12:20:30,423 - INFO # # Received: len   100, seq    12
2019-05-16 12:20:30,427 - INFO # # Received: len   100, seq    13
2019-05-16 12:20:30,430 - INFO # # Received: len   100, seq    14
2019-05-16 12:20:30,434 - INFO # # Received: len   100, seq    15
2019-05-16 12:20:30,437 - INFO # # Received: len   100, seq    16
2019-05-16 12:20:30,440 - INFO # # Received: len   100, seq    17
2019-05-16 12:20:30,444 - INFO # # Received: len   100, seq    18
2019-05-16 12:20:30,447 - INFO # # Received: len   100, seq    19
2019-05-16 12:20:30,450 - INFO # # Received: len   100, seq    20
2019-05-16 12:20:30,453 - INFO # # Received: len   100, seq    21
2019-05-16 12:20:30,457 - INFO # # Received: len   100, seq    22
2019-05-16 12:20:30,491 - INFO # # Received: len   100, seq    23
2019-05-16 12:20:30,537 - INFO # # Received: len   100, seq     0
2019-05-16 12:20:30,542 - INFO # # Received: len   100, seq 6555648
2019-05-16 12:20:30,546 - INFO # # Received: len   100, seq 6555648
2019-05-16 12:20:30,588 - INFO # # Received: len   100, seq 6555648
[ the last line is repeated forever ]

Node B (client):

2019-05-16 12:20:26,664 - INFO #  main(): This is RIOT! (Version: 2019.07-devel-289-g8ccf8-opt_nimble_ver370305a)
2019-05-16 12:20:26,667 - INFO # NimBLE L2CAP test application
2019-05-16 12:20:26,668 - INFO # # Scanning now
2019-05-16 12:20:26,782 - INFO # # Found Server, connecting now# GAP event: 0
2019-05-16 12:20:26,883 - INFO # # L2CAP: CONNECTED
2019-05-16 12:20:26,885 - INFO # # Connection established
2019-05-16 12:20:26,887 - INFO # # MTUs: our 250, remote 250
2019-05-16 12:20:26,889 - INFO # # Shell is now available
> flood 100 100
2019-05-16 12:20:30,355 - INFO #  flood 100 100
2019-05-16 12:20:30,358 - INFO # # Sending: size   100 seq     1
2019-05-16 12:20:30,361 - INFO # # Sending: size   100 seq     2
2019-05-16 12:20:30,364 - INFO # # Sending: size   100 seq     3
2019-05-16 12:20:30,367 - INFO # # Sending: size   100 seq     4
2019-05-16 12:20:30,370 - INFO # # Sending: size   100 seq     5
2019-05-16 12:20:30,373 - INFO # # Sending: size   100 seq     6
2019-05-16 12:20:30,375 - INFO # # Sending: size   100 seq     7
2019-05-16 12:20:30,378 - INFO # # Sending: size   100 seq     8
2019-05-16 12:20:30,381 - INFO # # Sending: size   100 seq     9
2019-05-16 12:20:30,384 - INFO # # Sending: size   100 seq    10
2019-05-16 12:20:30,387 - INFO # # Sending: size   100 seq    11
2019-05-16 12:20:30,391 - INFO # # Sending: size   100 seq    12
2019-05-16 12:20:30,395 - INFO # # Sending: size   100 seq    13
2019-05-16 12:20:30,398 - INFO # # Sending: size   100 seq    14
2019-05-16 12:20:30,401 - INFO # # Sending: size   100 seq    15
2019-05-16 12:20:30,404 - INFO # # Sending: size   100 seq    16
2019-05-16 12:20:30,408 - INFO # # Sending: size   100 seq    17
2019-05-16 12:20:30,411 - INFO # # Sending: size   100 seq    18
2019-05-16 12:20:30,414 - INFO # # Sending: size   100 seq    19
2019-05-16 12:20:30,417 - INFO # # Sending: size   100 seq    20
2019-05-16 12:20:30,421 - INFO # # Sending: size   100 seq    21
2019-05-16 12:20:30,424 - INFO # # Sending: size   100 seq    22
2019-05-16 12:20:30,428 - INFO # # Sending: size   100 seq    23
[stuck]

Node B gets stuck in the send loop, endlessly stalling and unstalling without ever leaving the loop (see code snip above).

Theory

Though don't fully understand the issue (yet), it seems to me that this has something to do with concurrency:
ble_l2cap_coc_send() is called in the thread context of the user application, leading subsequently to ble_l2cap_coc_continue_tx() also being called from that same context. In the same time, ble_l2cap_coc_continue_tx() is also called in the context of Nimbles host stack whenever there is a l2cap_coc related event. My guess is, that calling this function in parallel from two threads leads to some scrambled state and so the send function will never exit properly.

Any idea what we can do to fix this?

[haukepetersen]

Ok, found it - seems like I was using the API in a bad way.

Simple changing the sending code to:

    res = ble_l2cap_send(_coc, txd);
    if (res == BLE_HS_ESTALLED) {
        thread_flags_wait_all(FLAG_TX_UNSTALLED);
    }

seems to solve my sending issues for good.

I am still not sure if there might be some concurrency issues left with ble_l2cap_coc_continue_tx(), but since my test cases are running fine with the code stated above, I consider this issue solved for now.

[haukepetersen]

Just for completeness: I found the most efficient way to use the send function is:

    do {
        res = ble_l2cap_send(_coc, txd);
        if (res == BLE_HS_EBUSY) {
            // OS primitive to block the thread and wait for the 
            //BLE_L2CAP_EVENT_COC_TX_UNSTALLED event, e.g.
            thread_flags_wait_all(FLAG_TX_UNSTALLED);
        }
    } while (res == BLE_HS_EBUSY);