search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.32k stars 7.2k forks source link

E (1307459) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128 (IDFGH-4517) #6341

Closed wjdready closed 3 years ago

wjdready commented 3 years ago

Environment

Problem Description

When I connect to a remote Mqtt server, the Mqtt client of Esp32 is always disconnected regularly. It always disconnects on time after 10 minutes of connecting to the Mqtt server, then reconnects within seconds, and then disconnects after 10 minutes of reconnection. There are two possibilities for this problem, one is that there is a problem with the server, and the other is that there is a problem with Esp32 If there is a problem with the server, there is no problem when I use the paho.mqtt.client library under python to connect to the remote server. If there is a problem with Esp32, there is no problem when I use Esp32 to connect to mqtt://mqtt.eclipse.org. So what's the problem? Please help me.

Expected Behavior

I need to keep Esp32 mqtt stable enough to communicate with my server.

Actual Behavior

It always disconnects in 10 minutes.

Steps to reproduce

Code to reproduce this issue

#include <stdio.h>
#include "esp_spi_flash.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "freertos/event_groups.h"
#include "mqtt_client.h"
#include "esp_wifi.h"
#include "nvs_flash.h"
#include "esp_netif.h"
#include "esp_log.h"
#include "protocol_examples_common.h"

static EventGroupHandle_t mqtt_event_group;
const static int CONNECTED_BIT = BIT5;      
static bool mqtt_connected = false;
static esp_mqtt_client_handle_t global_client;

static esp_err_t mqtt_event_handler(esp_mqtt_event_handle_t event)
{
    static const char *TAG = "mqtt_event";

    switch (event->event_id)
    {
    case MQTT_EVENT_CONNECTED:
        ESP_LOGI(TAG, "MQTT_EVENT_CONNECTED");
        xEventGroupSetBits(mqtt_event_group, CONNECTED_BIT);
        mqtt_connected = true;
        break;
    case MQTT_EVENT_DISCONNECTED:
        ESP_LOGI(TAG, "MQTT_EVENT_DISCONNECTED");
        mqtt_connected = false;
        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_EVENT_PUBLISHED, msg_id=%d", event->msg_id);
        break;
    case MQTT_EVENT_DATA:
        printf("TOPIC=%d , %.*s\r\n", event->topic_len, event->topic_len, event->topic);
        printf("DATA=%d , %.*s\r\n", event->data_len, event->data_len, event->data);
        break;
    default:
        ESP_LOGI(TAG, "Other event id:%d", event->event_id);
        break;
    }

    return ESP_OK;
}

void mqtt_server_login()
{
    mqtt_event_group = xEventGroupCreate();
    esp_mqtt_client_config_t mqtt_cfg = {
        // .uri = "mqtt://mqtt.eclipse.org",
        .uri = "mqtt://192.168.137.1",
        .port = 1883,
        .event_handle = mqtt_event_handler
    };
    mqtt_cfg.username = "user1";
    mqtt_cfg.password = "123456";
    mqtt_cfg.client_id = "test";
    global_client = esp_mqtt_client_init(&mqtt_cfg);
    esp_mqtt_client_start(global_client);
}

void app_main(void)
{
    ESP_ERROR_CHECK(nvs_flash_init());
    ESP_ERROR_CHECK(esp_netif_init());
    ESP_ERROR_CHECK(esp_event_loop_create_default());
    ESP_ERROR_CHECK(example_connect());

    mqtt_server_login();

    xEventGroupWaitBits(mqtt_event_group, CONNECTED_BIT, false, true, portMAX_DELAY);

    while (1)
    {
        if(mqtt_connected == true)
            esp_mqtt_client_publish(global_client, "/test", "s", 1, 0, 0);
        vTaskDelay(1000 / portTICK_PERIOD_MS);
    }

}

Debug Logs

