search

espressif / esp-azure

SDK to connect ESP8266 and ESP32 to Microsoft Azure IoT services
177 stars 93 forks source link

tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED. #10

Closed robert-kuramshin closed 5 years ago

robert-kuramshin commented 6 years ago

ESP IDF Version: v3.2-dev-362-g1c7a8b3

esp-azure: latest

Issue: I am working on a project that involves sending sensor information to Azure over MQTT. Messages are being sent once a minute, and device runs up to days at a time. I am using a modified version of the code found in iothub_client_sample_mqtt.c to send the messages.

Currently, after 3-4 hours of the device running I get the following error: tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED. Sometime the device locks up as well.

Otherwise the MQTT code runs well and seems to recover from loss of connectivity in my testing.

Log: I get the following log error after sending a message using IoTHubClient_LL_SendEventAsync:

Error: Time:Sat Sep 29 09:20:48 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/azure/c-utility/pal/socket_async.c Func:socket_async_is_create_complete Line:196 Socket select errset non-empty: 113

Info: socket_async_is_create_complete failure

Error: Time:Sat Sep 29 09:20:48 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:21:40 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

W (8793757) wifi: alloc eb len=24 type=3 fail, heap:432

W (8793757) wifi: m f null

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:21:51 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:21:59 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:22:15 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:22:48 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:23:53 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:26:03 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Error: Time:Sat Sep 29 09:26:21 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/azure/c-utility/pal/socket_async.c Func:socket_async_is_create_complete Line:196 Socket select errset non-empty: 113

Info: socket_async_is_create_complete failure

Error: Time:Sat Sep 29 09:30:30 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:39:23 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 09:56:56 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 10:32:42 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

Error: Time:Sat Sep 29 11:42:11 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

