Possible bug on mqtt5 client when QoS>0 (IDFGH-10436)

[jmpmscorp]

Enviroment

• Windows 10
• esp-wrover-kit (esp32)
• esp-idf v5.0.2 release

Description

Reason code on messages with QoS1 or QoS2 doesn't return 0x00 when brokers don't add reason code in PUBACK, PUBREL, PUBREC and PUBCOMP packets and its remaining length are exactly 2.

Tested with:

Code

#include <stdio.h>
#include <stdint.h>
#include <stddef.h>
#include <string.h>

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

#include "esp_log.h"
#include "esp_check.h"
#include "esp_system.h"
#include "esp_event.h"

#include "protocol_examples_common.h"

#include "nvs_flash.h"
#include "nvs.h"
#include "mqtt_client.h"

#define MQTT_BROKER_MOSQUITTO 1
#define MQTT_BROKER_HIVEMQ 2
#define MQTT_BROKER_EMQX 3
#define MQTT_BROKER_ECLIPSE_PROJECT 4

#define MQTT_BROKER_USED 4
#define MQTT_QOS_USED 2

#define MQTT_BROKER_MOSQUITTO 1
#define MQTT_BROKER_HIVEMQ 2
#define MQTT_BROKER_EMQX 3
#define MQTT_BROKER_ECLIPSE_PROJECT 4

#define MQTT_BROKER_USED 3
#define MQTT_QOS_USED 2

#if MQTT_BROKER_USED == MQTT_BROKER_MOSQUITTO
#define MQTT_BROKER_URL "mqtt://test.mosquitto.org"
#define MQTT_BROKER_PORT 1883

#elif MQTT_BROKER_USED == MQTT_BROKER_HIVEMQ
#define MQTT_BROKER_URL "mqtt://broker.hivemq.com"
#define MQTT_BROKER_PORT 1883

#elif MQTT_BROKER_USED == MQTT_BROKER_EMQX
#define MQTT_BROKER_URL "mqtt://broker.emqx.io"
#define MQTT_BROKER_PORT 1883

#elif MQTT_BROKER_USED == MQTT_BROKER_ECLIPSE_PROJECT
#define MQTT_BROKER_URL "mqtt://mqtt.eclipseprojects.io"
#define MQTT_BROKER_PORT 1883

#elif
#pragma error "Not defined MQTT broker to use"
#endif

static const char *TAG = "MQTT5_EXAMPLE";

static void log_error_if_nonzero(const char *message, int error_code)
{
    if (error_code != 0)
    {
        ESP_LOGE(TAG, "Last error %s: 0x%x", message, error_code);
    }
}

static esp_mqtt5_user_property_item_t mqtt_user_properties[] = {
    {"board", "esp32"},
};

#define USE_PROPERTY_ARR_SIZE sizeof(mqtt_user_properties) / sizeof(esp_mqtt5_user_property_item_t)