I (563) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (669) wifi:wifi driver task: 3ffc04dc, prio:23, stack:6656, core=0
I (669) system_api: Base MAC address is not set
I (669) system_api: read default base MAC address from EFUSE
I (689) wifi:wifi firmware version: 1865b55
I (689) wifi:wifi certification version: v7.0
I (689) wifi:config NVS flash: enabled
I (689) wifi:config nano formating: disabled
I (699) wifi:Init data frame dynamic rx buffer num: 32
I (699) wifi:Init management frame dynamic rx buffer num: 32
I (709) wifi:Init management short buffer num: 32
I (709) wifi:Init dynamic tx buffer num: 32
I (719) wifi:Init static rx buffer size: 1600
I (719) wifi:Init static rx buffer num: 10
I (719) wifi:Init dynamic rx buffer num: 32
I (729) wifi_init: rx ba win: 6
I (729) wifi_init: tcpip mbox: 32
I (739) wifi_init: udp mbox: 6
I (739) wifi_init: tcp mbox: 6
I (739) wifi_init: tcp tx win: 5744
I (749) wifi_init: tcp rx win: 5744
I (749) wifi_init: tcp mss: 1440
I (759) wifi_init: WiFi IRAM OP enabled
I (759) wifi_init: WiFi RX IRAM OP enabled
I (769) example_connect: Connecting to fyy...
I (859) phy: phy_version: 4500, 0cd6843, Sep 17 2020, 15:37:07, 0, 0
I (859) wifi:mode : sta (b8:f0:09:93:4a:24)
I (869) example_connect: Waiting for IP(s)
I (989) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:10
I (1759) wifi:state: init -> auth (b0)
I (1759) wifi:state: auth -> assoc (0)
E (1769) wifi:Set status to INIT
I (1769) wifi:state: assoc -> init (c00)
I (1769) wifi:new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:10
I (1769) wifi:new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:10
I (1779) wifi:state: init -> auth (b0)
I (1799) wifi:state: auth -> assoc (0)
I (1849) wifi:state: assoc -> run (10)
I (1889) wifi:connected with fyy, aid = 1, channel 6, BW20, bssid = c6:72:64:dc:16:b6
I (1889) wifi:security: WPA2-PSK, phy: bgn, rssi: -58
I (1889) wifi:pm start, type: 1

I (1989) wifi:AP's beacon interval = 307200 us, DTIM period = 3
I (2659) esp_netif_handlers: example_connect: sta ip: 172.20.10.11, mask: 255.255.255.240, gw: 172.20.10.1
I (2659) example_connect: Got IPv4 event: Interface "example_connect: sta" address: 172.20.10.11
I (3659) example_connect: Got IPv6 event: Interface "example_connect: sta" address: fe80:0000:0000:0000:baf0:09ff:fe93:4a24, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (3659) example_connect: Connected to example_connect: sta
I (3669) example_connect: - IPv4 address: 172.20.10.11
I (3669) example_connect: - IPv6 address: fe80:0000:0000:0000:baf0:09ff:fe93:4a24, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (3689) mqtt_event: Other event id:7
I (3803079) mqtt_event: Other event id:7
I (3804639) mqtt_event: MQTT_EVENT_CONNECTED
E (4407399) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128
I (4407399) mqtt_event: Other event id:0
E (4407399) MQTT_CLIENT: mqtt_process_receive: mqtt_message_receive() returned -1
I (4407409) mqtt_event: MQTT_EVENT_DISCONNECTED
I (4422409) mqtt_event: Other event id:7
I (4423939) mqtt_event: MQTT_EVENT_CONNECTED
E (5027969) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128
I (5027969) mqtt_event: Other event id:0
E (5027979) MQTT_CLIENT: mqtt_process_receive: mqtt_message_receive() returned -1
I (5027989) mqtt_event: MQTT_EVENT_DISCONNECTED
I (5042989) mqtt_event: Other event id:7
I (5043859) mqtt_event: MQTT_EVENT_CONNECTED
Alvin1Zhang commented 3 years ago

Thanks for reporting, we will look into.

wjdready commented 3 years ago

Mqtt broker is a Vert.x MQTT implemented in Java.

david-cermak commented 3 years ago

@wjdready Could you please share the debug log from your board and possibly some log from the server side, as well? And possibly also a wireshark capture of the disconnection event, which is happening every 10 minutes?

