jebrando
commented
5 years ago @brennantj I'm would like to make sure we are on the same page as far as the issue you're seeing. I'll describe what I did to test this:
I took my test file which is a slightly modified iothub_ll_telemetry_sample (included below) that send 1 message every 2 seconds. I then changed the sas token lifetime to be 2 mins with the line below:
int lifetime = 2 * 60;
IoTHubDeviceClient_LL_SetOption(device_ll_handle, OPTION_SAS_TOKEN_LIFETIME, &lifetime);After ~1:24 the device sends a DISCONNECT packet to the IoTHub server and then sends a CONNECT packet to reconnect:
Confirmation callback received for message 32 with result IOTHUB_CLIENT_CONFIRMATION_OK
-> 08:17:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/sample_key_dev/messages/events/ | PACKET_ID: 35 | PAYLOAD_LEN: 20
<- 08:17:00 PUBACK | PACKET_ID: 35
Confirmation callback received for message 33 with result IOTHUB_CLIENT_CONFIRMATION_OK
-> 08:17:01 DISCONNECT
The device client has been disconnected
-> 08:17:01 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: iot-test-sdk.azure-devices.net/sample_key_dev/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.10%20(native%3b%20WindowsProduct%3a0x00000004%206.2%3b%20x32) | PWD: XXXX | CLEAN: 0
<- 08:17:01 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
The device client is connected to iothub
-> 08:17:01 SUBSCRIBE | PACKET_ID: 36 | TOPIC_NAME: devices/sample_key_dev/messages/devicebound/# | QOS: 1I'm not sure where I'm misunderstanding the issue. Can you run my sample and edit it so I can get a repro of your issue.
Thanks, Jelani
yzhong94
TomBrennan-Eaton
rafilho
CIPop
az-iot-builder-01
OS and version used: Linux, kernel version 4.14.51
SDK version used: release_2018_10_03
Description of the issue:
I setup our code to let Azure try to automatically reconnect when we hit the SAS Token expiration, and Azure failed to reconnect on its own. People we discussed this with at MS believed that this should work; that also seems to be what is expected in resolved issue 613. Also, looking into the Azure code, the path to the error condition doesn’t seem possible, but there it is.
I looked into the Azure code to see if there was some option we could set that would prevent this problem and assist the retry operation, but I didn't find anything. What is most curious about the first Azure message (below in the log) is, that looking at the Azure code, it can't happen: OptionHandler_FeedOptions() is called from (I'm pretty sure): https://github.com/Azure/azure-iot-sdk-c/blob/master/iothub_client/src/iothubtransport_mqtt_common.c#L1986 which is line 1938 in release_2018_10_03. The debug output says the second argument is null, but that is checked 10 lines earlier, so shouldn't ever happen.
As a comment: searching for OptionHandler_FeedOptions in the Azure code turns up a pile of hits in the AMQP areas, and only one in the MQTT area. I don't know if that means the retry mechanism is underdeveloped for MQTT.
Code sample exhibiting the issue:
I arranged our code to set a much shorter SAS Token Lifetime to speed up the test; I set "sas_token_lifetime" to 304 seconds, so it would timeout in about 243 seconds. Then I had our application code not do anything when the ConnectionStatusCallback() gave us reasonCode = IOTHUB_CLIENT_CONNECTION_EXPIRED_SAS_TOKEN, where our code had been reacting to this by disconnecting and reconnecting.
Console log of the issue:
Then I ran the application, connected to Azure (through our corporate proxy) and waited for the refresh. When it occurred, our code didn't react but kept trying to send messages. However, it is clear from the Azure low-level messages that it was failing to do the reconnect on its own; here's the mixed debug output, with the Azure messages highlighted:
Debug: Published 1 IOT_DATA_CHANNEL_REALTIMES_ITEM updates for device 16 Info: handleD2CMessageConfirmationCallback: Message Confirmation Received, Seq: 51
Info: handleConnectionStatusCallback: Connection Status Received, Result: 1, Reason: 0 Info: handleConnectionStatusCallback: Letting Azure reconnect, after SAS Token epxiration *Error: Time:Fri Nov 9 15:33:25 2018 File:../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:225 invalid arguments OPTIONHANDLER_HANDLE handle=0xb44153b0, void destinationHandle=(nil) Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/xio.c Func:xio_setoption Line:187 unable to OptionHandler_FeedOptions Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:238 failure while trying to _SetOption Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/xio.c Func:xio_setoption Line:187 unable to OptionHandler_FeedOptions Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:238 failure while trying to _SetOption Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/adapters/tlsio_openssl.c Func:tlsio_openssl_setoption Line:1605 failed feeding options to underlying I/O instance Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:238 failure while trying to _SetOption Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/xio.c Func:xio_setoption Line:187 unable to OptionHandler_FeedOptions Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:238 failure while trying to _SetOption Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/uws_client.c Func:uws_client_set_option Line:2063 OptionHandler_FeedOptions failed Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:238 failure while trying to _SetOption Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/wsio.c Func:wsio_setoption Line:676 unable to OptionHandler_FeedOptions Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:238 failure while trying to _SetOption Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/xio.c Func:xio_setoption Line:187 unable to OptionHandler_FeedOptions Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:238 failure while trying to _SetOption Error: Time:Fri Nov 9 15:33:25 2018 File:.../azure-iot-sdk-c-release_2018_10_03/iothub_client/src/iothubtransport_mqtt_common.c Func:GetTransportProviderIfNecessary Line:1940 Failed feeding existing options to new TLS instance.**
Info: Update to IoT Status: IOT_CONNECTING, Error: IOT_NO_ERROR, Reason:
Debug: list_create: Creating connection list. Debug: setMessageProperties: Setting data message property 'a' = Realtimes Debug: setMessageProperties: Setting message property 'e' = json Debug: setMessageProperties: Setting message property 'p' = f4f802f8-64b4-50fe-a183-713e3aa73f5a Debug: iot_send: Message Sent, Seq: 52 Serialized Message: {"realtimes":[{"c":"596","t":1541795606,"t_ms":786,"v":"64.0781479"}]} Debug: CIoTDeviceStats::update_counter(): Message type = 1, size = 1024, 4k messages = 1 Debug: Published 1 IOT_DATA_CHANNEL_REALTIMES_ITEM updates for device 16
*Error: Time:Fri Nov 9 15:33:30 2018 File:.../azure-iot-sdk-c-release_2018_10_03/c-utility/src/optionhandler.c Func:OptionHandler_FeedOptions Line:225 invalid arguments OPTIONHANDLER_HANDLE handle=0xb4413308, void destinationHandle=(nil)** ... and so on, without recovery