search

Azure / azure-iot-sdk-c

A C99 SDK for connecting devices to Microsoft Azure IoT services
https://azure.github.io/azure-iot-sdk-c
Other
588 stars 737 forks source link

Crash after network disconnection (AMQP/AMQP_WS) #251

Closed ghost closed 7 years ago

ghost commented 7 years ago

Description of the issue:

After a successfull connection the network is disconnected. A few minutes later the application crashes.

Code sample exhibiting the issue:

Take the iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509.c and:

  1. adapt connection string, certificate and key
  2. change #define MESSAGE_COUNT 5 to #define MESSAGE_COUNT 1000
  3. change the ThreadAPI_Sleep(1; in the while loop to ThreadAPI_Sleep(1000)
  4. start the program, wait until connection is established and messages are ack'ed
  5. disconnect network
  6. wait a few minutes

Console log of the issue:

start the application:

Starting the IoTHub client sample x509...
Info: IoT Hub SDK for C, version 1.1.25
Info: Retry policy set (5, timeout = 0)
IoTHubClient_LL_SetMessageCallback...successful.
IoTHubClient_LL_SendEventAsync accepted message [0] for transmission to IoT Hub.
IoTHubClient_LL_SendEventAsync accepted message [1] for transmission to IoT Hub.
IoTHubClient_LL_SendEventAsync accepted message [2] for transmission to IoT Hub.
IoTHubClient_LL_SendEventAsync accepted message [3] for transmission to IoT Hub.
-> Header (AMQP 0.1.0.0)
IoTHubClient_LL_SendEventAsync accepted message [4] for transmission to IoT Hub.
IoTHubClient_LL_SendEventAsync accepted message [5] for transmission to IoT Hub.
IoTHubClient_LL_SendEventAsync accepted message [6] for transmission to IoT Hub.
IoTHubClient_LL_SendEventAsync accepted message [7] for transmission to IoT Hub.
<- Header (AMQP 0.1.0.0)
-> [OPEN]* {399bb251-9e01-4271-8edd-2d3f4df96450,xxx.azure-devices.net,4294967295,65535,240000}
IoTHubClient_LL_SendEventAsync accepted message [8] for transmission to IoT Hub.
<- [OPEN]* {DeviceGateway_106f0bc99aa54ca396008b82caff5e72,10.0.8.25,65536,8191,240000,NULL,NULL,NULL,NULL,NULL}
-> [BEGIN]* {NULL,0,4294967295,100,4294967295}
IoTHubClient_LL_SendEventAsync accepted message [9] for transmission to IoT Hub.
<- [BEGIN]* {0,1,5000,4294967295,262143,NULL,NULL,NULL}
-> [ATTACH]* {link-snd-xxx-b243aa81-2dd7-4c67-b62b-76a382e5a243,0,false,0,0,* {link-snd-xxx-b243aa81-2dd7-4c67-b62b-76a382e5a243-source},* {amqps://xxx.azure-devices.net/devices/xxx/messages/events},NULL,NULL,0,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.25 (Linux; x86_64)]}}
-> [ATTACH]* {link-snd-xxx-6bcb4397-3470-46a2-a0a9-b0c91c66d064,1,false,0,0,* {link-snd-xxx-6bcb4397-3470-46a2-a0a9-b0c91c66d064-source},* {amqps://xxx.azure-devices.net/devices/xxx/twin},NULL,NULL,0,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.25 (Linux; x86_64)],[com.microsoft:channel-correlation-id:twin:ce1067fe-dba4-430b-8655-f30aee17010a],[com.microsoft:api-version:2016-11-14]}}
IoTHubClient_LL_SendEventAsync accepted message [10] for transmission to IoT Hub.
<- [ATTACH]* {link-snd-xxx-b243aa81-2dd7-4c67-b62b-76a382e5a243,0,true,0,NULL,* {link-snd-xxx-b243aa81-2dd7-4c67-b62b-76a382e5a243-source,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {amqps://xxx.azure-devices.net/devices/xxx/messages/events,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.25 (Linux; x86_64)]}}
<- [FLOW]* {0,5000,1,4294967295,0,0,1000,0,NULL,false,NULL}
<- [ATTACH]* {link-snd-xxx-6bcb4397-3470-46a2-a0a9-b0c91c66d064,1,true,1,0,* {link-snd-xxx-6bcb4397-3470-46a2-a0a9-b0c91c66d064-source,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {amqps://xxx.azure-devices.net/devices/xxx/twin,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.25 (Linux; x86_64)],[com.microsoft:channel-correlation-id:twin:ce1067fe-dba4-430b-8655-f30aee17010a],[com.microsoft:api-version:2016-11-14]}}
<- [FLOW]* {0,5000,1,4294967295,1,0,1000,0,NULL,false,NULL}
IoTHubClient_LL_SendEventAsync accepted message [11] for transmission to IoT Hub.
-> [ATTACH]* {link-rcv-xxx-573fd158-9364-4c33-b151-5e4fee4d947b,2,true,0,0,* {amqps://xxx.azure-devices.net/devices/xxx/messages/devicebound},* {link-rcv-xxx-573fd158-9364-4c33-b151-5e4fee4d947b-target},NULL,NULL,NULL,65536,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.25 (Linux; x86_64)]}}
-> [ATTACH]* {link-rcv-xxx-4f5f439c-f7d0-431c-8f11-3053c813ff57,3,true,0,0,* {amqps://xxx.azure-devices.net/devices/xxx/twin},* {link-rcv-xxx-4f5f439c-f7d0-431c-8f11-3053c813ff57-target},NULL,NULL,NULL,18446744073709551615,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.25 (Linux; x86_64)],[com.microsoft:channel-correlation-id:twin:ce1067fe-dba4-430b-8655-f30aee17010a],[com.microsoft:api-version:2016-11-14]}}
IoTHubClient_LL_SendEventAsync accepted message [12] for transmission to IoT Hub.
<- [ATTACH]* {link-rcv-xxx-573fd158-9364-4c33-b151-5e4fee4d947b,2,false,NULL,1,* {amqps://xxx.azure-devices.net/devices/xxx/messages/devicebound,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {link-rcv-xxx-573fd158-9364-4c33-b151-5e4fee4d947b-target,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,65536,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.25 (Linux; x86_64)]}}
-> [FLOW]* {1,4294967295,0,100,2,0,10000}
<- [ATTACH]* {link-rcv-xxx-4f5f439c-f7d0-431c-8f11-3053c813ff57,3,false,1,0,* {amqps://xxx.azure-devices.net/devices/xxx/twin,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {link-rcv-xxx-4f5f439c-f7d0-431c-8f11-3053c813ff57-target,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,1048576,NULL,NULL,{[com.microsoft:client-version:iothubclient/1.1.25 (Linux; x86_64)],[com.microsoft:channel-correlation-id:twin:ce1067fe-dba4-430b-8655-f30aee17010a],[com.microsoft:api-version:2016-11-14]}}
-> [FLOW]* {1,4294967295,0,100,3,0,10000}
IoTHubClient_LL_SendEventAsync accepted message [13] for transmission to IoT Hub.
IoTHubClient_LL_SendEventAsync accepted message [14] for transmission to IoT Hub.
-> [TRANSFER]* {0,0,<01 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [15] for transmission to IoT Hub.
-> [TRANSFER]* {0,1,<02 00 00 00>,2147563264,false,false}
<- [DISPOSITION]* {true,0,NULL,true,* {},NULL}
Confirmation[0] received for message tracking id = 0 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[1] received for message tracking id = 1 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[2] received for message tracking id = 2 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[3] received for message tracking id = 3 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[4] received for message tracking id = 4 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[5] received for message tracking id = 5 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[6] received for message tracking id = 6 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[7] received for message tracking id = 7 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[8] received for message tracking id = 8 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[9] received for message tracking id = 9 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[10] received for message tracking id = 10 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[11] received for message tracking id = 11 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[12] received for message tracking id = 12 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[13] received for message tracking id = 13 with result = IOTHUB_CLIENT_CONFIRMATION_OK
Confirmation[14] received for message tracking id = 14 with result = IOTHUB_CLIENT_CONFIRMATION_OK
IoTHubClient_LL_SendEventAsync accepted message [16] for transmission to IoT Hub.
-> [TRANSFER]* {0,2,<03 00 00 00>,2147563264,false,false}
<- [DISPOSITION]* {true,1,NULL,true,* {},NULL}
Confirmation[15] received for message tracking id = 15 with result = IOTHUB_CLIENT_CONFIRMATION_OK
IoTHubClient_LL_SendEventAsync accepted message [17] for transmission to IoT Hub.
-> [TRANSFER]* {0,3,<04 00 00 00>,2147563264,false,false}
<- [DISPOSITION]* {true,2,NULL,true,* {},NULL}
Confirmation[16] received for message tracking id = 16 with result = IOTHUB_CLIENT_CONFIRMATION_OK
IoTHubClient_LL_SendEventAsync accepted message [18] for transmission to IoT Hub.
-> [TRANSFER]* {0,4,<05 00 00 00>,2147563264,false,false}
<- [DISPOSITION]* {true,3,NULL,true,* {},NULL}
Confirmation[17] received for message tracking id = 17 with result = IOTHUB_CLIENT_CONFIRMATION_OK

disconnect the network:

IoTHubClient_LL_SendEventAsync accepted message [19] for transmission to IoT Hub.
-> [TRANSFER]* {0,5,<06 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [20] for transmission to IoT Hub.
-> [TRANSFER]* {0,6,<07 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [21] for transmission to IoT Hub.
-> [TRANSFER]* {0,7,<08 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [22] for transmission to IoT Hub.
-> [TRANSFER]* {0,8,<09 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [23] for transmission to IoT Hub.
-> [TRANSFER]* {0,9,<0A 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [24] for transmission to IoT Hub.
-> [TRANSFER]* {0,10,<0B 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [25] for transmission to IoT Hub.
-> [TRANSFER]* {0,11,<0C 00 00 00>,2147563264,false,false}

...

IoTHubClient_LL_SendEventAsync accepted message [255] for transmission to IoT Hub.
-> [TRANSFER]* {0,241,<F2 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [256] for transmission to IoT Hub.
-> [TRANSFER]* {0,242,<F3 00 00 00>,2147563264,false,false}
IoTHubClient_LL_SendEventAsync accepted message [257] for transmission to IoT Hub.
-> [TRANSFER]* {0,243,<F4 00 00 00>,2147563264,false,false}
-> [CLOSE]* {* {amqp:internal-error,No frame received for the idle timeout}}
IoTHubClient_LL_SendEventAsync accepted message [258] for transmission to IoT Hub.
Error: Time:Tue Oct 10 07:24:27 2017 File:xxx/azure-iot-sdk-c/uamqp/src/connection.c Func:connection_encode_frame Line:1832 Connection not open
Error: Time:Tue Oct 10 07:24:27 2017 File:xxx/azure-iot-sdk-c/uamqp/src/message_sender.c Func:send_one_message Line:522 Error in link transfer
Error: Time:Tue Oct 10 07:24:27 2017 File:xxx/azure-iot-sdk-c/uamqp/src/message_sender.c Func:messagesender_send_async Line:898 Error sending message
*** Error in `./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509': double free or corruption (fasttop): 0x0000000001241cb0 ***
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7fe7b16ed7e5]
/lib/x86_64-linux-gnu/libc.so.6(+0x8037a)[0x7fe7b16f637a]
/lib/x86_64-linux-gnu/libc.so.6(cfree+0x4c)[0x7fe7b16fa53c]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509(async_operation_destroy+0x62)[0x476b48]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509(messagesender_send_async+0x38f)[0x46c888]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509[0x429e2a]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509[0x42a4bd]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509(telemetry_messenger_do_work+0x1ae)[0x42b99c]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509(device_do_work+0x9a2)[0x42357c]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509[0x41d92b]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509(IoTHubTransport_AMQP_Common_DoWork+0x294)[0x41e85e]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509[0x41b799]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509(IoTHubClient_LL_DoWork+0x154)[0x4187a1]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509(main+0x43e)[0x4136c3]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fe7b1696830]
./iothub_client/samples/iothub_client_sample_x509/iothub_client_sample_x509(_start+0x29)[0x412f79]
ewertons commented 7 years ago

Hi @davidbuechi , thanks for reporting the issue.

We will verify the scenario and reply back briefly.

ewertons commented 7 years ago

We were able to repro the issue. An update will be sent soon once we root-cause and correct the problem.

As a note, the issue does not repro at this point using SAS authentication, only x509.

tameraw commented 7 years ago

Linking to #184

ewertons commented 7 years ago

This issue was root-caused and the fix is being tested. We will make it available on the master branch soon.

ewertons commented 7 years ago

Hi @davidbuechi , a fix was just checked in for this issue, please verify if you have a chance and let us know.

Thanks, Azure IoT Team.

ewertons commented 7 years ago

Relates to commit: https://github.com/Azure/azure-uamqp-c/commit/bb25057aeb5652e58467f90ed16cba0f7385aaa3

ghost commented 7 years ago

I've done some tests with bac8131fd232c7bbc7ac4243d6b2860c9668d6c6. It does not crash anymore. However, it also does not always re-establish the connection, see issue #274

ewertons commented 7 years ago

Hi @davidbuechi , since this is a new issue, it would have been better to open a new separate one. That helps make it more visible to all customers, and allows us to close on the previous one.

We will verify the issue above and reply back soon.

ewertons commented 7 years ago

@davidbuechi , in your application did you explicitly set the IoTHubClient to use IMMEDIATE retry policy? Similar to the call bellow?

IoTHubClient_SetRetryPolicy(iothubClientHandle, IOTHUB_CLIENT_RETRY_IMMEDIATE, 600);

ewertons commented 7 years ago

Thanks @davidbuechi , we will follow up on the other issue.

Closing this one. Thanks.