Weirdness when decoding and matching in a separate FreeRTOS task

[vladkorotnev]

Version/revision of the library used

crankyoldgit/IRremoteESP8266@^2.8.6

Describe the bug

There seems to be a race condition in the decoder, which returns a successful decode even though the actual packet has not yet been fully received.

To Reproduce

I have multiple remotes, as defined in a header in my project:

const infrared_definition_t HWCONF_IR_BUTTONS = {
    /**
        Optosupply OE13KIR (https://akizukidenshi.com/goodsaffix/OE13KIR.pdf)
    */
   
    { .protocol = IRPROTO_NEC, .address = 0x10, .command = 0xA0, .value = 0x8F705FA, .key = KEY_UP}, // UP
    { .protocol = IRPROTO_NEC, .address = 0x10, .command = 0x00, .value = 0x8F700FF, .key = KEY_DOWN}, // DOWN
    { .protocol = IRPROTO_NEC, .address = 0x10, .command = 0x10, .value = 0x8F708F7, .key = KEY_LEFT}, // LEFT
    { .protocol = IRPROTO_NEC, .address = 0x10, .command = 0x80, .value = 0x8F701FE, .key = KEY_RIGHT}, // RIGHT
    { .protocol = IRPROTO_NEC, .address = 0x10, .command = 0x20, .value = 0x8F704FB, .key = KEY_HEADPAT}, // CENTER
    { .protocol = IRPROTO_NEC, .address = 0x10, .command = 0xf8, .value = 0x8f71fe0, .key = KEY_SOFT_F1}, // A
    { .protocol = IRPROTO_NEC, .address = 0x10, .command = 0x78, .value = 0x8f71ee1, .key = KEY_SOFT_F2}, // B
    { .protocol = IRPROTO_NEC, .address = 0x10, .command = 0x58, .value = 0x8f71ae5, .key = KEY_SOFT_F3}, // C

    /**
     * ProSpec DVE (Digital Video Editor)
     */
    { .protocol = IRPROTO_NEC, .address = 0x2e82, .command = 0xa0, .value = 0x0, .key = KEY_UP },
    { .protocol = IRPROTO_NEC, .address = 0x2e82, .command = 0xa2, .value = 0x0, .key = KEY_DOWN },
    { .protocol = IRPROTO_NEC, .address = 0x2e82, .command = 0xa5, .value = 0x0, .key = KEY_LEFT },
    { .protocol = IRPROTO_NEC, .address = 0x2e82, .command = 0xa4, .value = 0x0, .key = KEY_RIGHT },
    { .protocol = IRPROTO_NEC, .address = 0x2e82, .command = 0xa1, .value = 0x0, .key = KEY_HEADPAT }, // input sw
    { .protocol = IRPROTO_NEC, .address = 0x2e82, .command = 0xa7, .value = 0x0, .key = KEY_SOFT_F1 }, // pwr
    { .protocol = IRPROTO_NEC, .address = 0x2e82, .command = 0xa6, .value = 0x0, .key = KEY_SOFT_F3 }, // frame
    { .protocol = IRPROTO_NEC, .address = 0x2e82, .command = 0xa3, .value = 0x0, .key = KEY_SOFT_F2 }, // back


    /**
     * UNKNOWN "LCD remote"
     */
    { .protocol = IRPROTO_NEC, .address = 0x6b86, .command = 0x1b, .value = 0x0, .key = KEY_UP },
    { .protocol = IRPROTO_NEC, .address = 0x6b86, .command = 0x1a, .value = 0x0, .key = KEY_DOWN },
    { .protocol = IRPROTO_NEC, .address = 0x6b86, .command = 0x4, .value = 0x0, .key = KEY_LEFT },
    { .protocol = IRPROTO_NEC, .address = 0x6b86, .command = 0x6, .value = 0x0, .key = KEY_RIGHT },
    { .protocol = IRPROTO_NEC, .address = 0x6b86, .command = 0x5, .value = 0x0, .key = KEY_HEADPAT },
    { .protocol = IRPROTO_NEC, .address = 0x6b86, .command = 0x6, .value = 0x0, .key = KEY_SOFT_F2 }, // pwr

    /**
     * UNKNOWN "Audio Switch" SPDIF/TOSLINK 4X1 REMOTE CONTROL
     */
    { .protocol = IRPROTO_NEC, .address = 0x0, .command = 0x15, .value = 0x0, .key = KEY_UP },
    { .protocol = IRPROTO_NEC, .address = 0x0, .command = 0x18, .value = 0x0, .key = KEY_DOWN },
    { .protocol = IRPROTO_NEC, .address = 0x0, .command = 0x16, .value = 0x0, .key = KEY_LEFT },
    { .protocol = IRPROTO_NEC, .address = 0x0, .command = 0xd, .value = 0x0, .key = KEY_RIGHT },
    { .protocol = IRPROTO_NEC, .address = 0x0, .command = 0x45, .value = 0x0, .key = KEY_HEADPAT },
};

