"Event queue full" Error after 10 minutes of usage

[mikkot]

Hi,

I started to experience "Event queue full" errors lately. I suspect this might have something to do with the fact that I have a DIY MQTT sensor that is publishing messages every 10 seconds to a topic ONH listens to.

I'm running the latest nightly.

This is what I get in the log
7.09.10 18:39:37 HomeServer Event queue full. Current Item processing is "Philips HUE Bridge" since 121.48 ms
17.09.10 18:39:37 HomeServer Event queue full. Current Item processing is "Philips HUE Bridge" since 79.54 ms
17.09.10 18:39:37 HomeServer Event queue full. Current Item processing is "Philips HUE Bridge" since 46.61 ms
17.09.10 18:39:37 HomeServer Event queue full. Current Item processing is "Keittiö ruokapöytä keski" since 7000.83 ms
17.09.10 18:39:35 HomeServer Event queue full. Current Item processing is "Keittiö ruokapöytä keski" since 5174.72 ms
17.09.10 18:36:01 HomeServer Failed to distribute event to "Lämpötila OH #1" (event,Mqtt_Message,Direction,In,Mqtt.Message,23.00 MyHome/LivingRoom/Sensor1/Li,Mqtt.Topic,MyHome/LivingRoom/Sensor1/Temperature,Value,)
17.09.10 18:30:07 TCPCommandPort$Session Disconnected from 127.0.0.1
17.09.10 18:30:07 TCPCommandPort Connection from 127.0.0.1
17.09.10 18:29:34 UPMThermometer Low battery for Ulkolampotila
17.09.10 18:29:34 UPMHygrometer Low battery for Kosteus tyohuone
17.09.10 18:29:23 HomeServer Activated 131 of 137 Items
17.09.10 18:29:08 TrayBarIcon SystemTray is not supported on this system
17.09.10 18:29:07 H2DatabaseTCPServer Started the H2 web server at: https://192.168.1.99:8082, Web Console server running at http://127.0.1.1:8082 (others can connect)
17.09.10 18:29:06 H2DatabaseTCPServer Started the H2 database server at: tcp://127.0.1.1:9092
17.09.10 18:29:05 DTLSConnector Unexpected error occurred while processing record from peer [/192.168.1.52:5684]
17.09.10 18:29:00 MqttClient Connected to MQTT Server tcp://localhost
17.09.10 18:28:57 IkeaGatewayClient Timeout waiting for response from IKEA GW coaps://192.168.1.52/15001
17.09.10 18:28:56 DTLSConnector DTLS connector listening on [{0}] with MTU [{1}] using (inbound) datagram buffer size [{2} bytes]
17.09.10 18:28:56 CoapEndpoint Starting endpoint at 0.0.0.0/0.0.0.0:0
17.09.10 18:28:56 NetworkConfig Error while storing properties to /opt/nethome/lib/Californium.properties
17.09.10 18:28:56 NetworkConfig Storing standard properties in file Californium.properties
17.09.10 18:28:41 HomeItemFileLoader Loading Items from /etc/opt/nethome/config.xml
17.09.10 18:28:40 HomeManagerStarter Logging to: /var/log/nethome/HomeManager%g.log
17.09.10 18:28:40 HomeManagerStarter **Starting HomeManager 3.0-fcb8f**

And this is what I see in the "Detected devices" window under "Create/Edit" view