D (21603357) tcpip_adapter: if0 dhcpc cb [0m
D (21603357) tcpip_adapter: if0 ip unchanged [0m
Error: Time:Sat Sep 29 14:00:43 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Error: Time:Sat Sep 29 14:01:06 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/azure/c-utility/pal/socket_async.c Func:socket_async_is_create_complete Line:196 Socket select errset non-empty: 113

Info: socket_async_is_create_complete failure

Error: Time:Sat Sep 29 18:36:41 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

D (43203317) tcpip_adapter: if0 dhcpc cb [0m
D (43203317) tcpip_adapter: if0 ip unchanged [0m
D (64803527) tcpip_adapter: if0 dhcpc cb [0m
D (64803527) tcpip_adapter: if0 ip unchanged [0m
Error: Time:Sun Sep 30 03:49:39 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Error: Time:Sun Sep 30 03:50:01 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/azure/c-utility/pal/socket_async.c Func:socket_async_is_create_complete Line:196 Socket select errset non-empty: 113

Info: socket_async_is_create_complete failure

D (86403317) tcpip_adapter: if0 dhcpc cb [0m
D (86403317) tcpip_adapter: if0 ip unchanged [0m
D (108003557) tcpip_adapter: if0 dhcpc cb [0m
D (108003557) tcpip_adapter: if0 ip unchanged [0m
D (129603577) tcpip_adapter: if0 dhcpc cb [0m
D (129603577) tcpip_adapter: if0 ip unchanged [0m
Error: Time:Sun Sep 30 22:03:19 2018 File:/home/robert/esp/carealert-esp32/components/azure_iot/pal/src/tlsio_openssl_compact.c Func:tlsio_openssl_destroy Line:218 tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

Info: Hard error from SSL_connect: 5

D (151203317) tcpip_adapter: if0 dhcpc cb [0m
D (151203317) tcpip_adapter: if0 ip unchanged [0m
D (172803317) tcpip_adapter: if0 dhcpc cb [0m
D (172803317) tcpip_adapter: if0 ip unchanged [0m
D (194403337) tcpip_adapter: if0 dhcpc cb [0m
D (194403337) tcpip_adapter: if0 ip unchanged [0m
D (216003327) tcpip_adapter: if0 dhcpc cb [0m
D (216003327) tcpip_adapter: if0 ip unchanged [0m

I haven't yet created a minimal code example that runs into this issue. If it is something that would be helpful let me know.

jpagliaccio commented 5 years ago

Getting the same error with Adafruit HUZZAH32 ESP32 Feather. Did you resolve this? The minimum code example is: /home/yourhomehere/.arduino15/packages/esp32/hardware/esp32/1.0.0/libraries/AzureIoT/examples/SimpleMQTT/SimpleMQTT.ino from Microsoft. Add the Microsoft Azure liberies in the Arduino Library Manager to install. Depending on your connection and the setting for #define EVENT_TIMEOUT_MS 10000 in Esp32MQTTClient.cpp it will fail in 5 minutes. The TLS close does not seem to work.

Resultfactory commented 5 years ago

"tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED" is not a fatal error. it will close any existing connection

robert-kuramshin commented 5 years ago

@jpagliaccio sorry for the delay. In my case it ended up being caused my a memory leak. My best guess is that low memory was causing a socket allocation error (socket_async_is_create_complete failure).

This message seems to point in the same direction as well. wifi: alloc eb len=24 type=3 fail, heap:432

jpagliaccio commented 5 years ago

Robert thanks for the reply. This is whats happening while I look into the leak. I am using the ESP32, Arduino IDE, and the Microsoft demo code. Everything ruins fine but if I loose my signal or its slow to respond I get the crash below. I am able to recreate this. The code is the Azure IoT simple example in the Arduino IDE.

Below is 3 good messages, then I move my WiFi router just out of range (you can pull the antennas or press the WiFi on/off button to simulate this) and then it tries to reconnect but there is the "Operating mode must not be set while SNTP client is running"

Thanks for your help.

Send Confirmation Callback finished. {"deviceId":"Esp32Device", "messageId":31, "Temperature":48.000000, "Humidity":24.299999} Info: >>>IoTHubClient_LL_SendEventAsync accepted message for transmission to IoT Hub. Info: >>>Confirmation[30] received for message tracking id = 30 with result = IOTHUB_CLIENT_CONFIRMATION_OK

Send Confirmation Callback finished. {"deviceId":"Esp32Device", "messageId":32, "Temperature":25.000000, "Humidity":51.400002} Info: >>>IoTHubClient_LL_SendEventAsync accepted message for transmission to IoT Hub. Info: >>>Confirmation[31] received for message tracking id = 31 with result = IOTHUB_CLIENT_CONFIRMATION_OK

Send Confirmation Callback finished. {"deviceId":"Esp32Device", "messageId":33, "Temperature":15.000000, "Humidity":88.199997} Info: >>>IoTHubClient_LL_SendEventAsync accepted message for transmission to IoT Hub. Error: Time:Fri Nov 16 13:32:59 2018 File:/home/jpagliaccio/.arduino15/packages/esp32/hardware/esp32/1.0.0/libraries/AzureIoT/src/Esp32MQTTClient.cpp Func:SendEventOnce Line:316 Waiting for send confirmation, time is up 10008

Info: >>>Re-connect.

Info: >>>Confirmation[32] received for message tracking id = 32 with result = IOTHUB_CLIENT_CONFIRMATION_BECAUSE_DESTROY

Info: Initializing SNTP

assertion "Operating mode must not be set while SNTP client is running" failed: file "/Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/lwip/apps/sntp/sntp.c", line 591, function: sntp_setoperatingmode abort() was called at PC 0x400e3bbb on core 1

Backtrace: 0x4008fac0:0x3ffb1d10 0x4008fcc3:0x3ffb1d30 0x400e3bbb:0x3ffb1d50 0x4011997d:0x3ffb1d80 0x400d3bfe:0x3ffb1da0 0x400d3f5e:0x3ffb1dc0 0x400d3406:0x3ffb1de0 0x400d373a:0x3ffb1e20 0x400d38a1:0x3ffb1e40 0x400d2787:0x3ffb1e60 0x40148594:0x3ffb1fa0

Rebooting... ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:1 load:0x3fff0018,len:4 load:0x3fff001c,len:808 load:0x40078000,len:6084 load:0x40080000,len:6696 entry 0x400802e4 ESP32 Device Initializing... In Setup Microsoft Demo Code - WiFi Connecting... ......WiFi connected IP address: 192.168.0.145

IoT Hub Info: Initializing SNTP

Info: SNTP initialization complete

Info: IoT Hub SDK for C, version 1.1.23

Info: >>>Connection status: connected

{"deviceId":"Esp32Device", "messageId":1, "Temperature":29.000000, "Humidity":46.599998} Info: >>>IoTHubClient_LL_SendEventAsync accepted message for transmission to IoT Hub. Info: >>>Confirmation[0] received for message tracking id = 0 with result = IOTHUB_CLIENT_CONFIRMATION_OK

Send Confirmation Callback finished. { "desired": { "$version": 1 }, "reported": { "$version": 1 } } {"deviceId":"Esp32Device", "messageId":2, "Temperature":22.000000, "Humidity":41.900002} Info: >>>IoTHubClient_LL_SendEventAsync accepted message for transmission to IoT Hub. Info: >>>Confirmation[1] received for message tracking id = 1 with result = IOTHUB_CLIENT_CONFIRMATION_OK

Send Confirmation Callback finished. {"deviceId":"Esp32Device", "messageId":3, "Temperature":28.000000, "Humidity":33.000000} Info: >>>IoTHubClient_LL_SendEventAsync accepted message for transmission to IoT Hub. Info: >>>Confirmation[2] received for message tracking id = 2 with result = IOTHUB_CLIENT_CONFIRMATION_OK

Send Confirmation Callback finished. {"deviceId":"Esp32Device", "messageId":4, "Temperature":7.000000, "Humidity":15.300000} Info: >>>IoTHubClient_LL_SendEventAsync accepted message for transmission to IoT Hub. Info: >>>Confirmation[3] received for message tracking id = 3 with result = IOTHUB_CLIENT_CONFIRMATION_OK

Send Confirmation Callback finished.