search

Azure / iot-edge-v1

Azure IoT Edge
http://azure.github.io/iot-edge/
Other
525 stars 258 forks source link

[V2] Messages from ingester to other module (filter) are not routed #540

Open villepalo opened 6 years ago

villepalo commented 6 years ago

I have a three module setup, ingester --> filter --> wrapper. Sometimes after iotedgect is restarted or device is booted, messages from ingester are not forwarded to filter. Usually this works, but occasionally not. Here's the edgeHub log:

2018-03-14 08:33:13.091 +00:00 [INF] - Initializing configuration 2018-03-14 08:33:13.670 +00:00 [INF] - Created persistent store at /tmp/edgeHub 2018-03-14 08:33:13.735 +00:00 [INF] - Attempting to connect to IoT Hub for client test-device/$edgeHub via AMQP... 2018-03-14 08:33:15.289 +00:00 [INF] - Connected to IoT Hub for client test-device/$edgeHub via AMQP, with client operation timeout 60000. 2018-03-14 08:33:15.299 +00:00 [INF] - Created cloud connection for client test-device/$edgeHub 2018-03-14 08:33:15.330 +00:00 [INF] - New device connection for device test-device/$edgeHub 2018-03-14 08:33:16.179 +00:00 [INF] - Created new message store 2018-03-14 08:33:16.180 +00:00 [INF] - Started task to cleanup processed and stale messages 2018-03-14 08:33:18.148 +00:00 [INF] - Obtained edge hub config from module twin 2018-03-14 08:33:18.414 +00:00 [INF] - Set the following 3 route(s) in edge hub 2018-03-14 08:33:18.416 +00:00 [INF] - route1: FROM /messages/modules/ingester/outputs/output1 INTO BrokeredEndpoint("/modules/filter/inputs/input1") 2018-03-14 08:33:18.416 +00:00 [INF] - route2: FROM /messages/modules/filter/outputs/output1 INTO BrokeredEndpoint("/modules/event_wrapper/inputs/input1") 2018-03-14 08:33:18.416 +00:00 [INF] - route3: FROM /messages/modules/event_wrapper/outputs/output1 INTO $upstream 2018-03-14 08:33:18.417 +00:00 [INF] - Updated message store TTL to 72 seconds 2018-03-14 08:33:18.418 +00:00 [INF] - Updated the edge hub store and forward configuration 2018-03-14 08:33:18.419 +00:00 [INF] - Initialized edge hub configuration 2018-03-14 08:33:18.419 +00:00 [INF] - Starting Http Server 2018-03-14 08:33:20.176 +00:00 [INF] - Starting MQTT Server 2018-03-14 08:33:20.216 +00:00 [INF] - Starting 2018-03-14 08:33:20.976 +00:00 [INF] - Initializing TLS endpoint on port 8883. 2018-03-14 08:33:21.089 +00:00 [INF] - Started 2018-03-14 08:33:22.856 +00:00 [INF] - Attempting to connect to IoT Hub for client test-device/filter via AMQP... 2018-03-14 08:33:22.881 +00:00 [INF] - New token requested by client test-device/filter, but using existing token as it is usable. 2018-03-14 08:33:23.218 +00:00 [INF] - Connected to IoT Hub for client test-device/filter via AMQP, with client operation timeout 60000. 2018-03-14 08:33:23.255 +00:00 [INF] - Set subscriptions from session state for test-device/filter on cloud reconnect 2018-03-14 08:33:23.255 +00:00 [INF] - Created cloud connection for client test-device/filter 2018-03-14 08:33:23.256 +00:00 [INF] - New cloud connection created for device test-device/filter 2018-03-14 08:33:23.258 +00:00 [INF] - Successfully authenticated device test-device/filter 2018-03-14 08:33:23.259 +00:00 [INF] - Successfully generated identity for clientId test-device/filter and username cnpdev-virtualbox/test-device/filter/api-version=2017-06-30&DeviceClientType=Microsoft.Azure.Devices.Client%2F1.6.0-preview-001%20%28.NET%20Core%204.6.00001.0%3B%20Linux%204.4.0-116-generic%20%23140~14.04.1-Ubuntu%20SMP%20Fri%20Feb%2016%2009%3A25%3A20%20UTC%202018%3B%20X64%29 2018-03-14 08:33:23.263 +00:00 [INF] - ClientAuthenticated, test-device/filter, 1e053962 2018-03-14 08:33:23.339 +00:00 [INF] - New device connection for device test-device/filter 2018-03-14 08:33:23.381 +00:00 [INF] - Bind device proxy for device test-device/filter 2018-03-14 08:33:23.382 +00:00 [INF] - Binding message channel for device Id test-device/filter 2018-03-14 08:33:23.749 +00:00 [INF] - Set subscriptions from session state for test-device/filter 2018-03-14 08:33:23.818 +00:00 [INF] - Set subscriptions from session state for test-device/filter 2018-03-14 08:33:23.862 +00:00 [INF] - Attempting to connect to IoT Hub for client test-device/event_wrapper via AMQP... 2018-03-14 08:33:23.868 +00:00 [INF] - New token requested by client test-device/event_wrapper, but using existing token as it is usable. 2018-03-14 08:33:24.493 +00:00 [INF] - Connected to IoT Hub for client test-device/event_wrapper via AMQP, with client operation timeout 60000. 2018-03-14 08:33:24.494 +00:00 [INF] - Set subscriptions from session state for test-device/event_wrapper on cloud reconnect 2018-03-14 08:33:24.494 +00:00 [INF] - Created cloud connection for client test-device/event_wrapper 2018-03-14 08:33:24.494 +00:00 [INF] - New cloud connection created for device test-device/event_wrapper 2018-03-14 08:33:24.494 +00:00 [INF] - Successfully authenticated device test-device/event_wrapper 2018-03-14 08:33:24.494 +00:00 [INF] - Successfully generated identity for clientId test-device/event_wrapper and username cnpdev-virtualbox/test-device/event_wrapper/api-version=2017-06-30&DeviceClientType=Microsoft.Azure.Devices.Client%2F1.6.0-preview-001%20%28.NET%20Core%204.6.00001.0%3B%20Linux%204.4.0-116-generic%20%23140~14.04.1-Ubuntu%20SMP%20Fri%20Feb%2016%2009%3A25%3A20%20UTC%202018%3B%20X64%29 2018-03-14 08:33:24.494 +00:00 [INF] - ClientAuthenticated, test-device/event_wrapper, 50a6288a 2018-03-14 08:33:24.495 +00:00 [INF] - New device connection for device test-device/event_wrapper 2018-03-14 08:33:24.495 +00:00 [INF] - Bind device proxy for device test-device/event_wrapper 2018-03-14 08:33:24.495 +00:00 [INF] - Binding message channel for device Id test-device/event_wrapper 2018-03-14 08:33:24.823 +00:00 [INF] - Set subscriptions from session state for test-device/event_wrapper 2018-03-14 08:33:24.861 +00:00 [INF] - Set subscriptions from session state for test-device/event_wrapper 2018-03-14 08:33:25.119 +00:00 [INF] - Set subscriptions from session state for test-device/filter 2018-03-14 08:33:25.879 +00:00 [INF] - Set subscriptions from session state for test-device/event_wrapper 2018-03-14 08:33:26.046 +00:00 [INF] - Attempting to connect to IoT Hub for client test-device/ingester via AMQP... 2018-03-14 08:33:26.047 +00:00 [INF] - New token requested by client test-device/ingester, but using existing token as it is usable. 2018-03-14 08:33:26.335 +00:00 [INF] - Connected to IoT Hub for client test-device/ingester via AMQP, with client operation timeout 60000. 2018-03-14 08:33:26.335 +00:00 [INF] - Set subscriptions from session state for test-device/ingester on cloud reconnect 2018-03-14 08:33:26.335 +00:00 [INF] - Created cloud connection for client test-device/ingester 2018-03-14 08:33:26.336 +00:00 [INF] - New cloud connection created for device test-device/ingester 2018-03-14 08:33:26.336 +00:00 [INF] - Successfully authenticated device test-device/ingester 2018-03-14 08:33:26.336 +00:00 [INF] - Successfully generated identity for clientId test-device/ingester and username cnpdev-virtualbox/test-device/ingester/api-version=2017-06-30&DeviceClientType=Microsoft.Azure.Devices.Client%2F1.6.0-preview-001%20%28.NET%20Core%204.6.00001.0%3B%20Linux%204.4.0-116-generic%20%23140~14.04.1-Ubuntu%20SMP%20Fri%20Feb%2016%2009%3A25%3A20%20UTC%202018%3B%20X64%29 2018-03-14 08:33:26.336 +00:00 [INF] - ClientAuthenticated, test-device/ingester, 1b321eab 2018-03-14 08:33:26.336 +00:00 [INF] - New device connection for device test-device/ingester 2018-03-14 08:33:26.343 +00:00 [INF] - Bind device proxy for device test-device/ingester 2018-03-14 08:33:26.343 +00:00 [INF] - Binding message channel for device Id test-device/ingester 2018-03-14 08:33:26.427 +00:00 [INF] - Set subscriptions from session state for test-device/ingester 2018-03-14 08:45:07.589 +00:00 [ERR] - LEAK: IByteBuffer.Release() was not called before it's garbage-collected. Enable advanced leak reporting to find out where the leak occurred. To enable advanced leak reporting, set environment variable io.netty.leakDetection.level to advanced or set ResourceLeakDetector.Level in code. See http://netty.io/wiki/reference-counted-objects.html for more information. 2018-03-14 09:03:16.222 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub 2018-03-14 09:03:17.531 +00:00 [INF] - Cleaned up 4426 messages from queue for endpoint iothub and 4426 messages from message store. 2018-03-14 09:03:47.531 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint test-device/filter/input1 2018-03-14 09:03:51.942 +00:00 [INF] - Cleaned up 19235 messages from queue for endpoint test-device/filter/input1 and 19235 messages from message store. 2018-03-14 09:04:22.167 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint test-device/even_wrapper/input1 2018-03-14 09:04:25.884 +00:00 [INF] - Cleaned up 13553 messages from queue for endpoint test-device/event_wrapper/input1 and 13553 messages from message store. 2018-03-14 09:18:42.739 +00:00 [WRN] - Closing connection for device: test-device/ingester, scope: ExceptionCaught, DotNetty.Codecs.DecoderException: [MQTT-2.3.1-1] at DotNetty.Codecs.Mqtt.MqttDecoder.DecodePacketIdVariableHeader(IByteBuffer buffer, PacketWithId packet, Int32& remainingLength) at DotNetty.Codecs.Mqtt.MqttDecoder.DecodePublishPacket(IByteBuffer buffer, PublishPacket packet, Int32& remainingLength) at DotNetty.Codecs.Mqtt.MqttDecoder.DecodePacketInternal(IByteBuffer buffer, Int32 packetSignature, Int32& remainingLength, IChannelHandlerContext context) at DotNetty.Codecs.Mqtt.MqttDecoder.TryDecodePacket(IByteBuffer buffer, IChannelHandlerContext context, Packet& packet) at DotNetty.Codecs.Mqtt.MqttDecoder.Decode(IChannelHandlerContext context, IByteBuffer input, List1 output) at DotNetty.Codecs.ReplayingDecoder1.CallDecode(IChannelHandlerContext context, IByteBuffer input, List1 output) at DotNetty.Codecs.ByteToMessageDecoder.ChannelRead(IChannelHandlerContext context, Object message) at DotNetty.Transport.Channels.AbstractChannelHandlerContext.InvokeChannelRead(Object msg), 1b321eab 2018-03-14 09:18:42.749 +00:00 [INF] - Disposing MessagingServiceClient for device Id test-device/ingester because of exception - DotNetty.Codecs.DecoderException: [MQTT-2.3.1-1] at DotNetty.Codecs.Mqtt.MqttDecoder.DecodePacketIdVariableHeader(IByteBuffer buffer, PacketWithId packet, Int32& remainingLength) at DotNetty.Codecs.Mqtt.MqttDecoder.DecodePublishPacket(IByteBuffer buffer, PublishPacket packet, Int32& remainingLength) at DotNetty.Codecs.Mqtt.MqttDecoder.DecodePacketInternal(IByteBuffer buffer, Int32 packetSignature, Int32& remainingLength, IChannelHandlerContext context) at DotNetty.Codecs.Mqtt.MqttDecoder.TryDecodePacket(IByteBuffer buffer, IChannelHandlerContext context, Packet& packet) at DotNetty.Codecs.Mqtt.MqttDecoder.Decode(IChannelHandlerContext context, IByteBuffer input, List1 output) at DotNetty.Codecs.ReplayingDecoder1.CallDecode(IChannelHandlerContext context, IByteBuffer input, List1 output) at DotNetty.Codecs.ByteToMessageDecoder.ChannelRead(IChannelHandlerContext context, Object message) at DotNetty.Transport.Channels.AbstractChannelHandlerContext.InvokeChannelRead(Object msg) 2018-03-14 09:18:42.754 +00:00 [INF] - Setting device proxy inactive for device Id test-device/ingester 2018-03-14 09:18:42.770 +00:00 [INF] - Closing receiver for device test-device/ingester 2018-03-14 09:18:42.817 +00:00 [INF] - Closed cloud proxy for device test-device/ingester 2018-03-14 09:18:42.822 +00:00 [INF] - Device connection removed for device test-device/ingester 2018-03-14 09:18:42.833 +00:00 [INF] - Remove device connection for device test-device/ingester 2018-03-14 09:18:43.067 +00:00 [INF] - Attempting to connect to IoT Hub for client test-device/ingester via AMQP... 2018-03-14 09:18:43.073 +00:00 [INF] - New token requested by client test-device/ingester, but using existing token as it is usable. 2018-03-14 09:18:43.325 +00:00 [INF] - Connected to IoT Hub for client test-device/ingester via AMQP, with client operation timeout 60000. 2018-03-14 09:18:43.325 +00:00 [INF] - Closing receiver for device test-device/ingester 2018-03-14 09:18:43.325 +00:00 [INF] - Closed cloud proxy for device test-device/ingester 2018-03-14 09:18:43.334 +00:00 [INF] - Set subscriptions from session state for test-device/ingester on cloud reconnect 2018-03-14 09:18:43.334 +00:00 [INF] - New cloud connection created for device test-device/ingester 2018-03-14 09:18:43.334 +00:00 [INF] - Successfully authenticated device test-device/ingester 2018-03-14 09:18:43.334 +00:00 [INF] - Successfully generated identity for clientId test-device/ingester and username cnpdev-virtualbox/test-device/ingester/api-version=2017-06-30&DeviceClientType=Microsoft.Azure.Devices.Client%2F1.6.0-preview-001%20%28.NET%20Core%204.6.00001.0%3B%20Linux%204.4.0-116-generic%20%23140~14.04.1-Ubuntu%20SMP%20Fri%20Feb%2016%2009%3A25%3A20%20UTC%202018%3B%20X64%29 2018-03-14 09:18:43.334 +00:00 [INF] - ClientAuthenticated, test-device/ingester, 5b466ea6 2018-03-14 09:18:43.338 +00:00 [INF] - New device connection for device test-device/ingester 2018-03-14 09:18:43.339 +00:00 [INF] - Bind device proxy for device test-device/ingester 2018-03-14 09:18:43.339 +00:00 [INF] - Binding message channel for device Id test-device/ingester 2018-03-14 09:18:43.339 +00:00 [INF] - Set subscriptions from session state for test-device/ingester

aribeironovaes commented 6 years ago

Thanks a lot for reporting this @villepalo,

Can you please enable Debug logs on EdgeHub and Edge Agent, run your scenario and send us the logs again? It should give us better information, from the logs you sent things should be working normally. I've open an internal bug so we can investigate this further.

Thanks,

Angelo Ribeiro.

villepalo commented 6 years ago

I'll try, it didn't occur always, but if it occurs again, I'll send more detailed logs.

xitia commented 6 years ago

Hi, any update here? I have a customer getting the similar issue, occasionally, after they restarting device, the downstream module does not receive messages anymore. I had a screen share session with them, there wasn't error message in edgehub (they turned on debug mode). Thanks!