static void mqtt5_event_handler(void *handler_args, esp_event_base_t base, int32_t event_id, void *event_data)
{
    ESP_LOGD(TAG, "Event dispatched from event loop base=%s, event_id=%" PRIi32, base, event_id);
    esp_mqtt_event_handle_t event = event_data;
    esp_mqtt_client_handle_t client = event->client;
    int msg_id;

    ESP_LOGD(TAG, "free heap size is %" PRIu32 ", minimum %" PRIu32, esp_get_free_heap_size(), esp_get_minimum_free_heap_size());
    switch ((esp_mqtt_event_id_t)event_id)
    {
    case MQTT_EVENT_CONNECTED:
        ESP_LOGI(TAG, "MQTT connected to %s:%d", MQTT_BROKER_URL, MQTT_BROKER_PORT);
        break;

    case MQTT_EVENT_DISCONNECTED:
        ESP_LOGI(TAG, "MQTT disconnected");
        break;
    case MQTT_EVENT_SUBSCRIBED:
        ESP_LOGI(TAG, "MQTT_EVENT_SUBSCRIBED, msg_id=%d", event->msg_id);
        break;

    case MQTT_EVENT_UNSUBSCRIBED:
        ESP_LOGI(TAG, "MQTT_EVENT_UNSUBSCRIBED, msg_id=%d", event->msg_id);
        break;

    case MQTT_EVENT_PUBLISHED:
        ESP_LOGI(TAG, "MQTT PUBLISHED, msg_id=%d", event->msg_id);
        break;

    case MQTT_EVENT_DATA:
        ESP_LOGI(TAG, "MQTT_EVENT_DATA");
        ESP_LOGI(TAG, "payload_format_indicator is %d", event->property->payload_format_indicator);
        ESP_LOGI(TAG, "response_topic is %.*s", event->property->response_topic_len, event->property->response_topic);
        ESP_LOGI(TAG, "correlation_data is %.*s", event->property->correlation_data_len, event->property->correlation_data);
        ESP_LOGI(TAG, "content_type is %.*s", event->property->content_type_len, event->property->content_type);
        ESP_LOGI(TAG, "TOPIC=%.*s", event->topic_len, event->topic);
        ESP_LOGI(TAG, "DATA=%.*s", event->data_len, event->data);
        break;

    case MQTT_EVENT_DELETED:
        ESP_LOGI(TAG, "MQTT_EVENT_DELETED, msg_id=%d", event->msg_id);
        break;

    case MQTT_EVENT_ERROR:
        ESP_LOGI(TAG, "MQTT_EVENT_ERROR");
        ESP_LOGI(TAG, "MQTT5 return code is %d", event->error_handle->connect_return_code);
        if (event->error_handle->error_type == MQTT_ERROR_TYPE_TCP_TRANSPORT)
        {
            log_error_if_nonzero("reported from esp-tls", event->error_handle->esp_tls_last_esp_err);
            log_error_if_nonzero("reported from tls stack", event->error_handle->esp_tls_stack_err);
            log_error_if_nonzero("captured as transport's socket errno", event->error_handle->esp_transport_sock_errno);
            ESP_LOGI(TAG, "Last errno string (%s)", strerror(event->error_handle->esp_transport_sock_errno));
        }
        break;
    default:
        ESP_LOGI(TAG, "Other event id:%d", event->event_id);
        break;
    }
}

static void mqtt5_publisher_task(void *param)
{
    esp_mqtt5_connection_property_config_t connect_property = {
        .session_expiry_interval = 10,
        .maximum_packet_size = 1024,
        .receive_maximum = 65535,
        .topic_alias_maximum = 2,
        .request_resp_info = true,
        .request_problem_info = true,
        .will_delay_interval = 10,
        .payload_format_indicator = true,
        .message_expiry_interval = 10,
    };

    esp_mqtt_client_config_t mqtt5_cfg = {
        // .broker.address.uri = CONFIG_BROKER_URL,
        .broker.address.uri = MQTT_BROKER_URL,
        .broker.address.port = MQTT_BROKER_PORT,
        .session.protocol_ver = MQTT_PROTOCOL_V_5,
        .network.disable_auto_reconnect = false,
    };

    esp_mqtt5_client_handle_t mqtt_client = esp_mqtt_client_init(&mqtt5_cfg);

    /* Set connection properties and user properties */
    esp_mqtt5_client_set_user_property(&connect_property.user_property, mqtt_user_properties, USE_PROPERTY_ARR_SIZE);
    esp_mqtt5_client_set_user_property(&connect_property.will_user_property, mqtt_user_properties, USE_PROPERTY_ARR_SIZE);
    esp_mqtt5_client_set_connect_property(mqtt_client, &connect_property);

    /* If you call esp_mqtt5_client_set_user_property to set user properties, DO NOT forget to delete them.
     * esp_mqtt5_client_set_connect_property will malloc buffer to store the user_property and you can delete it after
     */
    esp_mqtt5_client_delete_user_property(connect_property.user_property);
    esp_mqtt5_client_delete_user_property(connect_property.will_user_property);

    /* The last argument may be used to pass data to the event handler, in this example mqtt_event_handler */
    esp_mqtt_client_register_event(mqtt_client, ESP_EVENT_ANY_ID, mqtt5_event_handler, NULL);
    esp_mqtt_client_start(mqtt_client);

    while (true)
    {
        esp_mqtt5_publish_property_config_t publish_property = {
            .payload_format_indicator = 1,
            .message_expiry_interval = 5000,
        };

        esp_mqtt5_client_set_user_property(&publish_property.user_property, mqtt_user_properties, USE_PROPERTY_ARR_SIZE);
        esp_mqtt5_client_set_publish_property(mqtt_client, &publish_property);
        int msg_id = esp_mqtt_client_enqueue(mqtt_client, "test/qos_over_0", "hello world!", 0, MQTT_QOS_USED, false, false);
        esp_mqtt5_client_delete_user_property(publish_property.user_property);
        publish_property.user_property = NULL;

        vTaskDelay(pdMS_TO_TICKS(1000));
    }
}

