Ringbuf: Acquiring entire ring buffer results in items being received prematurely (IDFGH-13694)

[james-corticallabs]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.4-dev-2744-g59e1838270

Espressif SoC revision.

ESP32-D0WD-V3 (revision v3.0)

Operating System used.

Linux

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

Custom Board

Power Supply used.

External 3.3V

What is the expected behavior?

I expect to:

1. Acquire space for multiple items on a ring buffer using xRingbufferSendAcquire until the ring buffer is full.
2. For each item, write a value to it and complete the sending of it using xRingbufferSendComplete. I expect to be able to do this in a different order from which the items were acquired in step 1.
3. Receive the items using xRingbufferReceive on a separate task in the order they were acquired in step 1 and containing their expected values.

What is the actual behavior?

Instead, when the buffer is full, the oldest acquired item is returned by xRingbufferReceive even if that item has not been sent yet using xRingbufferSendComplete. If the sending task has not yet finished writing to this oldest acquired item then it results in the receiving task reading the wrong value for that item.

Steps to reproduce.

1. Create a no split ring buffer
2. Create a task which reads from the ring buffer
3. Acquire first item on the ring buffer using xRingbufferSendAcquire (labelled as item1 in the steps and code below)
4. Repeat the following until the ring buffer is full
   4a. Acquire item using xRingbufferSendAcquire
   4b. Write a value to item
   4c. Send item using xRingbufferSendComplete
5. Write a value to item1
6. Send item1 using xRingbufferSendComplete

Code to reproduce:

#include <stdio.h>

#include "freertos/FreeRTOS.h"
#include "freertos/ringbuf.h"

#define QUEUE_LENGTH            3
#define FREERTOS_RB_HEADER      8   // sizeof(ItemHeader_t)
#define BUFFER_SIZE             ((FREERTOS_RB_HEADER + sizeof(uint32_t)) * QUEUE_LENGTH)

#define STACK_SIZE              2048

RingbufHandle_t xRingBuffer;
StaticRingbuffer_t xRingBufferStruct;
uint8_t xRingBufferStorage[BUFFER_SIZE];

StackType_t xStack[STACK_SIZE];
StaticTask_t xTaskBuffer;

void receive_task(void* pvParameters)
{
    size_t item_size;

    while (true)
    {
        uint32_t* item = (uint32_t*)xRingbufferReceive(xRingBuffer, &item_size, portMAX_DELAY);
        if (item != NULL)
        {
            printf("Item: %ld\n", *item);
        }
    }
}

void app_main(void)
{
    xRingBuffer = xRingbufferCreateStatic(BUFFER_SIZE, RINGBUF_TYPE_NOSPLIT, xRingBufferStorage, &xRingBufferStruct);
    xTaskCreateStatic(receive_task, "receive_task", STACK_SIZE, NULL, 2, xStack, &xTaskBuffer);

    printf("Start\n");

    uint32_t* item1;
    xRingbufferSendAcquire(xRingBuffer, (void**)&item1, sizeof(uint32_t), 0);
    *item1 = 1000;

    uint32_t* item2;
    xRingbufferSendAcquire(xRingBuffer, (void**)&item2, sizeof(uint32_t), 0);
    *item2 = 2;
    xRingbufferSendComplete(xRingBuffer, item2);

    uint32_t* item3;
    xRingbufferSendAcquire(xRingBuffer, (void**)&item3, sizeof(uint32_t), 0);
    *item3 = 3;

    vTaskDelay(3000 / portTICK_PERIOD_MS);

    // This call to xRingbufferSendComplete causes item1 to be received by receive_task prematurely 
    xRingbufferSendComplete(xRingBuffer, item3);

    vTaskDelay(3000 / portTICK_PERIOD_MS);

    *item1 = 1;
    xRingbufferSendComplete(xRingBuffer, item1);
}

Expected result of above code:

Start
Item: 1
Item: 2
Item: 3

Actual result of above code:

Start
Item: 1000
Item: 2
Item: 3

Debug Logs.

I (13) boot: ESP-IDF v5.4-dev-2744-g59e1838270 2nd stage bootloader
I (14) boot: compile time Sep 13 2024 04:37:33
I (14) boot: Multicore bootloader
I (18) boot: chip revision: v3.0
I (22) boot.esp32: SPI Speed      : 40MHz
I (27) boot.esp32: SPI Mode       : DIO
I (31) boot.esp32: SPI Flash Size : 2MB
I (36) boot: Enabling RNG early entropy source...
I (41) boot: Partition Table:
I (45) boot: ## Label            Usage          Type ST Offset   Length
I (52) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (60) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (67) boot:  2 factory          factory app      00 00 00010000 00100000
I (75) boot: End of partition table
I (79) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=09c10h ( 39952) map
I (101) esp_image: segment 1: paddr=00019c38 vaddr=3ffb0000 size=0230ch (  8972) load
I (105) esp_image: segment 2: paddr=0001bf4c vaddr=40080000 size=040cch ( 16588) load
I (113) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=13a14h ( 80404) map
I (143) esp_image: segment 4: paddr=00033a3c vaddr=400840cc size=097a0h ( 38816) load
I (165) boot: Loaded app from partition at offset 0x10000
I (165) boot: Disabling RNG early entropy source...
I (177) cpu_start: Multicore app
I (186) cpu_start: Pro cpu start user code
I (186) cpu_start: cpu freq: 160000000 Hz
I (186) app_init: Application information:
I (189) app_init: Project name:     idf-ringbuf-test
I (194) app_init: App version:      1
I (199) app_init: Compile time:     Sep 13 2024 04:37:25
I (205) app_init: ELF file SHA256:  84dc7f4bf...
I (210) app_init: ESP-IDF:          v5.4-dev-2744-g59e1838270
I (217) efuse_init: Min chip rev:     v0.0
I (221) efuse_init: Max chip rev:     v3.99 
I (226) efuse_init: Chip rev:         v3.0
I (231) heap_init: Initializing. RAM available for dynamic allocation:
I (238) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (244) heap_init: At 3FFB35B8 len 0002CA48 (178 KiB): DRAM
I (251) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (257) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (263) heap_init: At 4008D86C len 00012794 (73 KiB): IRAM
I (271) spi_flash: detected chip: generic
I (274) spi_flash: flash io: dio
W (278) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (292) main_task: Started on CPU0
I (302) main_task: Calling app_main()
Start
Item: 1000
Item: 2
Item: 3
I (6302) main_task: Returned from app_main()

