transparent gateway - no "device id" from a leaf device

[stevebus]

Expected Behavior

• expect messages from leaf devices in transparent gateway scenario
  • get routed properly
  • pass along a proper device ID to modules
  • not cause errors in edgeHub logs

Current Behavior

Messages from leaf devices (iotTestDev01 in the context below) have several issues, all related.

1. they cause these errors in edgeHub

2018-08-23 20:57:38.799 +00:00 [INF] - Set the following 1 route(s) in edge hub
2018-08-23 20:57:38.799 +00:00 [INF] - toFormatterFromDevices: FROM /messages/* WHERE NOT IS_DEFINED($connectionModuleId) INTO $upstream
2018-08-23 20:57:38.801 +00:00 [INF] - Updated message store TTL to 7200 seconds
2018-08-23 20:57:38.801 +00:00 [INF] - Updated the edge hub store and forward configuration
2018-08-23 20:57:39.795 +00:00 [ERR] - Received message does not contain a device Id
2018-08-23 20:57:40.741 +00:00 [WRN] - Message address devices/iotTestDev01/messages/events/ matches more than one topic. Picking first matching topic.
2018-08-23 20:57:41.983 +00:00 [ERR] - Received message does not contain a device Id
2018-08-23 20:57:43.741 +00:00 [WRN] - Message address devices/iotTestDev01/messages/events/ matches more than one topic. Picking first matching topic.
2018-08-23 20:57:45.591 +00:00 [ERR] - Received message does not contain a device Id
2018-08-23 20:57:46.741 +00:00 [WRN] - Message address devices/iotTestDev01/messages/events/ matches more than one topic. Picking first matching topic.
(I know I can do a FROM /* to $upstream route, but this is part of a larger solution that will route "leaf" device messages through modules.. also, this used to work fine)

2. I have a module in edge that uses the message.ConnectionDeviceId property and it is null for any messages routed from a leaf device, this used to work fine

3. messages with the route below do not get routed to IoT Hub. I think this related to issue Please upload crates to crates.io #1 above.
   (FROM /messages/* WHERE NOT IS_DEFINED($connectionModuleId) INTO $upstream)

Steps to Reproduce

1. edge up IoT Edge as a transparent gateway
2. create a leaf iot device and connect it via MQTT
3. create routes based on FROM /messages/* WHERE NOT IS_DEFINED($connectionModuleId) to both $upstream and a c# custom module (created from our dotnet core template)
4. observe errors above in edgeHub logs
5. observe that no messages get routed to IoT Hub
6. in the PipeMessage method, Console.WriteLine out the message.ConnectionDeviceId property (it will be null)

Context (Environment)

Ubuntu 18.04 VM in Azure
i've tried my "leaf" device as both a python script and a dotnet core app, same results
python device was created today with a fresh manual build of the python sdk
C# leaf device was created today with 1.18.0 version of the device client.

Device (Host) Operating System

Ubuntu 18.04

Architecture

amd64

Container Operating System

Linux

Runtime Versions

latest (installed today)

iotedged

iotedge 1.0.1 (6e5e86d)

Edge Agent

1.0

Edge Hub

1.0

Docker

(installed yesterday from the MS provided moby install)

Client:
Version: 18.06.0-dev
API version: 1.37
Go version: go1.10.2
Git commit: daf021fe
Built: Mon Jun 25 21:07:53 2018
OS/Arch: linux/amd64
Experimental: false
Orchestrator: swarm

Server:
Engine:
Version: dev
API version: 1.37 (minimum version 1.12)
Go version: go1.10.2
Git commit: 9aac187
Built: Mon Jun 25 20:43:05 2018
OS/Arch: linux/amd64
Experimental: false

[varunpuranik]

@stevebus - I have seen this error before, when the MQTT topic did not have a '/' at the end. This was because of a bug in the EdgeHub, where it required the '/' to parse the topic correctly. This has been fixed in version 1.0.1. So that might explain why you are seeing this with your Python script. However, it should not repro with the C# SDK, since it does set the right MQTT topic.

In any case, can you try upgrading to EdgeHub version 1.0.1? Meanwhile I will look at why you might be seeing the issue with the C# SDK.

[stevebus]

thanks @varunpuranik - I'll give it a try tonight with updated edgeHub… I also tried changing to AMQP in my python script and got a really strange error, but I didn't capture it. I'll try to repo that as well.

For clarity on the trailing '/' at the end.. is it required? or optional now with this fix? (asking because I saw that behavior when I was testing a Paho MQTT client on a transparent gateway too. It worked one way, and failed the other).

[stevebus]

Hey @varunpuranik - I tried upgrading to 1.0.1 of both edgeHub and edgeAgent (Version - 1.0.1.15962126 ). Didn't change the behavior. Same edgeHub errors as above.

Also, I tried switching to AMQP, just to see if it worked... Potentially unrelated (let me know if you want me to file another issue)… AMQP in the python module gives the errors below (in the python device itself.. nothing in the edgeHub logs). Changing to Amqp in the dotnet client doesn't give any errors at all, however, the message.ConnectionDeviceId is null.

Error: Time:Fri Aug 24 01:30:10 2018 File:/home/stevebus/azure-iot-sdk-python/c/uamqp/src/saslclientio.c Func:on_sasl_frame_received_callback Line:767 Could not find desired SASL mechanism in the list presented by server
Error: Time:Fri Aug 24 01:30:10 2018 File:/home/stevebus/azure-iot-sdk-python/c/uamqp/src/amqp_management.c Func:amqp_management_close Line:1018 AMQP management instance not open
Error: Time:Fri Aug 24 01:30:10 2018 File:/home/stevebus/azure-iot-sdk-python/c/iothub_client/src/iothubtransport_amqp_connection.c Func:on_cbs_open_complete Line:153 CBS open failed
Error: Time:Fri Aug 24 01:30:10 2018 File:/home/stevebus/azure-iot-sdk-python/c/c-utility/adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:785 SSL channel closed in decode_ssl_received_bytes.
Error: Time:Fri Aug 24 01:30:10 2018 File:/home/stevebus/azure-iot-sdk-python/c/uamqp/src/saslclientio.c Func:on_underlying_io_error Line:243 Error callback received in unexpected state
Error: Time:Fri Aug 24 01:30:10 2018 File:/home/stevebus/azure-iot-sdk-python/c/c-utility/adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:834 Error in decode_ssl_received_bytes.

[stevebus]

BTW - if you want access to my VM to troubleshoot, hit me up internally and I get give you access.

[aribeironovaes]

We have a repro Steve. We are debugging. Thanks Angelo Ribeiro

…

Sent from my phone

On Aug 23, 2018, at 6:46 PM, Steve Busby ***@***.***> wrote: BTW - if you want access to my VM to troubleshoot, hit me up internally and I get give you access. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or mute the thread.

[stevebus]

ok... thanks! and, to add one additional detail that might or might not help, but see it in my own troubleshooting... In the last scenario (amqp in C#) I'm routing the message both up to IoT Hub as well as to a custom c# module. In IoTHub, I can see that the device id is flowing through (the az iot hub monitor-events command shows the right device id).. however, in my module, I pull out the message.ConnectionDeviceId and it is null, so it's getting lost somewhere

[varunpuranik]

Thanks for all the info. The ConnectionDeviceId seems like a separate issue. I am looking into both at the moment. I will let you know when I have an update.

[aribeironovaes]

Hi @stevebus ,

We found the root cause of the issue (the: Received message does not contain a device Id). We have a fix and it's under check in process now.

It should make the next release. (Switching to AMQP will unblock, if it's possible, but don't forget to clean up edgeHub. If the broken message is in the pipe, it won't recover (We have fixed that as well)). You clean up by deleting edgeHub container and starting it again.

Thanks,

Angelo Ribeiro.

[varunpuranik]

Here is the PR - #203

[stevebus]

thanks @aribeironovaes … Glad to know a fix is inbound.

As an FYI - switching to AMQP works for the C# leaf device, but not for the python one. May be a separate issue, but the python amqp client throws the errors below in the client (and nothing is seen in edgeHub logs)

stevebus@edgeUbuntu:~/azure-iot-edge-hol-linux/module2$ python iotdevice.py
Connected to IoTHub gateway
sending message: [50.33,70.67]
Error: Time:Mon Aug 27 21:11:02 2018 File:/home/stevebus/azure-iot-sdk-python/c/uamqp/src/saslclientio.c Func:on_sasl_frame_received_callback Line:767 Could not find desired SASL mechanism in the list presented by server
Error: Time:Mon Aug 27 21:11:02 2018 File:/home/stevebus/azure-iot-sdk-python/c/uamqp/src/amqp_management.c Func:amqp_management_close Line:1018 AMQP management instance not open
Error: Time:Mon Aug 27 21:11:02 2018 File:/home/stevebus/azure-iot-sdk-python/c/iothub_client/src/iothubtransport_amqp_connection.c Func:on_cbs_open_complete Line:153 CBS open failed
Error: Time:Mon Aug 27 21:11:02 2018 File:/home/stevebus/azure-iot-sdk-python/c/c-utility/adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:785 SSL channel closed in decode_ssl_received_bytes.
Error: Time:Mon Aug 27 21:11:02 2018 File:/home/stevebus/azure-iot-sdk-python/c/uamqp/src/saslclientio.c Func:on_underlying_io_error Line:243 Error callback received in unexpected state
Error: Time:Mon Aug 27 21:11:02 2018 File:/home/stevebus/azure-iot-sdk-python/c/c-utility/adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:834 Error in decode_ssl_received_bytes.
sending message: [50.67,71.33]
^CTraceback (most recent call last):
File "iotdevice.py", line 117, in

[varunpuranik]

@stevebus - This is different issue - can you please open a separate github issue for it? That will make it easier to track.

[stevebus]

done - 215

[myagley]

Version 1.0.2 of the runtime was just released. This release has a fix for this issue.

[stevebus]

Confirmed this fixed my issue. thanks guys