Telemetry messages do not timeout if client is disconnected

[ewertons]

Development Machine, OS, Compiler (and Other Relevant Toolchain Info)

Any.

SDK Version (Please Give Commit SHA if Manually Compiling)

LTS 01/2023

Protocol

Any.

Describe the Bug

If the iothub_client is not connected, telemetry messages added to the queue do not timeout.
Only when the client is connected and messages have been attempted to be sent at least once they timeout if sitting in the queue for too long (4 minutes?).

The expected behavior should be the same if the client ever connects or not, timing out telemetry messages if they sit in the queue for too long.

Filed on behalf of @shmulikpeled

[shmulikpeled]

Thanks for opening this. we expected OPTION_MESSAGE_TIMEOUT to be respected regardless of the client connection state.

[ewertons]

By default the message timeout at the iothub_client layer is 0, disabling the timeout of telemetry messages by the iothub_client layer queued in the waitingToSend list.
This is documented in the SDK docs.

This is still fully controllable by the user by setting OPTION_MESSAGE_TIMEOUT right after creating the iothub client handle.

So, OPTION_MESSAGE_TIMEOUT is respected regardless of the client connection state.
But it needs to be explicitly set by the user application.

My concern about changing the default telemetry timeout at the iothub_client layer is if it would break existing user applications.

[shmulikpeled]

So if I set OPTION_MESSAGE_TIMEOUT to 1 hour, can I expect the SDK to behave the same way - regardless of the client connection state?

[ewertons]

I have not tried for 1 hour, but with 40 seconds this is what I get when not connected:

Messages get put in the waitToSend queue ("Sending message X to IoTHub") at about 13:30:57
Then they are returned to the user app roughly after 40 seconds (after 13:31:28) with result IOTHUB_CLIENT_CONFIRMATION_MESSAGE_TIMEOUT.

ewertons@ewertons-lcx1:~/code/s2/azure-iot-sdk-c/cmake/iothub_client/samples/iothub_ll_telemetry_sample$ ./iothub_ll_telemetry_sample
Creating IoTHub Device handle
Sending message 1 to IoTHub
Sending message 2 to IoTHub
Sending message 3 to IoTHub
Sending message 4 to IoTHub
Sending message 5 to IoTHub
-> 13:30:57 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ewertons-iothub.azure-devices.net/ewertons-device2a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.11.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 13:30:57 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
The device client has been disconnected
Error: Time:Thu Feb 16 13:30:57 2023 File:/home/ewertons/code/s2/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2129 Connection Not Accepted: 0x5: Not Authorized
The device client has been disconnected
-> 13:30:57 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ewertons-iothub.azure-devices.net/ewertons-device2a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.11.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 13:30:57 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
The device client has been disconnected
Error: Time:Thu Feb 16 13:30:57 2023 File:/home/ewertons/code/s2/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2129 Connection Not Accepted: 0x5: Not Authorized
The device client has been disconnected
-> 13:30:58 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ewertons-iothub.azure-devices.net/ewertons-device2a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.11.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 13:30:58 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
The device client has been disconnected
Error: Time:Thu Feb 16 13:30:58 2023 File:/home/ewertons/code/s2/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2129 Connection Not Accepted: 0x5: Not Authorized
The device client has been disconnected
-> 13:31:00 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ewertons-iothub.azure-devices.net/ewertons-device2a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.11.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 13:31:00 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
The device client has been disconnected
Error: Time:Thu Feb 16 13:31:00 2023 File:/home/ewertons/code/s2/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2129 Connection Not Accepted: 0x5: Not Authorized
The device client has been disconnected
-> 13:31:04 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ewertons-iothub.azure-devices.net/ewertons-device2a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.11.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 13:31:04 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
The device client has been disconnected
Error: Time:Thu Feb 16 13:31:04 2023 File:/home/ewertons/code/s2/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2129 Connection Not Accepted: 0x5: Not Authorized
The device client has been disconnected
-> 13:31:12 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ewertons-iothub.azure-devices.net/ewertons-device2a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.11.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 13:31:12 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
The device client has been disconnected
Error: Time:Thu Feb 16 13:31:12 2023 File:/home/ewertons/code/s2/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2129 Connection Not Accepted: 0x5: Not Authorized
The device client has been disconnected
-> 13:31:28 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ewertons-iothub.azure-devices.net/ewertons-device2a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.11.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 13:31:28 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
The device client has been disconnected
Error: Time:Thu Feb 16 13:31:28 2023 File:/home/ewertons/code/s2/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2129 Connection Not Accepted: 0x5: Not Authorized
The device client has been disconnected
Confirmation callback received for message 1 with result IOTHUB_CLIENT_CONFIRMATION_MESSAGE_TIMEOUT
Confirmation callback received for message 2 with result IOTHUB_CLIENT_CONFIRMATION_MESSAGE_TIMEOUT
Confirmation callback received for message 3 with result IOTHUB_CLIENT_CONFIRMATION_MESSAGE_TIMEOUT
Confirmation callback received for message 4 with result IOTHUB_CLIENT_CONFIRMATION_MESSAGE_TIMEOUT

[ewertons]

Unfortunately, there is a different option for setting the message timeout if using AMQP protocol: "event_send_timeout_secs"
Also documented here: https://github.com/Azure/azure-iot-sdk-c/blob/main/doc/connection_and_messaging_reliability.md#current-configuration-options

And in MQTT the message timeout is hardcoded.

Tying OPTION_MESSAGE_TIMEOUT to the transports would be a breaking change. Example: customer already sets a OPTION_MESSAGE_TIMEOUT to 1 minute, but waits longer (say, 10 minutes) if the AMQP transport is trying to resend the message.

[shmulikpeled]

right. I suspect apps that use the SDK may have a bug they aren't aware of if they don't set the OPTION_MESSAGE_TIMEOUT.

Tying OPTION_MESSAGE_TIMEOUT to the transports would be a breaking change. Example: customer already sets a OPTION_MESSAGE_TIMEOUT to 1 minute, but waits longer (say, 10 minutes) if the AMQP transport is trying to resend the message.

With current behaviour, customer will get 10 minutes timeout on message before SDK discovers it's disconnected, then next messages will have 1 minute timeout - correct? I'm not sure this behaviour is usable. plus currently if customer didn't set OPTION_MESSAGE_TIMEOUT and SDK is disconnected, there is no callback called on app which can cause many issues.

wdyt of the following logic:

1. app sends a message via send event func
2. SDK queues message (as it does now if not connected)
3. if connected, SDK tries to send queued messages
4. on successful transport, notifies app, remove message from queue
5. if timeout on transport, message returns to queue
6. if message older than OPTION_MESSAGE_TIMEOUT, call app with timeout error, remove from queue

This will result in consistent behavior. set OPTION_MESSAGE_TIMEOUT to something by default - or do not queue at all if OPTION_MESSAGE_TIMEOUT not set - call app cb with error immediately if in disconnected state.