(the data in the table was captured from the logs directly).

That table is used by a FreeRTOS task which polls the library every so often and logs all the received codes:

static IRrecv receiver(HWCONF_IR_RECV_GPIO);

static void ir_task(void*) {
    static decode_results results;
    while(1) {
        if(receiver.decode(&results)) {
            if(results.repeat) {
                last_pressed_timestamp = xTaskGetTickCount();
            } else if(results.overflow) {
                ESP_LOGW(LOG_TAG, "Overflow when decoding IR code TYPE=%i, VALUE=0x%x, ADDRESS=0x%x, COMMAND=0x%x", results.decode_type, results.value, results.address, results.command);
            } else {
                bool found = false;
                ESP_LOGI(LOG_TAG, "IR code { .protocol = %i, .address = 0x%x, .command = 0x%x, .value = 0x%x, .key = ? }", results.decode_type, results.address, results.command, results.value);
                for(int i = 0; i < sizeof(HWCONF_IR_BUTTONS) / sizeof(infrared_identifier_t); i++) {
                    const infrared_identifier_t * id = &HWCONF_IR_BUTTONS[i];
                    ESP_LOGI(LOG_TAG, "Check against TYPE=%i, VALUE=0x%x, ADDRESS=0x%x, COMMAND=0x%x", id->protocol, id->value, id->address, id->command);
                    if(id->protocol == (int) results.decode_type &&
                    id->address == results.address &&
                    id->command == results.command &&
                    id->value == results.value) {
                        found = true;
                        last_pressed_timestamp = xTaskGetTickCount();

                        if(last_pressed != KEY_MAX_INVALID) {
                            if(last_pressed == id->key)
                                break;
                            ESP_LOGI(LOG_TAG, "Unpress key %i (recv)", last_pressed);
                            hid_set_key_state(last_pressed, false);
                        }

                        last_pressed = id->key;
                        ESP_LOGI(LOG_TAG, "Press key %i", last_pressed);
                        hid_set_key_state(id->key, true);
                        break;
                    }
                }
                if(!found) {
                    ESP_LOGI(LOG_TAG, "Unknown IR code { .protocol = %i, .address = 0x%x, .command = 0x%x, .value = 0x%x, .key = ? }", results.decode_type, results.address, results.command, results.value);
                    ESP_LOGI(LOG_TAG, "%s", resultToHumanReadableBasic(&results).c_str());
                    ESP_LOGI(LOG_TAG, "%s", resultToSourceCode(&results).c_str());
                }
            }

            receiver.resume();
        } else {
            if(last_pressed != KEY_MAX_INVALID && (xTaskGetTickCount() - last_pressed_timestamp) > pdMS_TO_TICKS(300)) {
                ESP_LOGI(LOG_TAG, "Unpress key %i (timeout)", last_pressed);
                hid_set_key_state(last_pressed, false);
                last_pressed = KEY_MAX_INVALID;
            }
        }
        vTaskDelay(pdMS_TO_TICKS(25));
    }
}

The weirdness begins when I use some specific remotes.

