Not recovering from "The message container is being closed"

[smuehlst]

Apparently it is a known fact that receiving of messages from Azure IoT Hub can fail with a message like this one:

The message container is being closed (47363). TrackingId:<... removed ....>, SystemTracker:NoSystemTracker, Timestamp:2/23/2018 10:38:09 AM

See for example:

https://stackoverflow.com/questions/42563043/azure-event-hub-servicebusexception-causing-skipped-messages
https://github.com/Azure/azure-event-hubs/issues/320

I'm currently trying the node-red-contrib-azure-eventhub-receive node and I'm seeing the above error message from time to time in the Node-RED log, and after that no further messages are received. Only a restart of Node-RED helps.

I'm fairly new to Node-RED and node.js in general, so it's unclear to me whether one should handle this kind of error somehow in the Node-RED flow. Or should the node-red-contrib-azure-eventhub-receive be able to handle this situation gracefully and this is a bug?

[smuehlst]

After running the Node-RED flow now for a while another symptom manifests itself: Repeatedly the node-red-contrib-azure-eventhub-receive node stops receiving messages without any error message being recorded in the system logs. I'm running the node within Node-RED on a Raspberry Pi under Raspbian, and after starting/restarting Node-RED I can see the connection to the Azure IoT Hub with lsof:

pi@raspberrypi:~ $ sudo lsof -i  | grep node
node-red   3922          pi   10u  IPv4 234336      0t0  TCP 192.168.1.50:42940->104.40.179.185:amqps (ESTABLISHED)
node-red   3922          pi   11u  IPv4 234307      0t0  TCP *:1880 (LISTEN)
node-red   3922          pi   13u  IPv4 234339      0t0  TCP 192.168.1.50:1880->COPERNICIUM:51644 (ESTABLISHED)

The connection 192.168.1.50:42940->104.40.179.185:amqps is the one to the Azure IoT Hub server. Wenn receiving of messages does no longer occur, this connection is gone, without any error in the system logs.

I found the following issue that sounds similarly to what I'm seeing:

https://github.com/Azure/azure-event-hubs/issues/184

So is the receiver functionality in the Azure Event Hub Client for Node.js unreliable in general?

[jantielens]

Hi @smuehlst, thanks for reporting this. I need some time to investigate. Will keep you posted!

[jantielens]

@smuehlst I'm trying to replicate here. Can you give me an idea after how long (minutes, hours ...) this error occurs. Do you have a complete output log of Node-Red you can share? Thx!

[smuehlst]

@jantielens Thanks for looking into this!
It can take days until this occurs. This is the Node-RED log from yesterday from one restart to another, and the error happened at 19:03:26:

Feb 27 17:10:15 raspberrypi Node-RED[5295]: 27 Feb 18:10:15 - [info]
Feb 27 17:10:15 raspberrypi Node-RED[5295]: Welcome to Node-RED
Feb 27 17:10:15 raspberrypi Node-RED[5295]: ===================
Feb 27 17:10:15 raspberrypi Node-RED[5295]: 27 Feb 18:10:15 - [info] Node-RED version: v0.18.3
Feb 27 17:10:15 raspberrypi Node-RED[5295]: 27 Feb 18:10:15 - [info] Node.js  version: v8.9.4
Feb 27 17:10:15 raspberrypi Node-RED[5295]: 27 Feb 18:10:15 - [info] Linux 4.9.59+ arm LE
Feb 27 17:10:22 raspberrypi Node-RED[5295]: 27 Feb 18:10:22 - [info] Loading palette nodes
Feb 27 17:10:55 raspberrypi Node-RED[5295]: 27 Feb 18:10:55 - [info] Dashboard version 2.8.1 started at /ui
Feb 27 17:10:56 raspberrypi Node-RED[5295]: 27 Feb 18:10:56 - [info] Settings file  : /home/pi/.node-red/settings.js
Feb 27 17:10:56 raspberrypi Node-RED[5295]: 27 Feb 18:10:56 - [info] User directory : /home/pi/.node-red
Feb 27 17:10:56 raspberrypi Node-RED[5295]: 27 Feb 18:10:56 - [info] Server now running at http://127.0.0.1:1880/
Feb 27 17:10:57 raspberrypi Node-RED[5295]: 27 Feb 18:10:57 - [info] Active project : larch
Feb 27 17:10:57 raspberrypi Node-RED[5295]: 27 Feb 18:10:57 - [info] Flows file     : /home/pi/.node-red/projects/larch/flows_COPERNICIUM.json
Feb 27 17:10:57 raspberrypi Node-RED[5295]: 27 Feb 18:10:57 - [info] Starting flows
Feb 27 17:10:59 raspberrypi Node-RED[5295]: 27 Feb 18:10:59 - [info] Started flows
Feb 27 17:11:02 raspberrypi Node-RED[5295]: 27 Feb 18:11:02 - [info] [azure-event-hub-receive:radmonaut] Created partition receiver: 1
Feb 27 17:11:02 raspberrypi Node-RED[5295]: 27 Feb 18:11:02 - [info] [azure-event-hub-receive:radmonaut] Created partition receiver: 0
Feb 27 19:03:26 raspberrypi Node-RED[5295]: 27 Feb 20:03:26 - [error] [azure-event-hub-receive:radmonaut] The message container is being closed (47363). TrackingId:<... id removed ...>, SystemTracker:NoSystemTracker, Timestamp:2/27/2018 7:03:26 PM
Feb 27 21:00:50 raspberrypi systemd[1]: Stopping Node-RED graphical event wiring tool....

What happens once a day and what maybe shadows the above error is what I described in my second comment. Apparently every day at around 04:30 h receiving of messages stops without any error in the log file, and the TCP/IP connections is gone. This happens from my home network with a DSL connection, and I am now pretty sure that this is the forced disconnect from my DSL provider that happens once in 24 hours.