export-distro sometimes encounters 0MQ message body error

[cloudxxx8]

🐞 Bug Report

Affected Services

The issue is located in: the communication between export-distro and core-data via 0MQ

Is this a regression?

Yes, it doesn't happen in Delhi release

Description and Minimal Reproduction

Running EdgeX v1.0.0 with multiple Device Services on lower power kit (Dell3000, UPSquared), and create multiple export registrations, and wait for 5-15 mins until the error log printed in export-distro. All export-distro goroutines are terminated when this issue occurs. In the error log, 'events events' bit looks wrong.

🔥 Exception or Error

level=ERROR ts=2019-07-01T14:35:12.820403389Z app=edgex-export-distro source=registrations.go:350 msg="exit msg: found more than 2 incoming messages (1 is no topic, 2 is topic and message), but found: 3"
When we print with a bit more info we see:
level=ERROR ts=2019-07-08T18:40:04.596019465Z app=edgex-export-distro source=registrations.go:350 msg="exit msg: found more than 2 incoming messages (1 is no topic, 2 is topic and message), but found: 3, message content: [events events {"Checksum":"","CorrelationID":"e8c3960b-afb3-42b5-910f-4f20d6e36267","Payload":"eyJjb3JyZWxhdGlvbi1pZCI6ImU4YzM5NjBiLWFmYjMtNDJiNS05MTBmLTRmMjBkNmUzNjI2NyIsImlkIjoiMWIwYzlhNzItMjRhNC00YTFiLTgyYTgtOTgxZDUxNDVjMTg5IiwiZGV2aWNlIjoiUmFuZG9tLUludGVnZXItRGV2aWNlIiwib3JpZ2luIjoxNTYyNjExMjA0NTYwNDgwODUxLCJyZWFkaW5ncyI6W3siaWQiOiI5OThlN2MxNy0xMTYyLTRlMmYtYjBmYy0wNjJmMzdkYTJmM2MiLCJvcmlnaW4iOjE1NjI2MTEyMDQ1NDI1OTA4MDcsImRldmljZSI6IlJhbmRvbS1JbnRlZ2VyLURldmljZSIsIm5hbWUiOiJSYW5kb21WYWx1ZV9JbnQxNiIsInZhbHVlIjoiLTQ5NTkifV19","ContentType":"application/json"}]"
level=INFO ts=2019-07-08T18:40:04.596015754Z app=edgex-export-distro source=registrations.go:250 msg="Terminating registration goroutine"
level=INFO ts=2019-07-08T18:40:04.597181997Z app=edgex-export-distro source=registrations.go:250 msg="Terminating registration goroutine"
level=INFO ts=2019-07-08T18:40:04.597900919Z app=edgex-export-distro source=registrations.go:250 msg="Terminating registration goroutine"

🌍 Your Environment

Deployment Environment:
lower power kit, such as Dell3000, UPSquared

EdgeX Version:
Edinburgh Release v1.0.0

Anything else relevant?
The log is printed by https://github.com/edgexfoundry/go-mod-messaging/blob/18e14ad62fb232c3fddceea415da29d0b56d5906/internal/pkg/zeromq/client.go#L172 , and the message content printing is added by us

[tsconn23]

FWIW that error message is coming from the following location in the go-mod-messaging module
https://github.com/edgexfoundry/go-mod-messaging/blob/8a7864e25347004b93e696f26b74d0c6a56b78e3/internal/pkg/zeromq/client.go#L166

@rsdmike @lenny-intel for visibility

[lenny-goodell]

