openLuup email server

[ArcherS]

@akbooer yes Homewave works as it should. At times it is a bit slow to connect, usually quite ok.

I have enabled Historian and have connected it to Grafana in which I have some graphs.

@rafale77 I tried to switch between cellular&vpn and wifi with Homewave and it seems to work without crashing OpenLuup. I am using Qvpn from Qnap.

[rafale77]

@archers

Any update?

I just inadvertently stress tested openLuup's socket after all the updates this morning:

I went working in the yard cutting wood this morning which trips my ipcam motion sensor which then trips HomeAssistant object detection which then scans my camera stream using a deep learning model and when it detects a person sends an http call to openLuup to trip a security sensor on which I run a scene to do other things ranging from notifications to announcement depending on housemode etc... This happens at a rate of 5Hz (one call every 200ms)... You can see that the high frequency of http calls on top of the regular polling (I poll z-way at rate of 2Hz for example) made openLuup's CPU utilization jump! yet no crash...

Edit: And I checked the log to discover a lot more errors of sending bytes to a closed connection but as I said, it handled like a champ.

[akbooer]

5% peak load? Shameful!

I’ve been stress testing too, and haven’t been able to make anything crash recently. I’m crafting a new Docker to take over from my main, and ageing, BeagleBone Black system, and the I/O there just whistles along with cpu at under 0.2%. I also see that RapidJson is available as a standard install of Alpine, so I may include that.

My conclusion, following yours, is that this is low-level LuaSocket issues on out of date libraries, which only show a problem when moderately stressed. I don’t think there’s anything more I can do at the openLuup coding level.

[rafale77]

@akbooer said in OpenLuup unavailable:

5% peak load? Shameful!

I know! right? lol! As you know I optimize things to the edge... running on luajit, having turned JIT back on and rapidjson which I highly recommend over cjson because it enables not having to failover to dkjson if you so desire. I also regularly look at library updates which admittedly for lua, are sadly rare. I even tested a number of forks of luajit and found nothing worth the trouble at this point.

[ArcherS]

@rafale77 @akbooer two days ago the system was quite slow and non-responsive. I then decided to disable the Mqtt server in OpenLuup to see what would happen. Now after two days no crash, so it seems as if this is somehow casing the crashes. Small progress perhaps.

Edit:
What I still have noticed is that the system has been quite slow on v21.3.25b and v2.3.24b with at times very long response times. Much worse that what it was 3-4 days ago for some reason, before updating from v2.3.21 to v2.3.24b.
On 2.3.21 the system was quite snappy, but after some time crashed without warning.
Now I updated to 21.3.26 and so far it seems much more responsive that on v2.3.24b / v21.3.25b.

I thought I would updated the Lua sockets libraries, LuaFileSystem etc to the latest versions, but now I cannot find the openLuup > System > Required list list.
This is what I had alst time I checked a week ago:

Hints on what to update and how to do it much appreciated.

Edit: The update to 21.3.26 initially seems to have made the system more repsonsive for whatevere reason. Good news, let's see if it stays like that.
I see that I am on LuaFileSystem 1.6.3 that seems to be from 2015 and @rafale77 you are on 1.8.0 that is from 2020. This seems like something that could need updating.

[rafale77]

@archers

Yeah @akbooer has moved that section under tables/luup files

I know that only because I checked the code changes...

[ArcherS]

@rafale77 yepp, still on the same versions:

[rafale77]

Just in case you would want to know how to update these libraries:
Need to install luarocks. This depends on what machine you are using but assuming you are on a debian base,

sudo apt-get install luarocks

will do it. then you can start upgrading things:

LuaFileSystem - LuaRocks

[ArcherS]

@rafale77 I am on Ubuntu 18.04 so googling says:

sudo apt update
sudo apt install luarocks

[akbooer]

@rafale77 said in OpenLuup unavailable:

Yeah @akbooer has moved that section under tables/luup files

Sorry! Yes, in fact they were duplicates (almost) and Files seemed a better place than System.

[akbooer]

@archers said in OpenLuup unavailable:

