search

Azure / azure-iot-sdk-python

A Python SDK for connecting devices to Microsoft Azure IoT services
MIT License
417 stars 374 forks source link

create_from_edge_environment does not send messages to IoT Hub #1009

Closed MrVhek closed 2 years ago

MrVhek commented 2 years ago

Hello, I've been facing a weird issue using: iotedge 1.2.10 edgeAgent/edgeHub 1.2.10.55800403 azure-iot-device 2.11.0

When I create the client module using create_from_edge_environment function within my IoT Edge Module, the module is able to correctly push and pull twin, but any message sent is never received on the hub. If I use the from_connection_string and use a connection string within the same Docker, it works... This is really strange, here some information I got from logs:

2022-06-08 09:13:18 azure.iot.device.common.mqtt_transport _create_mqtt_client 149 [INFO]: Creating client for connecting using MQTT over TCP
2022-06-08 09:13:18 azure.iot.device.common.http_transport request 108 [INFO]: sending https POST request to devices/Gateway-1200723-01004/files .
2022-06-08 09:13:19 azure.iot.device.iothub.aio.async_clients get_storage_info_for_blob 572 [INFO]: Successfully retrieved storage_info
2022-06-08 09:13:20 azure.iot.device.common.http_transport request 108 [INFO]: sending https POST request to devices/Gateway-1200723-01004/files/notifications .
2022-06-08 09:13:20 azure.iot.device.iothub.aio.async_clients notify_blob_upload_status 598 [INFO]: Successfully notified blob upload status
2022-06-08 09:13:20 azure.iot.device.iothub.aio.async_clients send_message 349 [INFO]: Sending message to Hub...
2022-06-08 09:13:20 azure.iot.device.common.mqtt_transport publish 528 [INFO]: publishing on devices/Gateway-1200723-01004/modules/GWApp/messages/events/
2022-06-08 09:13:20 azure.iot.device.common.mqtt_transport on_publish 243 [INFO]: payload published for 8
2022-06-08 09:13:20 azure.iot.device.iothub.aio.async_clients send_message 356 [INFO]: Successfully sent message to Hub
Jun 08 09:13:05 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:05Z [INFO] - [mgmt] - - - [2022-06-08 09:13:05.748824404 UTC] "GET /modules?api-version=2021-12-07 HTTP/1.1" 200 OK 1952 "-" "-" auth_id(-)
Jun 08 09:13:10 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:10Z [INFO] - [mgmt] - - - [2022-06-08 09:13:10.787328141 UTC] "GET /modules?api-version=2021-12-07 HTTP/1.1" 200 OK 1952 "-" "-" auth_id(-)
Jun 08 09:13:15 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:15Z [INFO] - [mgmt] - - - [2022-06-08 09:13:15.820943495 UTC] "GET /modules?api-version=2021-12-07 HTTP/1.1" 200 OK 1952 "-" "-" auth_id(-)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (74 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-length": "74", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 377 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (2599 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-length": "2599", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 2286 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:20Z [INFO] - [work] - - - [2022-06-08 09:13:20.484697762 UTC] "POST /modules/%24edgeHub/genid/637800092105391013/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 2176 "-" "-" auth_id(-)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (74 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-length": "74", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 377 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (2574 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-length": "2574", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 2311 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:20Z [INFO] - [work] - - - [2022-06-08 09:13:20.564417345 UTC] "POST /modules/%24edgeHub/genid/637800092105391013/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 2201 "-" "-" auth_id(-)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (74 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-length": "74", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 377 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (2599 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-length": "2599", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 2286 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:20Z [INFO] - [work] - - - [2022-06-08 09:13:20.640107437 UTC] "POST /modules/%24edgeHub/genid/637800092105391013/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 2176 "-" "-" auth_id(-)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (74 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-length": "74", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 377 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (3614 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-length": "3614", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 3351 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:20Z [INFO] - [work] - - - [2022-06-08 09:13:20.717824087 UTC] "POST /modules/%24edgeHub/genid/637800092105391013/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 3241 "-" "-" auth_id(-)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (74 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-length": "74", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 377 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (3639 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-length": "3639", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 3326 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:20Z [INFO] - [work] - - - [2022-06-08 09:13:20.806012386 UTC] "POST /modules/%24edgeHub/genid/637800092105391013/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 3216 "-" "-" auth_id(-)
Jun 08 09:13:20 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:20Z [INFO] - [mgmt] - - - [2022-06-08 09:13:20.855975590 UTC] "GET /modules?api-version=2021-12-07 HTTP/1.1" 200 OK 1952 "-" "-" auth_id(-)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (74 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-length": "74", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 377 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (3639 bytes)
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-length": "3639", "content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::io] flushed 3326 bytes
Jun 08 09:13:20 iot-gate-imx8 aziot-keyd[21666]: 2022-06-08T09:13:20Z [DBUG] - [hyper::proto::h1::conn] read eof
Jun 08 09:13:20 iot-gate-imx8 aziot-edged[21652]: 2022-06-08T09:13:20Z [INFO] - [work] - - - [2022-06-08 09:13:20.879883540 UTC] "POST /modules/%24edgeHub/genid/637800092105391013/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 3216 "-" "-" auth_id(-)

As you can see, no message is received on the IoT Hub... I normally have a function app that will use the fallback route to receive messages sent. image

Any way to investiguate it further on IoT Hub side ? Or some additional logs to investigate on python side ?

Thanks

anthonyvercolano commented 2 years ago

@MrVhek have u raised this issue in the Edge repo?

anthonyvercolano commented 2 years ago

To get more debug logs add:

import logging logging.basicConfig(level=logging.DEBUG)

At the beginning of your application.

MrVhek commented 2 years ago

@MrVhek have u raised this issue in the Edge repo?

Not yet, not sure if this can be related to your SDK or to Azure IoT Edge directly ?

To get more debug logs add:

import logging logging.basicConfig(level=logging.DEBUG)

At the beginning of your application.

Thanks, I've added it but don't see more python logs than those that I posted above. I need to see if I can have more logs on Azure side.

raowaqas72 commented 2 years ago

i am facing same problem

cartertinney commented 2 years ago

@MrVhek can you try reverting to IoT Edge 1.1? There are known issues with using Edge 1.2 with the SDK.

@raowaqas72 if you could try the same, that would also be appreciated

MrVhek commented 2 years ago

Sorry for the late reply, I finally found the issue, it was related to the routing of send_message.

image

Be sure to not have an output after your module name (here GWApp or ToolsApp). Thanks for your help anyway ! I just hope that some warning or error log could be emitted if messages are not being routed. But maybe it is already the case.