void app_main(void)
{
    ESP_LOGI(TAG, "[APP] Startup..");
    ESP_LOGI(TAG, "[APP] Free memory: %d bytes", esp_get_free_heap_size());
    ESP_LOGI(TAG, "[APP] IDF version: %s", esp_get_idf_version());

    esp_log_level_set("*", ESP_LOG_INFO);
    esp_log_level_set("mqtt_client", ESP_LOG_VERBOSE);
    esp_log_level_set("mqtt5_client", ESP_LOG_VERBOSE);
    esp_log_level_set("MQTT_EXAMPLE", ESP_LOG_VERBOSE);
    // esp_log_level_set("TRANSPORT_BASE", ESP_LOG_VERBOSE);
    // esp_log_level_set("esp-tls", ESP_LOG_VERBOSE);
    // esp_log_level_set("TRANSPORT", ESP_LOG_VERBOSE);
    esp_log_level_set("outbox", ESP_LOG_VERBOSE);

    ESP_ERROR_CHECK(nvs_flash_init());
    ESP_ERROR_CHECK(esp_netif_init());
    ESP_ERROR_CHECK(esp_event_loop_create_default());

    /* This helper function configures Wi-Fi or Ethernet, as selected in menuconfig.
     * Read "Establishing Wi-Fi or Ethernet Connection" section in
     * examples/protocols/README.md for more information about this function.
     */
    ESP_ERROR_CHECK(example_connect());

    xTaskCreate(mqtt5_publisher_task, "mqtt publisher tsk", configMINIMAL_STACK_SIZE * 6, NULL, 5, NULL);

    // mqtt5_app_start();
}

Log on mosquitto, hivemq and eclipseproject free online test brokers.

Log on emqx free online test broker.

Yellow log message is the packet received by the broker. I add this line on mqtt5_msg_get_reason_code function. Same log with same local broker docker versions .

With EMQX broker, message error E (29216) mqtt5_client: Client send more than 20 QoS1 and QoS2 PUBLISH packet without no ack is not shown.

In OASIS mqtt specs in PUBACK, PUBREL, PUBREC and PUBCOMP packets we can find this:

It seems that mosquitto, hivemq and eclipse broker tested don't append reason code on success.

As can be checked in logs, when broker doesn't append reason code (yellow lines), returned value is -1 but, by specs, it should be 0x00. I suppose that this -1 returned value is the cause that messages waiting to be confirmed by PUBxxx packets show E (29216) mqtt5_client: Client send more than 20 QoS1 and QoS2 PUBLISH packet without no ack error.

** Edit
After apply patch #243 E (29216) mqtt5_client: Client send more than 20 QoS1 and QoS2 PUBLISH packet without no ack goes out on every broker

[ESP-YJM]

@jmpmscorp Thanks for reporting it. We will fix it.

[AxelLin]

@jmpmscorp Thanks for reporting it. We will fix it.

@ESP-YJM
There is no update for 10 Months? How is the progress for this fix?

[ESP-YJM]

@jmpmscorp Could you please use the latest MQTT components, maybe use IDF master branch to test the issue E (29216) mqtt5_client: Client send more than 20 QoS1 and QoS2 PUBLISH packet without no ac. And for mqtt5_msg_get_reason_code return -1, the reason code is 0x0, it not affect the code logic and only a print issue. Sorry that i forget to fix it. Thanks for reminding @AxelLin

[jmpmscorp]

Sorry for delay @ESP-YJM , holiday time.

I have tested again with IDF 5.3 release version, QoS2 and no more E (29216) mqtt5_client: Client send more than 20 QoS1 and QoS2 PUBLISH packet without no ack.

Reason code -1 still printed. I know it will not affect but, maybe, in my opinion, it would be a good idea return another value than -1 that could be interpreted as unknown error and, certainly, it's not an error because it must be equal than 0x00.

Thanks for your work.