More Information.

I am building using the docker image espressif/idf:latest.

[sudeep-mohanty]

Thanks for reporting the issue, @james-corticallabs. We shall take a look and get back to you on this.

[james-corticallabs]

Thanks @sudeep-mohanty for fixing this. Will this fix be backported to a current release of esp-idf?

[sudeep-mohanty]

Hi @james-corticallabs, Yes, the fix will be back ported to the release branches once our internal tests pass. Thanks.

[upolc-lg]

Hi,
according to my testing this issue is still not resolved.
I'm attaching a sample code that causes the ringbuffer to stop returning items.

#include "esp_log.h"
#include "sdkconfig.h"

#include "freertos/FreeRTOS.h"
#include "freertos/ringbuf.h"
#include "freertos/task.h"

#include <inttypes.h>
#include <stdio.h>
#include <string.h>

static const char tag_c[] = "RB_TST";

void ringbuffer_test(void *pvParameters)
{
    char *item = NULL;
    char *item_1 = NULL;
    char *item_2 = NULL;
    size_t size = 0;

    esp_log_level_set(tag_c, ESP_LOG_VERBOSE);

    RingbufHandle_t rb = xRingbufferCreate(64, RINGBUF_TYPE_NOSPLIT);

    xRingbufferSendAcquire(rb, (void **)&item_1, 15, 0);
    xRingbufferSendAcquire(rb, (void **)&item_2, 15, 0);

    xRingbufferSendComplete(rb, item_1);
    xRingbufferSendComplete(rb, item_2);

    while ((item = xRingbufferReceive(rb, &size, 0)) != NULL)
    {
        ESP_LOGI(tag_c, "1: received message size %u from %p", size, item);
        vRingbufferReturnItem(rb, item);
    }

    vTaskDelay(100);

    xRingbufferSendAcquire(rb, (void **)&item_1, 15, 0);
    xRingbufferSendAcquire(rb, (void **)&item_2, 15, 0);

    sprintf(item_1, "Hello ");

    sprintf(item_2, "This is fine");
    xRingbufferSendComplete(rb, item_2);

    while ((item = xRingbufferReceive(rb, &size, 0)) != NULL)
    {
        ESP_LOGI(tag_c, "2: received message size %u from %p: %s", size, item, item);
        vRingbufferReturnItem(rb, item);
    }

    sprintf(&item_1[6], "world");
    xRingbufferSendComplete(rb, item_1);

    while ((item = xRingbufferReceive(rb, &size, 0)) != NULL)
    {
        ESP_LOGI(tag_c, "3: received message size %u from %p: %s", size, item, item);
        vRingbufferReturnItem(rb, item);
    }

    ESP_LOGI(tag_c, "done");

    while (1)
    {
        vTaskDelay(1000);
    }
}

void app_main(void)
{
    xTaskCreate(ringbuffer_test, "RB_TST", 4096, NULL, 0, NULL);
}

I ran the same code three times. Here are the results:

esp-idf v5.3 without the fix:

I (310) RB_TST: 1: received message size 15 from 0x3fc974e0
I (310) RB_TST: 1: received message size 15 from 0x3fc974f8
I (1320) RB_TST: 2: received message size 15 from 0x3fc974e0: Hello
I (1320) RB_TST: 3: received message size 15 from 0x3fc974f8: This is fine
I (1320) RB_TST: done

esp-idf v5.3 with the fix:

I (310) RB_TST: 1: received message size 15 from 0x3fc974e0
I (310) RB_TST: 1: received message size 15 from 0x3fc974f8
I (1320) RB_TST: done

esp-idf v5.3 with my own fix:

I (310) RB_TST: 1: received message size 15 from 0x3fc974e0
I (310) RB_TST: 1: received message size 15 from 0x3fc974f8
I (1320) RB_TST: 3: received message size 15 from 0x3fc974e0: Hello world
I (1320) RB_TST: 3: received message size 15 from 0x3fc974f8: This is fine
I (1320) RB_TST: done

It looks like the problem still happens after wraparound if there were any dummy bytes at the end of ringbuffer.

[sudeep-mohanty]

Thanks for reporting the issue @upolc-lg. We shall investigate it further. I'll re-open the ticket. Since you have done some investigation already, would you mind sharing your fix or creating a PR for us? Thanks!

[sudeep-mohanty]

Closing this issue. Fix to be evaluated under #14948.