Much worse that what it was 3-4 days ago for some reason. Then the system was quite snappy, but after some time. This was on v21.3.25b, now I updated to 21.3.26, I will see if ot continues to be slow.

OK, I have a possible answer to that. The system wait for up to a specified period of time if it fins that a socket is not ready to send. Initially, I used a timeout of zero (v21.3.24) bad choice, since most things timed out. Changed it to 0.2 seconds (v21.3.24b) , and later, then to 1.0 seconds (v21.3.26).

I will rever to something smaller, perhaps 0.1s. But you can change this (for the HTTP server) with:

luup.attr_set ("openLuup.HTTP.SelectWait", 0.1)

Again, apologies, but your excellent reporting of the effect of these changes is a very efficient way for me to zero in on issues, for which, thanks.

[ArcherS]

@akbooer thanks! I see that my text above got a bit incomplete.

This is how it should be ( I think, many updates lately ) :
What I still have noticed is that the system has been quite slow on v21.3.25b and v2.3.24b with at times very long response times. Much worse that what it was 3-4 days ago for some reason, before updating from v2.3.21 to v2.3.24b.
On 2.3.21 the system was quite snappy, but after some time crashed without warning.
Now I updated to 21.3.26 and so far it seems much more responsive that on v2.3.24b / v21.3.25b.

For clarity I edited the post above also.

[ArcherS]

@rafale77 LuaFileSystem 1.8.0 Installed:

What I did was:

sudo apt update
sudo apt install luarocks
sudo luarocks install luafilesystem

I will keep it running without eabling Mqtt for a while and see if it seems stable.

[rafale77]

While you are at it, I would recommend you upgrade luasec (ssl) as well.

[akbooer]

@rafale77 said in OpenLuup unavailable:

would recommend you upgrade luasec (ssl) as well

No harm in that, although we're not using SSL in this exercise, AFAIK.

[ArcherS]

A short status update.

Yesterday evening I updated OpenLupp to v21.3.26 and LuaFileSystem to 1.8.0.
I have since then left the system up and running as-is, i.e. without Mqtt re-enabled and with most of the http updates from my various Tasmota devices turned off.

So far so good, the system seems as responsive as it has been earlier for the past approx 20 hours.
I have not changed the http server waiting time, it is at the default value for v21.3.26.

When looking in the logs, it looks ok. Usually quite fast responses and no errors.

I found two similar lines that had a bit longer response time:

2002 lines, 0 errors, max gap 41s @ 2021-03-28 17:30:00.131