If I use the OptoSupply one (first one in the array — but it doesn't matter if I move it around in the array or not), the code correctly matches to an entry in the table. Logs are then as follows:

[524085][I][infrared.cpp:33] ir_task(): [IRRC] IR code { .protocol = 3, .address = 0x10, .command = 0x0, .value = 0x45, .key = ? }
[524085][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f705fa, ADDRESS=0x10, COMMAND=0xa0
[524095][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f700ff, ADDRESS=0x10, COMMAND=0x0
[524105][I][infrared.cpp:52] ir_task(): [IRRC] Press key 2

As you can see, the printed code and the printed entry do not match in the logs — yet they properly matched in the if condition for some reason.

If I press another button on another remote, we can see that the outputted code is different each time it's logged.

[743733][I][infrared.cpp:33] ir_task(): [IRRC] IR code { .protocol = 3, .address = 0x2e82, .command = 0xa0, .value = 0x45, .key = ? }
[743734][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f705fa, ADDRESS=0x10, COMMAND=0xa0
[743743][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f700ff, ADDRESS=0x10, COMMAND=0x0
[743753][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f708f7, ADDRESS=0x10, COMMAND=0x10
[743763][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f701fe, ADDRESS=0x10, COMMAND=0x80
[743773][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f704fb, ADDRESS=0x10, COMMAND=0x20
[743783][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f71fe0, ADDRESS=0x10, COMMAND=0xf8
[743793][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f71ee1, ADDRESS=0x10, COMMAND=0x78
[743803][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x8f71ae5, ADDRESS=0x10, COMMAND=0x58
[743813][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x2e82, COMMAND=0xa0
[743822][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x2e82, COMMAND=0xa2
[743832][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x2e82, COMMAND=0xa5
[743841][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x2e82, COMMAND=0xa4
[743851][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x2e82, COMMAND=0xa1
[743860][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x2e82, COMMAND=0xa7
[743870][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x2e82, COMMAND=0xa6
[743879][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x2e82, COMMAND=0xa3
[743889][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x6b86, COMMAND=0x1b
[743899][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x6b86, COMMAND=0x1a
[743908][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x6b86, COMMAND=0x4
[743918][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x6b86, COMMAND=0x6
[743927][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x6b86, COMMAND=0x5
[743936][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x6b86, COMMAND=0x6
[743946][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x0, COMMAND=0x15
[743955][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x0, COMMAND=0x18
[743964][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x0, COMMAND=0x16
[743974][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x0, COMMAND=0xd
[743983][I][infrared.cpp:36] ir_task(): [IRRC] Check against TYPE=3, VALUE=0x0, ADDRESS=0x0, COMMAND=0x45
[743992][I][infrared.cpp:57] ir_task(): [IRRC] Unknown IR code { .protocol = 3, .address = 0x2e82, .command = 0xa0, .value = 0x45, .key = ? }
[744005][I][infrared.cpp:58] ir_task(): [IRRC] Protocol  : NEC
Code      : 0x417405FA (32 Bits)

[744013][I][infrared.cpp:59] ir_task(): [IRRC] uint16_t rawData[67] = {9010, 4478,  600, 544,  626, 1642,  596, 542,  600, 544,  600, 544,  600, 546,  600, 546,  602, 1662,  600, 544,  600, 1662,  600, 1672,  590, 1662,  604, 542,  600, 1662,  598, 546,  600, 550,  600, 546,  600, 544,  600, 546,  602, 542,  602, 546,  600, 1666,  600, 550,  596, 1664,  596, 1662,  600, 1662,  600, 1662,  600, 1662,  600, 1662,  600, 544,  604, 1662,  596, 520,  602};  // NEC 417405FA
uint32_t address = 0x2E82;
uint32_t command = 0xA0;
uint64_t data = 0x417405FA;

As you can see, the code logged by the ESP_LOGI line and the code logged by the resultToSourceCode call is different.

I'm not sure if this is a library problem or am I doing something wrong, so if you could please spin me around into the right direction that would be much appreciated!

What brand/model IR demodulator are you using?

Sharp GP1UXC41QS

Circuit diagram and hardware used (if applicable)

Just output of receiver to GPIO 14.

[crankyoldgit]

As you can see, the printed code and the printed entry do not match in the logs — yet they properly matched in the if condition for some reason.

I think one of the reasons for this is you are using the incorrect variable display format in the format string.
Remember "%x" is for an unsigned int (or int16_t) the address & command are unsigned long or uint32_t e.g. "%lx".
The value is a unsigned long long or uint64_t. Normal formatting string expansion on the ESP platforms doesn't handle 64 bit integers, hence the existence of uint64ToString()

That probably explains why your if comparison is working as expected, yet your logging reports something different than you would expect.

e.g.
In your code id.address is an unsigned int/uint16_t but results.address is a unsigned long/uint32_t.
Ditto id.value in your code will be a unsigned long/uint32_t but results.value is a unsigned long long/uint64_t.
The compiler knows how to compare 16bit values to 32bit values, and 32bit values to 64bit values. i.e. Your if statement logic, but "printf`'ing it is a completely different matter.