dllama commented 6 years ago

Environment

Windows 10 Python 3.6 azure-iothub-device-client==1.4.3

Description of the issue:

We keep a local log of telemetry sent to IoT Hub and would like to flag and capture an error if transmission to IoT Hub fail. There is no sync method for sending data, so we are reliant on the callback, but the send_confirmation_callback is not triggered on failures. How can we capture a message status on transmission?

Code sample exhibiting the issue:

The simple sample can be used to reproduce: https://github.com/Azure/azure-iot-sdk-python/blob/master/device/samples/iothub_client_simple_sample.py

Console log of the issue:

Manually causing a connection error result in the below underlying errors, but the callback is never invoked even when setting a timeout.

IoT: testing connection...
IoT: sending startup message...
Error: Time:Thu Oct 11 14:52:25 2018 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\socketio_win32.c Func:socketio_open Line:297 Failure: getaddrinfo failure 11002.
Error: Time:Thu Oct 11 14:52:25 2018 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\tlsio_schannel.c Func:tlsio_schannel_open Line:1165 xio_open failed
Error: Time:Thu Oct 11 14:52:25 2018 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\umqtt\src\mqtt_client.c Func:mqtt_client_connect Line:1000 Error: io_open failed
Error: Time:Thu Oct 11 14:52:25 2018 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:2122 failure connecting to address <>

pierreca commented 6 years ago

definitely should timeout - how do you "manually cause a connection error"?

LTsLlama commented 6 years ago

Hi @pierreca, I tried three methods and they all result in the same issue, the send_confirmation_callback is never invoked on an error:

Turn off WiFi on test machine causing connection failure
Change deviceId to be invalid causing authentication error
Change IoT Hub endpoint to be incorrect causing server unavailable error

The C# SDK behaves the same, except if I set Client.OperationTimeoutInMilliseconds = 1000; Then I get: Intentional shutdown: Operation timeout expired.

Here is the logs if I leave it for a long time, 5 minutes, with the WiFi turned off. Message timeout is set to 1000: IoT: testing connection... IoT: sending startup message... Error: Time:Thu Oct 18 09:36:40 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:297 Failure: getaddrinfo failure 11001. Error: Time:Thu Oct 18 09:36:40 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1165 xio_open failed Error: Time:Thu Oct 18 09:36:40 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1000 Error: io_open failed Error: Time:Thu Oct 18 09:36:40 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2122 failure connecting to address XXXX.azure-devices.net. Error: Time:Thu Oct 18 09:36:41 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:297 Failure: getaddrinfo failure 11001. Error: Time:Thu Oct 18 09:36:41 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1165 xio_open failed Error: Time:Thu Oct 18 09:36:41 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1000 Error: io_open failed Error: Time:Thu Oct 18 09:36:41 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2122 failure connecting to address XXXX.azure-devices.net. Error: Time:Thu Oct 18 09:36:43 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:297 Failure: getaddrinfo failure 11001. Error: Time:Thu Oct 18 09:36:43 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1165 xio_open failed Error: Time:Thu Oct 18 09:36:43 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1000 Error: io_open failed Error: Time:Thu Oct 18 09:36:43 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2122 failure connecting to address XXXX.azure-devices.net. Error: Time:Thu Oct 18 09:36:47 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:297 Failure: getaddrinfo failure 11001. Error: Time:Thu Oct 18 09:36:47 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1165 xio_open failed Error: Time:Thu Oct 18 09:36:47 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1000 Error: io_open failed Error: Time:Thu Oct 18 09:36:47 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2122 failure connecting to address XXXX.azure-devices.net. Error: Time:Thu Oct 18 09:36:55 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:297 Failure: getaddrinfo failure 11001. Error: Time:Thu Oct 18 09:36:55 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1165 xio_open failed Error: Time:Thu Oct 18 09:36:55 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1000 Error: io_open failed Error: Time:Thu Oct 18 09:36:55 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2122 failure connecting to address XXXX.azure-devices.net. Error: Time:Thu Oct 18 09:37:11 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:297 Failure: getaddrinfo failure 11001. Error: Time:Thu Oct 18 09:37:11 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1165 xio_open failed Error: Time:Thu Oct 18 09:37:11 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1000 Error: io_open failed Error: Time:Thu Oct 18 09:37:11 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2122 failure connecting to address XXXX.azure-devices.net. Error: Time:Thu Oct 18 09:37:43 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:297 Failure: getaddrinfo failure 11001. Error: Time:Thu Oct 18 09:37:43 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1165 xio_open failed Error: Time:Thu Oct 18 09:37:43 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1000 Error: io_open failed Error: Time:Thu Oct 18 09:37:43 2018 File:c:\release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2122 failure connecting to address XXXX.azure-devices.net.

pierreca commented 6 years ago

@LTsLlama FYI I've been tracking this with the C SDK team (this version of the Python SDK wraps over the C SDK) and I was able to reproduce the issue (simply by disabling the network adapter).

At least what I can tell is that if the connection comes back the SDK sends the messages - so there is no message loss as long as the process is running - it's just queuing messages and not timing them out. Could be a bug, a missing feature, or a by design thing from the C team. I'll keep you posted.

pierreca commented 6 years ago

@jspaith thanks for the follow up! @dllama as soon as the C SDK has a fix we'll update our dependency and republish packages.

pierreca commented 5 years ago

This was fixed in November and the Python SDK has been released since, so this is fixed in the Python SDK as well (since v1.4.5, current version is 1.4.6)

Thanks @jspaith and @jebrando for the help!

az-iot-builder-01 commented 5 years ago

@dllama, @LTsLlama, thank you for your contribution to our open-sourced project! Please help us improve by filling out this 2-minute customer satisfaction survey

LTsLlama commented 5 years ago

@pierreca I just updated to v 1.4.6 of azure-iothub-device-client, but still getting the same issue. I am setting a message timeout, but the callback is never called. Is there anything specific that needs to be set.

pierreca commented 5 years ago

@dllama ok... reopening the issue then. can you share:

the simplest piece of code that reproduces the problem
console logs
how you simulate loss of connectivity?

I know i've asked all this already, just trying to see if anything is different by doing exactly what you do. if nothing changed, just let me know that nothing changed please :)

dllama commented 5 years ago

@pierreca, as requested:

Code to reproduce problem:


from datetime import datetime
import time
from iothub_client import IoTHubClient, IoTHubTransportProvider, IoTHubMessage

PROTOCOL = IoTHubTransportProvider.MQTT CONNECTION_STRING = "HostName=;DeviceId=;SharedAccessKey=" MESSAGE_TIMEOUT = 1000

Initialize IoT Hub client

client = IoTHubClient(CONNECTION_STRING, PROTOCOL)

set the time until a message times out

client.set_option("messageTimeout", MESSAGE_TIMEOUT)

def send_message(msg): try: print("Sending message...")

    # Encode message 
    message = IoTHubMessage(bytearray(msg, 'utf8'))

    # Send message
    client.send_event_async(message, send_confirmation_callback, None)
except(ex):
    print("Sending message failed:", str(ex))
pass

def send_confirmation_callback(message, result, user_context): print("Message confirmation = %s" % (result)) pass

if name == 'main': send_message("test")

while True:
    time.sleep(1)

- Console logs:

Sending message... Error: Time:Thu Jan 31 10:48:46 2019 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:mqtt_operation_complete_callback Line:1617 Connection Not Accepted: 0x5: Not Authorized Error: Time:Thu Jan 31 10:48:46 2019 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:mqtt_operation_complete_callback Line:1617 Connection Not Accepted: 0x5: Not Authorized Error: Time:Thu Jan 31 10:48:48 2019 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:mqtt_operation_complete_callback Line:1617 Connection Not Accepted: 0x5: Not Authorized Error: Time:Thu Jan 31 10:48:52 2019 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:mqtt_operation_complete_callback Line:1617 Connection Not Accepted: 0x5: Not Authorized Error: Time:Thu Jan 31 10:49:00 2019 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:mqtt_operation_complete_callback Line:1617 Connection Not Accepted: 0x5: Not Authorized Error: Time:Thu Jan 31 10:49:16 2019 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:mqtt_operation_complete_callback Line:1617 Connection Not Accepted: 0x5: Not Authorized Error: Time:Thu Jan 31 10:49:48 2019 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:mqtt_operation_complete_callback Line:1617 Connection Not Accepted: 0x5: Not Authorized Error: Time:Thu Jan 31 10:50:54 2019 File:C:\Release\iot-sdks-internals\release\python\automation\aziotsdk_pytools\src\c\iothub_client\src\iothubtransport_mqtt_common.c Func:mqtt_operation_complete_callback Line:1617 Connection Not Accepted: 0x5: Not Authorized


- I tried 3 methods:
1. Authorization error with incorrect device id / key: Connection Not Accepted: 0x5: Not Authorized
2. Disconnected network: Error: io_open failed
3. Server unavailable with incorrect host: Error: io_open failed

pierreca commented 5 years ago

Thanks a lot! very helpful!

ping @jspaith @jebrando for help on the C side.

jebrando commented 4 years ago

With the Python v2 reaching General Availability we are recommending users move away from the v1 SDK. We will be closing the v1 SDK issues whose features are covered by the v2 release. Feel free to open an new issue if you find an issue with the v2 SDK. Thank you for your patronage

Azure / azure-iot-sdk-python

Device to hub send_confirmation_callback on error not triggered #216

Environment

Description of the issue:

Code sample exhibiting the issue:

Console log of the issue:

Initialize IoT Hub client

set the time until a message times out