2021-03-28 17:29:18.910   luup.variable_set:: 10909.urn:micasaverde-com:serviceId:HaDevice1.sl_BatteryAlarm was: 0 now: 0 #hooks:0
2021-03-28 17:30:00.131   luup_log:0: 40Mb, 3.5%cpu, 0.8days
2021-03-28 17:30:00.646   luup.variable_set:: 68.urn:toggledbits-com:serviceId:ReactorSensor.cstate was: {"cond0":{"evaledge":[],"stateedge":[],"valuestamp":1615722020,"id":"cond0","statestamp":0,"lastvalue":0},"vars":{"... now: {"cond0":{"evaledge":[],"stateedge":[],"valuestamp":1615722020,"id":"cond0","statestamp":0,"lastvalue":0},"vars":{"... #hooks:0


2002 lines, 0 errors, max gap 65s @ 2021-03-28 16:54:07.724

2021-03-28 16:53:02.682   luup.variable_set:: 244.urn:toggledbits-com:serviceId:VirtualSensor1.LastUpdate was: 1616943122 now: 1616943182 #hooks:0
2021-03-28 16:54:07.724   luup_log:0: 44Mb, 1.5%cpu, 0.7days
2021-03-28 16:54:07.755   luup.variable_set:: 122.urn:toggledbits-com:serviceId:DelayLightTimer.Message was: Delay Off 9m now: Delay Off 8m #hooks:0

I will keep off the system until tomorrow to see that it is stable over time before I restart the Mqtt server.

[akbooer]

Nothing to worry about with those logs. Anything under 120s is fine.

[ArcherS]

I looked in the logs again after I had some slow responses in the system and found some errors. The IP address 192.168.1.127 this my iPhone and Homewave. I tested with Homewave on my iPad and got a similar set of errors for that IP address. These errors seem to be in the direction of what @rafale77 mentioned.

Edit: Still had some errors so I changed it to 0.1 which seems to give even fewer errors.
I changed the http server wait to 0.2 0.1 from 1.0 with luup.attr_set ("openLuup.HTTP.SelectWait", 0.1) and it seems as if it may have helped removing the errors. I will check some more later on and see if the errors return.

From the log file:

2021-03-28 19:58:23.148   openLuup.server:: error 'closed' sending 2 bytes to tcp{client}: 0x55979ef92ba8
2021-03-28 19:58:23.148   openLuup.server:: error 'closed' sending 6 bytes to tcp{client}: 0x55979ef92ba8
2021-03-28 19:58:23.148   openLuup.server:: error 'closed' sending 858578 bytes to tcp{client}: 0x55979ef92ba8
2021-03-28 19:58:23.148   openLuup.server:: error 'closed' sending 2 bytes to tcp{client}: 0x55979ef92ba8
2021-03-28 19:58:23.149   openLuup.server:: error 'closed' sending 5 bytes to tcp{client}: 0x55979ef92ba8
2021-03-28 20:01:02.561   openLuup.server:: error 'closed' sending 4 bytes to tcp{client}: 0x55979f3f9768
2021-03-28 20:01:02.561   openLuup.server:: error 'closed' sending 104 bytes to tcp{client}: 0x55979f3f9768
2021-03-28 20:01:02.561   openLuup.server:: error 'closed' sending 2 bytes to tcp{client}: 0x55979f3f9768
...


2021-03-28 19:58:21.155   openLuup.io.server:: HTTP:3480 connection from 192.168.1.127 tcp{client}: 0x55979ef92ba8

2021-03-28 20:01:00.882   openLuup.io.server:: HTTP:3480 connection from 127.0.0.1 tcp{client}: 0x55979f3f9768

2021-03-28 19:58:22.954   luup_log:203: VirtualBinaryLight[2.40@203]:[updateMeters] Watts Path: "meters[1].power" - Value: 0

2021-03-28 19:58:23.148   openLuup.server:: error 'closed' sending 2 bytes to tcp{client}: 0x55979ef92ba8

2021-03-28 19:58:23.148   openLuup.server:: ...only 0 bytes sent

2021-03-28 19:58:23.148   openLuup.server:: error 'closed' sending 6 bytes to tcp{client}: 0x55979ef92ba8

2021-03-28 19:58:23.148   openLuup.server:: ...only 0 bytes sent

2021-03-28 19:58:23.148   openLuup.server:: error 'closed' sending 858578 bytes to tcp{client}: 0x55979ef92ba8

2021-03-28 19:58:23.148   openLuup.server:: ...only 64000 bytes sent

2021-03-28 19:58:23.148   openLuup.server:: error 'closed' sending 2 bytes to tcp{client}: 0x55979ef92ba8

2021-03-28 19:58:23.148   openLuup.server:: ...only 0 bytes sent

2021-03-28 19:58:23.149   openLuup.server:: error 'closed' sending 5 bytes to tcp{client}: 0x55979ef92ba8

2021-03-28 19:58:23.149   openLuup.server:: ...only 0 bytes sent
2021-03-28 19:58:23.149   openLuup.server:: request completed (858578 bytes, 5 chunks, 446 ms) tcp{client}: 0x55979ef92ba8

[ArcherS]

I have now had the Mqtt server up and running for approx 30 hours without any crashes so far, a step in the right direction as it seems.

I am still on OpenLuup version: v21.3.26 and LuaFileSystem v1.8.0 (luasec not updated), want to keep the setup as-is to see what happens over longer time.

So far only one Tasmota device connected via Mqtt reporting every minute.
No errors in the log files (except for Homewave, see below), max response time usually approx 16 seconds. Changing the http wait to 0.1 was a big change. With 1.0 OpenLuup was sluggish and there is a noticable difference also when comparing to 0.2.
With 0.1 the system is much better.

Messages as displayed by MqttExplorer:

I have noticed two brief Mqtt disconnects during this time.
Log file:

1575 lines, 0 errors, max gap 75s @ 2021-03-29 13:35:48.179

2021-03-29 13:34:33.581   luup.variable_set:: 216.urn:upnp-org:serviceId:TemperatureSensor1.CurrentTemperature was: 25.3 now: 25.4 #hooks:0
2021-03-29 13:34:33.582   luup.variable_set:: 228.urn:micasaverde-com:serviceId:HumiditySensor1.CurrentLevel was: 36.1 now: 36.1 #hooks:0
2021-03-29 13:35:48.179   openLuup.io.server:: MQTT:1883 connection from 192.168.1.60 tcp{client}: 0x5652106f2f48
2021-03-29 13:35:48.180   openLuup.io.server:: HTTP:3480 connection closed EXPIRED tcp{client}: 0x56520e9d91c8
2021-03-29 13:35:48.180   openLuup.io.server:: MQTT:1883 connection closed EXPIRED tcp{client}: 0x565210622978
2021-03-29 13:35:48.180   openLuup.mqtt:: mqtt-explorer-22233d66 UNSUBSCRIBE from # tcp{client}: 0x565210622978
2021-03-29 13:35:48.180   openLuup.mqtt:: mqtt-explorer-22233d66 UNSUBSCRIBE from $SYS/# tcp{client}: 0x565210622978

Log from the Tasmota device console:

12:43:08 MQT: tele/tasmota_test/SENSOR = {"Time":"2021-03-29T12:43:08","AM2301":{"Temperature":25.4,"Humidity":36.1,"DewPoint":9.3},"TempUnit":"C"}
12:43:33 MQT: Attempting connection...
12:43:48 MQT: Connect failed to 192.168.1.107:1883, rc -4. Retry in 10 sec
12:43:59 MQT: Attempting connection...
12:44:10 MQT: Connected
12:44:10 MQT: tele/tasmota_test/LWT = Online (retained)
12:44:10 MQT: cmnd/tasmota_test/POWER = 
12:44:33 MQT: tele/tasmota_test/STATE = {"Time":"2021-03-29T12:44:33","Uptime":"0T01:05:15","UptimeSec":3915,"Heap":26,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":4,"Wifi":{"AP":1,"SSId":"BeachAC","BSSId":"FC:EC:DA:D1:7A:64","Channel":11,"RSSI":100,"Signal":-50,"LinkCount":1,"Downtime":"0T00:00:03"}}

It reconnected without problem quite fast, so that seems to be fine.

I have not used Homewave very much during this time, but it also seems to work ok. However I do see errors for it when I use it. So something is not 100% right there perhaps. I got more errors with a longer http wait (1.0 >> 0.2 > 0.1).
Log file:

2021-03-30 20:10:47.908   openLuup.server:: request completed (5907 bytes, 1 chunks, 194 ms) tcp{client}: 0x565210f173b8
2021-03-30 20:10:48.260   openLuup.server:: GET /data_request?output_format=json&id=lu_status HTTP/1.1 tcp{client}: 0x5652108936d8

2021-03-30 20:10:48.484   openLuup.server:: error 'socket.select() not ready to send tcp{client}: 0x5652108936d8' sending 2 bytes to tcp{client}: 0x5652108936d8

2021-03-30 20:10:48.563   openLuup.server:: request completed (858554 bytes, 54 chunks, 302 ms) tcp{client}: 0x5652108936d8
2021-03-30 20:10:48.932   openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=14594009&Timeout=60&MinimumDelay=1500&_=1617014398016 HTTP/1.1 tcp{client}: 0x565210f173b8
2021-03-30 20:10:49.068   openLuup.server:: request completed (5909 bytes, 1 chunks, 135 ms) tcp{client}: 0x565210f173b8

[akbooer]

Well, that seems like a step in the right direction.

I, too, have been pressing on MQTT, and all seems well. Disconnects happen when the iMac that I’m using to run Explorer goes to sleep, but reconnects when it wakes up, as expected. Current stats look like this: