edgeHub lose messages, not delivering to IoTHub

[carloshm]

Expected Behavior

every message deliver to edgeHub should be sent to IoTHub

Current Behavior

edgeHub receive message but does not deliver to IoTHub losing the messages

Steps to Reproduce

1. IoTEdge runtime 1.04 latest SDK 1.18
2. Modules edgeHub and edgeAgent 1.04
3. Custom Modules sending messages every minutes
4. Twin updates are used

In the logs you can see after setting debug mode, edgeHub is not working as expected

Context (Environment)

Device (Host) Operating System

Raspberry Pi Stretch
latest update

Architecture

arm32

Container Operating System

Linux

Runtime Versions

iotedged

iotedge 1.0.4 (2835ac47fbb944ba628a5cfe812ff394768842e0)

Edge Agent

1.04

Edge Hub

1.04

Docker

Client:
Version: 18.06.0-dev
API version: 1.37
Go version: go1.10.2
Git commit: daf021fe
Built: Wed Jun 27 00:53:52 2018
OS/Arch: linux/arm
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: Tue Jun 26 23:27:27 2018
OS/Arch: linux/arm
Experimental: false

Logs

First IoT Edge working fine

2018-11-27 15:46:52.853 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-11-27 15:46:52.853 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded for gateway01/vibrationModule
2018-11-27 15:46:52.853 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device gateway01/vibrationModule
2018-11-27 15:46:52.854 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for gateway01/vibrationModule from cloud at desired version 14 reported version 28
2018-11-27 15:46:52.854 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Local twin for gateway01/vibrationModule at higher or equal desired version 14 compared to cloud 14 or reported version 28 compared to cloud 28
2018-11-27 15:46:52.905 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Sent twin update to gateway01/vibrationModule
2018-11-27 15:46:52.906 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Processed GetTwin for gateway01/vibrationModule
2018-11-27 15:46:52.906 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Getting twin for device Id gateway01/vibrationModule
2018-11-27 15:46:53.115 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 208 with batch size 10.
2018-11-27 15:46:53.116 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 208.
2018-11-27 15:46:53.224 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Processing message for device Id gateway01/vibrationModule
2018-11-27 15:46:53.225 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from gateway01/vibrationModule
2018-11-27 15:46:53.230 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 208 with batch size 10.
2018-11-27 15:46:53.237 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 209.
2018-11-27 15:46:53.237 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 1 message(s) upstream.
2018-11-27 15:46:53.237 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device gateway01/vibrationModule
2018-11-27 15:46:53.280 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Processing message for device Id gateway01/vibrationModule
2018-11-27 15:46:53.280 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from gateway01/vibrationModule
2018-11-27 15:46:53.585 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-11-27 15:46:53.586 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for gateway01/vibrationModule
2018-11-27 15:46:53.586 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device gateway01/vibrationModule
2018-11-27 15:46:53.587 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 209 with batch size 10.
2018-11-27 15:46:53.588 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 210.
2018-11-27 15:46:53.589 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 1 message(s) upstream.
2018-11-27 15:46:53.589 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device gateway01/vibrationModule
2018-11-27 15:46:53.705 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-11-27 15:46:53.706 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for gateway01/vibrationModule
2018-11-27 15:46:53.706 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device gateway01/vibrationModule
2018-11-27 15:46:53.707 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 210 with batch size 10.
2018-11-27 15:46:53.707 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 210.
2018-11-27 15:47:03.708 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 210 with batch size 10.
2018-11-27 15:47:03.708 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 210.
2018-11-27 15:47:13.709 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 210 with batch size 10.
2018-11-27 15:47:13.709 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 210.
2018-11-27 15:47:23.710 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 210 with batch size 10.
2018-11-27 15:47:23.710 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 210.

Second IoT Edge NOT working

This is the log of our custom module (edgeHub acknowledge message and we delete from origin)

