Azure / iotedge

The IoT Edge OSS project
MIT License
1.45k stars 457 forks source link

create_from_edge_environment does not send messages to IoT Hub #6432

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

vipeller commented 2 years ago

hi @MrVhek, sorry for the late reply. Could you please do the following:

if the log is too big, you can upload it somewhere (like onedrive). If you don't want to share the link to the store here, you can send it to me at microsoft, my address is like my user id in github and the company domain dot com.

MrVhek commented 2 years ago

Hi ! I finally found the issue, it was related to the routing of send_message.

image

I had to make sure to not have an output after my 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.