I've tested your code (on v4.2 -- c40f2590bf759ff60ef122afa79b4ec04e7633d2) with vertx-mqtt broker running on my PC and seen no disconnections.

Alvin1Zhang commented 3 years ago

@wjdready Thanks for reporting, would you please help share if any updates for the issue? Thanks.

wjdready commented 3 years ago

@Alvin1Zhang It has been solved. It is my own vertx-mqtt problem. Vertx-mqtt disconnects the device without heartbeat. It's ok after I join the heartbeat. Thank you for your answers.

Alvin1Zhang commented 3 years ago

@wjdready Thanks for sharing updates.

anudeepsharma254 commented 3 years ago

Hi I'm having same issue with ESP32 but in my case device always disconnects on time after 10 seconds of connecting to the Mqtt server, then reconnects within seconds, and then disconnects after 10 seconds of reconnection. I'm using nodeMCU (https://nodemcu.readthedocs.io/en/dev-esp32/modules/mqtt/). I can't identify issue myself(whether it is related to server or device) Here my code..

local client_id,user_id,password,host_id,port="House1","temp1","temp2","198.xx.xx.xxx",18xx topics={"iot/ANUD45/HAll","iot/ADR1/KITCH","iot/ADR5/BED"} m = mqtt.Client(client_id, 0,user_id,password) m:lwt("/lwt", "offline", 0, 0) m:on("connect", function(client) print ("connection estblished") end) m:on("offline", function(client) print ("offline") do_mqtt_connect end) m:on("message", function(client, topic, data) if data ~= nil then data=string.sub(data,2,#data-1) print('mqtt',data) end end) function handle_mqtt_error(client, reason) tmr.create():alarm(10 * 1000, tmr.ALARM_SINGLE, do_mqtt_connect) end function do_mqtt_connect() m:connect(host_id, port, 0) m:subscribe(topics[3], 0, function(client_3) print("subscribe success_9") end) m:subscribe(topics[1], 0, function(client_1) print("subscribe success_1") end) m:subscribe(topics[2], 0, function(client_2) print("subscribe success_4") end) end do_mqtt_connect()

here is my error.. E (492351) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128 E (492351) MQTT_CLIENT: mqtt_process_receive: mqtt_message_receive() returned -1 W (492351) MQTT_CLIENT: Client asked to stop, but was not started offline

d0ct0rd-dalimo commented 3 years ago

I have the same problem with connection to local MQTT broker, although other clients connects properly.

The logs are

[I][mqtt_messaging.cpp:249] mqtt_event_handler(): MQTT_EVENT_DISCONNECTED
[I][mqtt_messaging.cpp:462] mqtt_event_handler(): Other event id:7
E (164519) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128
[I][mqtt_messaging.cpp:459] mqtt_event_handler(): MQTT_EVENT_ERROR
E (164521) MQTT_CLIENT: esp_mqtt_connect: mqtt_message_receive() returned -1
E (164528) MQTT_CLIENT: MQTT connect failed
[I][mqtt_messaging.cpp:249] mqtt_event_handler(): MQTT_EVENT_DISCONNECTED
[I][mqtt_messaging.cpp:462] mqtt_event_handler(): Other event id:7
E (174563) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128
[I][mqtt_messaging.cpp:459] mqtt_event_handler(): MQTT_EVENT_ERROR
E (174566) MQTT_CLIENT: esp_mqtt_connect: mqtt_message_receive() returned -1
E (174573) MQTT_CLIENT: MQTT connect failed

I tried to tweak MQTT version, change host or server address format (it's IP-address), with config, delay between connect with WiFi and connect to MQTT but it didn't make any effect. But once per 100 it can connect to MQTT. ESP-IDF version is v3.3.5-1-g85c43024c, used from ESP32-Arduino

MichaelEFlip commented 2 years ago

I had a similar behavior which was caused by a subscribe to a topic which contained invalid characters: topic=þÿÿÿp)\b>@#<\r<6>mytopic/commands/reported

Log at esp32:

[0;32mI (3699) MQTT: Other event id:7[0m
[0;32mI (3819) MQTT: MQTT_EVENT_CONNECTED[0m
[0;32mI (8839) MQTT: Handling motor info update[0m
[0;32mI (8849) MQTT: subscribing to mqtt command topic, topic=þÿÿÿp)<\b>@#<\r><6>mytopic/commands/reported[0m
[0;32mI (8859) MQTT: sent subscribe successful, msg_id=47155[0m
[0;31mE (8899) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128[0m
[0;32mI (8899) MQTT: MQTT_EVENT_ERROR[0m
[0;31mE (8899) MQTT_CLIENT: mqtt_process_receive: mqtt_message_receive() returned -1[0m
[0;32mI (8909) MQTT: MQTT_EVENT_DISCONNECTED[0m
[0;33mW (17839) MQTT_CLIENT: Publish: Losing qos0 data when client not connected[0m
[0;33mW (21839) MQTT_CLIENT: Publish: Losing qos0 data when client not connected[0m
[0;32mI (23909) MQTT: Other event id:7[0m
[0;32mI (23979) MQTT: MQTT_EVENT_CONNECTED[0m
[0;31mE (25009) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128[0m
[0;32mI (25019) MQTT: MQTT_EVENT_ERROR[0m
[0;31mE (25019) MQTT_CLIENT: mqtt_process_receive: mqtt_message_receive() returned -1[0m
[0;32mI (25029) MQTT: MQTT_EVENT_DISCONNECTED[0m
[0;33mW (25839) MQTT_CLIENT: Publish: Losing qos0 data when client not connected[0m
[0;33mW (29839) MQTT_CLIENT: Publish: Losing qos0 data when client not connected[0m
[0;33mW (33839) MQTT_CLIENT: Publish: Losing qos0 data when client not connected[0m
[0;33mW (37839) MQTT_CLIENT: Publish: Losing qos0 data when client not connected[0m
[0;32mI (40029) MQTT: Other event id:7[0m
[0;32mI (40159) MQTT: MQTT_EVENT_CONNECTED[0m

Broker was Mosquitto 2.0.14 I am not sure if the problem is the invalid topic or the timing to the CONNACK request from the server. After several connection retries the connection is working: 2022-02-14 10_30_48- To get this detail output you should set mosquitto to more verbose logging.

You could try to disable the subscribe request in the esp software to check if the situation gets better.

Ashutosh-017 commented 1 year ago

Hello I also facing same problem when I try to connect with Azure IoT hub please help me Guys.. My log messages are as follows: (14:42:20.717) [0;32mI (2081) Azure_IoT: STARTING MQTT (14:42:20.717) [0m (14:42:20.717) [0;32mI (2081) Azure_IoT: Other event id:7[0m (14:42:20.843) [0;31mE (2221) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128[0m (14:42:20.875) [0;32mI (2221) Azure_IoT: MQTT_EVENT_ERROR (14:42:20.875) [0m (14:42:20.875) [0;31mE (2231) MQTT_CLIENT: esp_mqtt_connect: mqtt_message_receive() returned -1[0m (14:42:20.875) [0;31mE (2231) MQTT_CLIENT: MQTT connect failed[0m (14:42:20.875) [0;32mI (2241) Azure_IoT: MQTT_EVENT_DISCONNECTED

Please help me Guys

shack3 commented 9 months ago

For anyone wondering, usually this tipe of errors:

E (6912) esp-tls-mbedtls: read error :-0x004C:

E (6912) transport_base: esp_tls_conn_read error, errno=Socket is not connected

E (6912) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=128

Occurs when the MQTT broker, closes the conection, meaning that maybe your code is not wrong, (certificate problems are addressed in other form).

In my case, it was that the Policy on AWS IoT Core was blocking the device, check the Policy of the Cloud you are using, or your broker related firewall and make a less strict policy (for amazon aws is arn:aws:iot:eu-west-1:XXXXXXXXXXXX:*) (WARNING: This is not the safest way of creating a policy, but maybe it helps with the testing) witch helped me figuring out what was the problem.

Hope it helps someone, it was the only post i found.