esp-modem: esp_modem_set_urc buffer issues? seeing same URCs multiple times (IDFGH-14179)

[jodab]

Answers checklist.

• I have read the documentation for esp-protocols components and the issue is not addressed there.
• I have updated my esp-protocols 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.

General issue report

I decided to test using the new urc callback feature but running in to some strange issues.

The esp_modem_set_urc(dce, urc_handler); is returning the same lines (or chunks of data) several times, from how I understand it. I've tried just printing whatever is returned without any kind of processing and the duplicate messages keeps coming. I'm not the most experienced with c programming so I might have misunderstood something here..

But in essence it's like every read seems to include previous data still in the buffer.

I verified that the modem isn't doing some funny stuff using an a different app on the esp32 which just let me to raw read/writes directly to the uart, and no problems there.

I've attached the code if it is of any help.

Here's a log while trying to debug what's going on:

I (00:00:08.532) main: Waiting for modem to respond...
I (00:00:09.032) main: Waiting for modem to respond...
I (00:00:09.532) main: Waiting for modem to respond...
I (00:00:10.032) main: Waiting for modem to respond...
I (00:00:10.532) main: Waiting for modem to respond...
I (00:00:10.540) main: Modem synchronized successfully.
I (00:00:11.540) main: ATE0 success
I (00:00:11.550) urc_handler: URC buffer hex @11467ms (25 bytes): 0d 0a 38 36 32 37 37 31 30 37 35 34 39 39 35 33 36 0d 0a 0d 0a 4f 4b 0d 0a 
I (00:00:11.553) main: IMEI=862771075499536
I (00:00:12.086) urc_handler: URC buffer hex @12003ms (16 bytes): 0d 0a 2b 43 50 49 4e 3a 20 52 45 41 44 59 0d 0a 
I (00:00:12.086) main: urc: +CPIN: READY
I (00:00:13.527) urc_handler: URC buffer hex @13445ms (28 bytes): 0d 0a 2b 43 50 49 4e 3a 20 52 45 41 44 59 0d 0a 0d 0a 53 4d 53 20 44 4f 4e 45 0d 0a 
I (00:00:13.531) main: urc: +CPIN: READY
I (00:00:13.643) urc_handler: URC buffer hex @13560ms (41 bytes): 0d 0a 2b 43 50 49 4e 3a 20 52 45 41 44 59 0d 0a 0d 0a 53 4d 53 20 44 4f 4e 45 0d 0a 0d 0a 2b 53 4d 53 20 46 55 4c 4c 0d 0a 
I (00:00:13.650) main: urc: +CPIN: READY
I (00:00:13.655) main: urc: +SMS FULL
I (00:00:15.737) urc_handler: URC buffer hex @15654ms (65 bytes): 0d 0a 2b 43 50 49 4e 3a 20 52 45 41 44 59 0d 0a 0d 0a 53 4d 53 20 44 4f 4e 45 0d 0a 0d 0a 2b 53 4d 53 20 46 55 4c 4c 0d 0a 0d 0a 2b 43 47 45 56 3a 20 45 50 53 20 50 44 4e 20 41 43 54 20 31 0d 0a 
I (00:00:15.750) main: urc: +CPIN: READY
I (00:00:15.755) main: urc: +SMS FULL
I (00:00:15.759) main: urc: +CGEV: EPS PDN ACT 1
I (00:00:22.635) urc_handler: URC buffer hex @22552ms (76 bytes): 0d 0a 2b 43 50 49 4e 3a 20 52 45 41 44 59 0d 0a 0d 0a 53 4d 53 20 44 4f 4e 45 0d 0a 0d 0a 2b 53 4d 53 20 46 55 4c 4c 0d 0a 0d 0a 2b 43 47 45 56 3a 20 45 50 53 20 50 44 4e 20 41 43 54 20 31 0d 0a 0d 0a 50 42 20 44 4f 4e 45 0d 0a 
I (00:00:22.651) main: urc: +CPIN: READY
I (00:00:22.656) main: urc: +SMS FULL
I (00:00:22.660) main: urc: +CGEV: EPS PDN ACT 1

the function i'm using:

static esp_err_t urc_handler(uint8_t *data, size_t len) {
    if(!data || !len) return ESP_ERR_INVALID_ARG;
    const char *TAG =  "urc_handler";

    // Debug
    char hex_buf[len * 3 + 1]; // 2 chars per byte + space
    memset(hex_buf, 0, len * 3 + 1);
    char *p = hex_buf;
    for(int i = 0; i < len; i++) {
        p += sprintf(p, "%02x ", data[i]);
    }
    int64_t time_ms = esp_timer_get_time() / 1000;
    ESP_LOGI(TAG, "URC buffer hex @%lldms (%d bytes): %s", time_ms, len, hex_buf);
    ESP_LOGD(TAG, "URC raw: '%.*s'", len, data);

    // Queue entire buffer for processing in task context
    urc_message_t msg = {0};
    size_t copy_len = len < (URC_MAX_LEN-1) ? len : (URC_MAX_LEN-1);
    memcpy(msg.data, data, copy_len);

    BaseType_t xHigherPriorityTaskWoken = pdFALSE;
    if(xQueueSendFromISR(urc_queue, &msg, &xHigherPriorityTaskWoken) != pdTRUE) {
        return ESP_FAIL;  // Keep in buffer if queue full
    }
    
    if(xHigherPriorityTaskWoken) {
        portYIELD_FROM_ISR();
    }

    return ESP_OK;  // Signal buffer can be cleared
}

I could do a lot more processing inside the urc_handler to work around this. But I thought it would be best to do the bare minimum here as to not cause any blocking in the uart. Just pass along urcs for handling in another task. Maybe this is the wrong approach?

It also seems that any at command processing by esp-modem will reset the urc buffer normally when looking at the logs. But when I signal to it that it's been processed it doesn't get consumed.

main.zip

[jodab]

Problem went away when enabling CMUX strangely

[david-cermak]

@jodab It is still expected that it keeps buffering up (for easier parsing, as the data might come in chunks, but maybe I could add another parameter to indicate the current chunk?)

Problem went away when enabling CMUX strangely

This is expected, too, as we process the data on CMUX frame boundary (here data come in frames -- could be chunked, but the library defragments it to frames)

[jodab]

@jodab It is still expected that it keeps buffering up (for easier parsing, as the data might come in chunks, but maybe I could add another parameter to indicate the current chunk?)

Problem went away when enabling CMUX strangely

This is expected, too, as we process the data on CMUX frame boundary (here data come in frames -- could be chunked, but the library defragments it to frames)

@david-cermak Thank you so much for clarifying. I think I just have to rethink how I approach this, but the parameter to indicate current chunk sounds like it would make it easier to work with.