Based on the logs above we are getting the events topic twice and then the message envelope.
events events {"Checksum....
we should be getting:
events {"Checksum....

So wondering if the previous message envelope got dropped.

[lenny-goodell]

@TomFlem , can you check your core data logs for this error?
Unable to send message for event: the length of the sent messages does not match the expected length

[weichou1229]

@lenny-intel I got the same issue

Deployment Environment:
macos, 2.2 GHz ,16 GB

EdgeX Version:
Edinburgh Release v1.0.0
https://github.com/edgexfoundry/developer-scripts/blob/master/compose-files/docker-compose-edinburgh-no-secty-1.0.0.yml

Case 1

core-data log

level=INFO ts=2019-07-10T05:39:17.7960776Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T05:39:17.7962221Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: 5c7631b0-20af-49b5-b63c-4358f9671f1c "
level=INFO ts=2019-07-10T05:39:21.1586094Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T05:39:21.158918Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: 281eb742-a43c-4e65-8f90-d645e0e031b4 "
level=INFO ts=2019-07-10T05:39:21.1679273Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T05:39:21.1686831Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T05:39:21.1694699Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: 7057b211-4c96-4fc2-968c-e60f8099e786 "
level=INFO ts=2019-07-10T05:39:21.1739622Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: 219f57e8-5c37-48c1-a36f-255c7a142989 "
level=INFO ts=2019-07-10T05:39:21.1815768Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T05:39:21.1817464Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: 4f1d4929-6548-4431-b99d-bab2aecd15ad "
level=INFO ts=2019-07-10T05:39:26.7243752Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T05:39:26.7249153Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: a8a2f505-043b-4e63-b15d-10a50302a77f "

export-distro log

level=INFO ts=2019-07-10T05:39:06.7335397Z app=edgex-export-distro source=httpsender.go:67 correlation-id=9ed25ed0-66e3-40f6-8719-8682c14c297e duration=3.58ms msg="Response: 200 OK"
level=INFO ts=2019-07-10T05:39:06.7336146Z app=edgex-export-distro source=httpsender.go:73 msg="Sent data: 7B226964223A2264363238666266652D613531322D346438322D613663642D616230653065643464643161222C22646576696365223A2252616E646F6D2D426F6F6C65616E2D446576696365222C226F726967696E223A313536323733373134363732313136303430302C2272656164696E6773223A5B7B226964223A2231373336636431382D306435652D343439372D626666622D316236363639333539333331222C226F726967696E223A313536323733373134363731333731383530302C22646576696365223A2252616E646F6D2D426F6F6C65616E2D446576696365222C226E616D65223A2252616E646F6D56616C75655F426F6F6C222C2276616C7565223A2266616C7365227D5D7D"
level=INFO ts=2019-07-10T05:39:16.7271274Z app=edgex-export-distro source=httpsender.go:67 correlation-id=6761ec32-103c-4c2c-8c92-050687f0874c duration=12.7865ms msg="Response: 200 OK"
level=INFO ts=2019-07-10T05:39:16.7273089Z app=edgex-export-distro source=httpsender.go:73 msg="Sent data: 7B226964223A2265616163633737642D633138322D346366362D613862632D343739336335346665623733222C22646576696365223A2252616E646F6D2D426F6F6C65616E2D446576696365222C226F726967696E223A313536323733373135363639363632353930302C2272656164696E6773223A5B7B226964223A2264613138346661312D636230312D346531612D623936362D626366316163363965316536222C226F726967696E223A313536323733373135363638373738333030302C22646576696365223A2252616E646F6D2D426F6F6C65616E2D446576696365222C226E616D65223A2252616E646F6D56616C75655F426F6F6C222C2276616C7565223A2274727565227D5D7D"
level=ERROR ts=2019-07-10T05:39:21.1821154Z app=edgex-export-distro source=registrations.go:346 msg="exit msg: found more than 2 incoming messages (1 is no topic, 2 is topic and message), but found: 3"
level=INFO ts=2019-07-10T05:39:21.1822993Z app=edgex-export-distro source=registrations.go:246 msg="Terminating registration goroutine"
level=INFO ts=2019-07-10T05:39:21.1826086Z app=edgex-export-distro source=registrations.go:246 msg="Terminating registration goroutine"
level=INFO ts=2019-07-10T05:39:21.1826169Z app=edgex-export-distro source=registrations.go:246 msg="Terminating registration goroutine"

Case 2

core-data log

level=INFO ts=2019-07-10T07:16:21.4614726Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:21.4643076Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: 42deb3b0-21a9-4303-b403-feb66dbbef14 "
level=INFO ts=2019-07-10T07:16:31.4255279Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:31.4255781Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:31.4256708Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: fed41a0c-4a87-45a2-9c88-1ce085ada123 "
level=INFO ts=2019-07-10T07:16:31.425781Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: a11ddfe9-bb57-41d8-8adc-407d708bfb7b "
level=INFO ts=2019-07-10T07:16:31.4615985Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:31.4620346Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: 11374ee4-39f7-4df7-b7f1-70830ccaecb3 "
level=INFO ts=2019-07-10T07:16:31.4697833Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:31.4701279Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: ce415aa0-697c-412d-ac3a-4833ce4bb68f "
level=INFO ts=2019-07-10T07:16:31.4781154Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:31.4782416Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: e14b84bd-425c-4f8b-9ab5-3790953a7ed3 "
level=INFO ts=2019-07-10T07:16:31.4881848Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:31.4887879Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: f4e6fcbd-9b41-43fb-bb3b-365f846becb7 "
level=INFO ts=2019-07-10T07:16:31.4926332Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:31.4927156Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: bc531c74-cf2f-4249-9c3a-1616f5419607 "
level=INFO ts=2019-07-10T07:16:41.3895282Z app=edgex-core-data source=event.go:239 msg="Putting event on message queue"
level=INFO ts=2019-07-10T07:16:41.3900324Z app=edgex-core-data source=event.go:257 msg="Event Published on message queue. Topic: events, Correlation-id: 6e7e9d89-30a3-484e-b49c-c93056ef5955 "

export-distro log

level=INFO ts=2019-07-10T07:16:21.4686292Z app=edgex-export-distro source=httpsender.go:73 msg="Sent data: 7B226964223A2230373063623532332D336334362D343364642D616161352D663163616264633432653565222C22646576696365223A2252616E646F6D2D426F6F6C65616E2D446576696365222C226F726967696E223A313536323734323938313434313130313230302C2272656164696E6773223A5B7B226964223A2232316336653865652D623865332D343463642D613239382D646132323538613233656435222C226F726967696E223A313536323734323938313433333735363430302C22646576696365223A2252616E646F6D2D426F6F6C65616E2D446576696365222C226E616D65223A2252616E646F6D56616C75655F426F6F6C222C2276616C7565223A2274727565227D5D7D"
level=ERROR ts=2019-07-10T07:16:31.4266712Z app=edgex-export-distro source=registrations.go:346 msg="exit msg: found more than 2 incoming messages (1 is no topic, 2 is topic and message), but found: 3"
level=INFO ts=2019-07-10T07:16:31.4266638Z app=edgex-export-distro source=registrations.go:246 msg="Terminating registration goroutine"
level=INFO ts=2019-07-10T07:16:31.42676Z app=edgex-export-distro source=registrations.go:246 msg="Terminating registration goroutine"
level=INFO ts=2019-07-10T07:16:31.4268764Z app=edgex-export-distro source=registrations.go:246 msg="Terminating registration goroutine"

[TomFlem]

@TomFlem , can you check your core data logs for this error?
Unable to send message for event: the length of the sent messages does not match the expected length

No we don't see this error.

[lenny-goodell]

Thanks @weichou1229. This is great information which confirms this issue is not just on low power devices. I will have one of our devs who uses a MAC attempt to recreate.

[lenny-goodell]

@rsdmike was able to recreate the issue on his MAC Book. I was not able to recreate it on my Linux box which ran for 2hrs.

[lenny-goodell]

I have now reproduced this issue on my Linux box running https://github.com/edgexfoundry/developer-scripts/blob/master/compose-files/docker-compose-edinburgh-no-secty-1.0.0.yml

I left it running over night.

[lenny-goodell]

I built latest images for core-data and export-distro from master (with Trevor's race condition fix) and still got the issue. This time it occurred fairly quickly, with approx 15mins. Running again with logging set to TRACE for both to see if we see anything from core data when the error occurs.

[tsconn23]

Fix was included in v1.0.1 images