Identity Create Time since Item Exists
Ikea CT Lamp 65542: "Keittiö katto 1.1" Create Item 17 Sec Existing
Ikea CT Lamp 65545: "Keittiö katto 2.2" Create Item 17 Sec Existing
Ikea CT Lamp 65539: "Keittiö katto 1.4" Create Item 17 Sec Existing
Ikea CT Lamp 65544: "Keittiö katto 2.3" Create Item 17 Sec Existing
Ikea CT Lamp 65543: "Keittiö katto 2.4" Create Item 17 Sec Existing
Ikea CT Lamp 65537: "Ruokapöytä 2" Create Item 17 Sec Existing
Ikea CT Lamp 65541: "Keittiö katto 1.2" Create Item 17 Sec Existing
Ikea CT Lamp 65546: "Keittiö katto 2.1" Create Item 17 Sec Existing
Ikea CT Lamp 65540: "Keittiö katto 1.3" Create Item 17 Sec Existing
IKEA Trådfri gateway: "gw:a0-cc-2b-f5-bb-f7" Create Item 17 Sec Existing
Philips Hue lamp 3: "Hue color lamp 3" Create Item 8 Sec Existing
Philips Hue lamp 2: "Hue color lamp 2" Create Item 8 Sec Existing
Philips Hue lamp 1: "Hue color lamp 1" Create Item 8 Sec Existing
Philips Hue bridge: "Philips hue (192.168.1.51)" Create Item 17 Sec Existing
Mqtt:Message=425 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 1 Min 3 Sec Existing
Mqtt:Message=426 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 8 Min 57 Sec Existing
UPM:DeviceCode=1,HouseCode=7 Create Item 18 Sec Existing
UPM:DeviceCode=1,HouseCode=6 Create Item 11 Sec Existing
UPM:DeviceCode=1,HouseCode=5 Create Item 10 Sec Existing
Mqtt:Message=Ping ,Topic=MyHome/LivingRoom/Sensor1/STATUS Create Item 3 Sec Existing
Mqtt:Message= 36.00 ,Topic=MyHome/LivingRoom/Sensor1/Humidit... Create Item 14 Min 9 Sec Existing
Mqtt:Message=23.00 ,Topic=MyHome/LivingRoom/Sensor1/Temperat... Create Item 3 Sec Existing
UPM:DeviceCode=1,HouseCode=1 Create Item 8 Sec Existing
Mqtt:Message=424 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 8 Min 16 Sec Existing
Mqtt:Message=ping,Topic=MyHome/LivingRoom/Sensor1/ESP8266out... Create Item 46 Sec Existing
Mqtt:Message=408 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 13 Min 39 Sec Existing
UPM:DeviceCode=1,HouseCode=2 Create Item 33 Sec Existing
Mqtt:Message=431 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 3 Min 34 Sec Existing
Mqtt:Message= 35.00 ,Topic=MyHome/LivingRoom/Sensor1/Humidit... Create Item 12 Min 8 Sec Existing
Mqtt:Message=416 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 11 Min 38 Sec Existing
Mqtt:Message=435 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 1 Min 54 Sec Existing
Mqtt:Message=430 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 2 Min 4 Sec Existing
Mqtt:Message=400 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 11 Min 58 Sec Existing
Mqtt:Message=422 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 43 Sec Existing
Mqtt:Message=423 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 2 Min 54 Sec Existing
Mqtt:Message= 34.00 ,Topic=MyHome/LivingRoom/Sensor1/Humidit... Create Item 3 Sec Existing
Mqtt:Message=428 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 9 Min 7 Sec Existing
Mqtt:Message=414 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 10 Min 47 Sec Existing
Mqtt:Message=399 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 10 Min 37 Sec Existing
Mqtt:Message=429 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 3 Sec Existing
Mqtt:Message=413 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 6 Min 31 Sec Existing
Mqtt:Message=23.00 MyHome/LivingRoom/Sensor1/Li,Topic=MyHom... Create Item 10 Min 7 Sec Existing
Mqtt:Message=427 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 2 Min 24 Sec Existing
Mqtt:Message=436 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 9 Min 17 Sec Existing
Mqtt:Message=404 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 8 Min 36 Sec Existing
Mqtt:Message=410 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 6 Min 31 Sec Existing
Mqtt:Message=421 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 4 Min 45 Sec Existing
Mqtt:Message=415 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 6 Min 31 Sec Existing
Mqtt:Message= 33.00 ,Topic=MyHome/LivingRoom/Sensor1/Humidit... Create Item 6 Min 5 Sec Existing
Mqtt:Message=25.00 ,Topic=MyHome/LivingRoom/Sensor1/Temperat... Create Item 6 Min 5 Sec Existing
Mqtt:Message=412 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 23 Sec Existing
UPM:DeviceCode=1,HouseCode=4 Create Item 6 Min 0 Sec Existing
Mqtt:Message=21.6,Topic=MyHome/BedroomJanna/Sensor1/Temperat... Create Item 6 Min 0 Sec Existing
Mqtt:Message=411 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 5 Min 25 Sec Existing
Mqtt:Message=420 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 2 Min 34 Sec Existing
Mqtt:Message=407 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 5 Min 35 Sec Existing
Mqtt:Message=22.5,Topic=MyHome/Bathroom/Sensor1/Temperature Create Item 5 Min 13 Sec Existing
Mqtt:Message=22.7,Topic=MyHome/Bathroom/Sensor1/Temperature Create Item 5 Min 8 Sec Existing
Mqtt:Message=418 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 13 Sec Existing
Mqtt:Message=417 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 33 Sec Existing
Mqtt:Message=21.9,Topic=MyHome/Bathroom/Sensor1/Temperature Create Item 3 Min 8 Sec Existing
Mqtt:Message=23.1,Topic=MyHome/Bathroom/Sensor1/Temperature Create Item 2 Min 8 Sec Existing
Mqtt:Message=419 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 53 Sec Existing
Mqtt:Message=409 ,Topic=MyHome/LivingRoom/Sensor1/Lightness Create Item 1 Min 34 Sec Existing
Mqtt:Message=22.6,Topic=MyHome/Bathroom/Sensor1/Temperature Create Item 1 Min 8 Sec Existing
Mqtt:Message=22.0,Topic=MyHome/Bathroom/Sensor1/Temperature Create Item 8 Sec Existing