11/27/2018 15:46:50: [Information] Updating properties.
11/27/2018 15:46:50: [Information] Updating Module Twin.
11/27/2018 15:46:50: [Information] Updating Nearby Sensors.
11/27/2018 15:46:50: [Information] Setting time for gateway c5aba775-c6df-4c4e-bf04-e1073ccc5cc5.
11/27/2018 15:46:50: [Information] Requesting Data from sensor fb:28:ab:63:ae:1a.
11/27/2018 15:46:50: [Information] Reading Data from Sensor fb:28:ab:63:ae:1a.
11/27/2018 15:46:50: [Information] Data sent.
11/27/2018 15:46:50: [Information] Received data from sensor fb:28:ab:63:ae:1a.
11/27/2018 15:46:50: [Information] Sending Data to Cloud (amplitude fd8f6e34-d5f8-4574-5bf5-7717bf9dd931).
11/27/2018 15:46:50: [Information] Data was sent.
11/27/2018 15:46:50: [Information] Sending Data to Cloud (temperature fd8f6e34-d5f8-4574-5bf5-7717bf9dd931).
11/27/2018 15:46:50: [Information] Data was sent.
11/27/2018 15:46:50: [Information] Cleaning data cache for Sensor fb:28:ab:63:ae:1a of Gateway c5aba775-c6df-4c4e-bf04-e1073ccc5cc5.
11/27/2018 15:46:50: [Information] Deleting Data from Sensor fb:28:ab:63:ae:1a.
11/27/2018 15:46:50: [Information] Data deleted.
11/27/2018 15:46:50: [Information] Cleaning is done.
11/27/2018 15:46:50: [Information] Requesting Data from sensor c0:36:cf:fe:96:d2.
11/27/2018 15:46:50: [Information] Reading Data from Sensor c0:36:cf:fe:96:d2.

### edgeHub log, it does not deliver

2018-11-27 15:46:50.704 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-11-27 15:46:50.704 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded for gateway02/vibrationModule
2018-11-27 15:46:50.704 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device gateway02/vibrationModule
2018-11-27 15:46:50.705 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for gateway02/vibrationModule from cloud at desired version 49 reported version 64
2018-11-27 15:46:50.706 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Local twin for gateway02/vibrationModule at higher or equal desired version 49 compared to cloud 49 or reported version 64 compared to cloud 64
2018-11-27 15:46:50.708 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Sent twin update to gateway02/vibrationModule
2018-11-27 15:46:50.708 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Processed GetTwin for gateway02/vibrationModule
2018-11-27 15:46:50.708 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Getting twin for device Id gateway02/vibrationModule
2018-11-27 15:46:50.811 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Processing message for device Id gateway02/vibrationModule
2018-11-27 15:46:50.812 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from gateway02/vibrationModule
2018-11-27 15:46:50.870 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 75 with batch size 10.
2018-11-27 15:46:50.871 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 75.
2018-11-27 15:46:50.875 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Processing message for device Id gateway02/vibrationModule
2018-11-27 15:46:50.875 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from gateway02/vibrationModule

As logs continue not message is delivered: from MessageStore. NO message sent...

2018-11-27 15:46:50.877 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 75 with batch size 10.
2018-11-27 15:46:50.877 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 75.
2018-11-27 15:47:00.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 75 with batch size 10.
2018-11-27 15:47:00.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 75.
2018-11-27 15:47:10.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 75 with batch size 10.
2018-11-27 15:47:10.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 75.
2018-11-27 15:47:20.880 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 75 with batch size 10.
2018-11-27 15:47:20.881 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 75.
2018-11-27 15:47:30.881 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 75 with batch size 10.
2018-11-27 15:47:30.882 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 75.
2018-11-27 15:47:40.883 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 75 with batch size 10.
2018-11-27 15:47:40.883 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 75.
2018-11-27 15:47:50.885 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 75 with batch size 10.
2018-11-27 15:47:50.885 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 75.
2018-11-27 15:47:50.968 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - GetTwin call received from gateway02/vibrationModule
2018-11-27 15:47:50.969 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device gateway02/vibrationModule
2018-11-27 15:47:51.132 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-11-27 15:47:51.132 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded for gateway02/vibrationModule
2018-11-27 15:47:51.132 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device gateway02/vibrationModule
2018-11-27 15:47:51.134 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for gateway02/vibrationModule from cloud at desired version 49 reported version 64

Additional Information

[carloshm]

FYI @ancaantochi

[ancaantochi]

Hi Carlos,

This is a bug in edgeHub that can be reproduced when edgeHub container gets killed. After it starts again the messages offset in the store is reset, but reading messages from the store is not reset. We are working on fixing this issue.

[myagley]

The fix for this is checked in here: #603

[MPapst]

Any idea when you plan to release this?
Can this be resolved by letting the engine recreate the containers? (e.g. by deleting the containers when iotedge daemon is not running?)

[myagley]

We are planning a release before the end of the year with this fix.

The only way to resolve it currently is to delete the Edge Hub container.

[myagley]

This has been fixed in the 1.0.5 release. More information on upgrading is here: https://docs.microsoft.com/en-us/azure/iot-edge/how-to-update-iot-edge