tlsio_openssl_destroy called while not in TLSIO_STATE_CLOSED.

[robert-kuramshin]

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]

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]

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

[robert-kuramshin]

@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]

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.