As it can be seen, the event queue gets full after about 10 minutes.

How to fix this? After the queue gets full most of the functionality is quite unreliable.

Thx!

BR,
Mikko

[stefangsbb]

Hmmm, this looks a bit bad. It might be because creation messages get repeated. I added filtering for the MQTT-Message attribute now , so that won't happen. The change is in the nightly build, so you can try it out. If that does not help, please send me the logfile, so I can get more detailed information.

[mikkot]

Hi Stefan,

I upgraded to the latest nightly build. Unfortunately the problem remains. I sent you some log via email.

Thanks!

BR,
Mikko

[stefangsbb]

Hi Mikko

I looked at the log, and I actually get the impression that you are overloading the server a bit.

Locking at the warnings started at 2017.09.12 20:41:37.487, there is warnings that are less than 20 ms apart, meaning that there are events coming in at a rate of 50 events per second. Since they time out on the IKEA GW and the HUE Bridge, I am guessing that there is actually some chain of events where an incoming event trigger some action on a lamp that in turn triggers a new event to the gateway, and that the events come in at such a rate that the server have no time to process them and the queue gets full.

It would probably be possible to increase the capacity of the server by having buffers at Items that communicate with external network nodes like the IKEA GW and the Philips Hue, but the server is not really built for high data rates. Would it be possible to limit the incoming data rates a bit in your case?

I Increased the queue size a bit in the nightly build, so you can try that out - but that is just a temporary fix. The real solution is to limit the incoming data rate (or implement better buffering in the sending Items).
The risk with buffering is that the gateway items will collect large buffers, and if you at that point manually want to turn a lamp on or off, you will have to wait until that command has gone through the buffer queue and the system will feel slow and unresponsive.

[mikkot]

Hi Stefan,

Most of the mqtt load is caused by a single sensor (lightness meter) that is bombarding the mqtt broker every 10s. That's probably unnecessary for most of the use cases. It can be changed to every 1min or 5min instead, but would be only a temporary fix again. There will be more an more sensors coming. The IoT is here, you know

But ok, I can do something with it.

For the long term solution I might need to start thinking of ways to balance the load. Maybe running two parallel ONHs instances to share tasks. I guess it's already doable today e.g. with REST API or TCP Command port. Just need to think about how to configure it. Do you think this would help?

BR,
Mikko

[stefangsbb]

Well, I am not sure that you have full control what really happens every ten seconds... Your logs show that you seem to receive bursts of events at a high rate. If these bursts come every 10 seconds, every minute or every 24 hours does not matter - the server will anyway choke when the burst comes.

One thing you can do to get an understanding of what is happening is to create a TCPCommandPort, telnet to that port and type "subscribe" to see all events that are sent in the system. Then you will get some idea of what is happening.

The problem is not really the performance of the server as such, rather how fast the connected devices are. If the Philips HUE bridge can only send 10 commands per second to the lamps, but you are generating 50 commands per second - then it does not matter how fast the server is, the commands will queue up somewhere (queue growing with 40 commands per second) and at some point the sever will not allow this queue to grow any more (to avoid the whole system to lock up) and then the server starts throwing away commands (events) and that is the messages you are seeing. The current event queue size is 30 events (I increased from 20).

[mikkot]

Hmm, I did the telnet/subcribe. I have

• 5-6 temp/humidity sensors. They seem to send 3 events at a time each (once per minute). Each of these then trigger MQTT message to be sent to mosquitto for other systems to get the data too

• Philips HUE bridge has 3 lamps configured into it. For each lamp the bridge seem to send (status?) events once per minute or close to that.

• An MQTT temp/humidity sensor sending MQTT messages every minute

• An MQTT brightness sensor sending MQTT messages every 10 seconds

• IKEA GW with ~10 lamps. Every 10 minutes the GW seems to send a LONG list of xml formatted statuses. For each bulbs there's an event coming with quite a few lines of info.

Furthermore I'm no longer seeing the "queue full" error in the log. Could it be that it was IKEA causing this? Now when the buffer is bigger, the server can handle the burst coming from IKEA GW every ten minutes.

I don't think my setup is that huge. I'm planning to double or triple the amount of Trådfri stuff in near future making the "IKEA burst" 2-3 times bigger too.

BR,
Mikko