Unexpected stop of openLuup
-
@crille said in Unexpected stop of openLuup:
I don't know if VeraBridge is running asynchronous, is that relevant too?
Yes, it's relevant. Synchronous polling takes a lot of time out from other things.
Check the VeraBridge variable AsyncPoll, if it's not set to true then you should try doing so (and reloading.)
-
@akbooer Ok. Thanks ,I changed it to true (was at, I guess default, false) and reloaded. Let’s hope that do good to the system.
I still always get errors after a reload though.
2021-08-20 23:44:09.048 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x55b0530b79b8 2021-08-20 23:44:09.049 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x55b0533b7bc8 2021-08-20 23:44:09.300 openLuup.server:: error 'socket.select() not ready to send tcp{client}: 0x55b0526b00d8' sending 2 bytes to tcp{client}: 0x55b0526b00d8
-
@akbooer I join in here since I have had some similar problems.
My Zway bridge has been running in asyc mode for long, however I checked my Vera bridge and it was not. I have changed it, but since I have no devices left on the Vera I thought that I just as well should remove it from OpenLuup to unload it a bit.
What is the best way of doing that? Just to delete the brigde device in OpenLuup and reload? -
Yup, just that.
-
Today I got a new crash. This time in the middle of the day. OpenLuup was not doing anything specific, I was not doing anything with it, no irregular cpu load (approx 3.6%). No errors in the log before what is shown below. Mqtt Explorer was not on either, so regular load there as well. (This was also before I tried with Mqtt from Home Assistant to OpenLuup, as described in another thread.)
I discovered a few hours later that the server had crashed. When checking the logs this is what I could see:
2021-09-17 11:04:36.136 openLuup.io.server:: MQTT:1883 connection from 192.168.1.144 tcp{client}: 0x29b5f80 2021-09-17 11:04:36.136 openLuup.io.server:: MQTT:1883 connection from 192.168.1.66 tcp{client}: 0x3136a28 2021-09-17 11:04:36.136 openLuup.io.server:: MQTT:1883 connection from 192.168.1.59 tcp{client}: 0x30932b0 2021-09-17 11:04:36.137 openLuup.io.server:: MQTT:1883 connection from 192.168.1.52 tcp{client}: 0x3671eb8 2021-09-17 11:04:36.137 openLuup.io.server:: MQTT:1883 connection from 192.168.1.51 tcp{client}: 0x3506688 2021-09-17 11:04:36.137 openLuup.io.server:: MQTT:1883 connection from 192.168.1.58 tcp{client}: 0x3005fa8 2021-09-17 11:04:36.182 luup.variable_set:: 144.urn:toggledbits-com:serviceId:ReactorValues.SpabadCut was: 349 now: 345 #hooks:1 2021-09-17 11:04:36.190 luup.variable_set:: 144.urn:toggledbits-com:serviceId:ReactorSensor.cstate was: {"cond0":{"evaledge":[],"stateedge":[],"valuestamp":1631631832,"id":"cond0","statestamp":0,"lastvalue":0},"root":{"... now: {"cond0":{"evaledge":[],"stateedge":[],"valuestamp":1631631832,"id":"cond0","statestamp":0,"lastvalue":0},"root":{"... #hooks:0 2021-09-17 11:04:36.191 luup.variable_set:: 144.urn:toggledbits-com:serviceId:ReactorSensor.lastacc was: 1631869442 now: 1631869476 #hooks:0 2021-09-17 11:04:36.191 luup.variable_set:: 144.urn:toggledbits-com:serviceId:ReactorGroup.GroupStatus_grp1b0eboj1 was: 1 now: 0 #hooks:0 2021-09-17 11:04:36.191 luup.variable_set:: 144.urn:toggledbits-com:serviceId:ReactorSensor.Message was: Not tripped now: Not tripped #hooks:0 2021-09-17 11:04:36.194 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x2a6a020 2021-09-17 11:04:36.195 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x2a6a020 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaFriggebod UNSUBSCRIBE from cmnd/TasmotaFriggebod_fb/# tcp{client}: 0x2a6a020 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaFriggebod UNSUBSCRIBE from cmnd/TasmotaFriggebod/# tcp{client}: 0x2a6a020 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaFriggebod UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x2a6a020 2021-09-17 11:04:36.195 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x2978900 2021-09-17 11:04:36.195 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x2978900 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaSjo UNSUBSCRIBE from cmnd/TasmotaSjo_fb/# tcp{client}: 0x2978900 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaSjo UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x2978900 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaSjo UNSUBSCRIBE from cmnd/Tasmota_Sjo/# tcp{client}: 0x2978900 2021-09-17 11:04:36.195 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x2c12be0 2021-09-17 11:04:36.195 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x2c12be0 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaIR UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x2c12be0 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaIR UNSUBSCRIBE from cmnd/TasmotaIR_fb/# tcp{client}: 0x2c12be0 2021-09-17 11:04:36.195 openLuup.mqtt:: TasmotaIR UNSUBSCRIBE from cmnd/TasmotaIR/# tcp{client}: 0x2c12be0 2021-09-17 11:04:36.210 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x30c6558 2021-09-17 11:04:36.210 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x30c6558 2021-09-17 11:04:36.210 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x395fb70 2021-09-17 11:04:36.210 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x395fb70 2021-09-17 11:04:36.210 openLuup.mqtt:: TasmotaGarage UNSUBSCRIBE from cmnd/TasmotaGarage_fb/# tcp{client}: 0x395fb70 2021-09-17 11:04:36.210 openLuup.mqtt:: TasmotaGarage UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x395fb70 2021-09-17 11:04:36.210 openLuup.mqtt:: TasmotaGarage UNSUBSCRIBE from cmnd/TasmotaGarage/# tcp{client}: 0x395fb70 ... 2021-09-17 11:04:36.219 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x29b5f80 2021-09-17 11:04:36.219 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x29b5f80 2021-09-17 11:04:36.219 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x3136a28 2021-09-17 11:04:36.219 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x3136a28 2021-09-17 11:04:36.223 luup.watch_callback:: 20013.MHZ19B.CarbonDioxide called [9]virtualSensorWatchCallback() function: 0x263bea8 ... 2021-09-17 11:04:36.243 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x2b7aff8 2021-09-17 11:04:36.243 openLuup.mqtt:: closed tcp{client}: 0x2b7aff8 2021-09-17 11:04:36.243 openLuup.mqtt:: TasmotaCO2Brandv UNSUBSCRIBE from cmnd/TasmotaCO2Brandv/# tcp{client}: 0x2b7aff8 2021-09-17 11:04:36.243 openLuup.mqtt:: TasmotaCO2Brandv UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x2b7aff8 2021-09-17 11:04:36.243 openLuup.mqtt:: TasmotaCO2Brandv UNSUBSCRIBE from cmnd/TasmotaCO2Brandv_fb/# tcp{client}: 0x2b7aff8 2021-09-17 11:04:36.243 openLuup.mqtt:: ERROR publishing application message for mqtt:cmnd/TasmotaCO2Brandv/POWER : closed
I am seeing a number of Mqtt connections almost at the same time and then some unsubscribe and receive errors and then just a crash.
I have had not crashes for >25 days, so a bit strange.
The only change I can think of that I made a day ago was that I added a Reactor that fetches data from a site parses it and sends it to Thingspeak by making two "http get" actions to get data from energyhive.com and then two:
os.execute( "curl -s -i -H 'Accept:application/json' 'https://api.thingspeak.com/update?api_key=key&field1='" .. result)
Both actions were running every minute. I have now removed one of the "http get" and curl commands, and also run this every second minute instead. The Reactor is what is shown in the beginning of the log btw.
Maybe this is something that puts a lot of load on the Lua sockets of something? I will disable it and see.Any ideas around this would be welcome.
-
@akbooer I'm still having a lot of crashes but since I added an autorestart of the service it's not really a major problem anymore.
Even though openLuup is rock solid for most people, may I suggest you add[Service] Restart=on-failure RestartSec=5s
To the documentation for openLuup in the appendix for systemd?
At least it helped me not coming home to a dead house -
Hi akbooer,
randomly openluup hangs but today I noticed in the log (attached) something strange :
2022-08-13 12:54:35.283 openLuup.server:: GET /data_request?id=lr_render&target=Vera-45108342.024.urn:upnp-org:serviceId:VContainer1.Variable3&from=2022-08-13T00:00&format=json HTTP/1.1 tcp{client}: 0x556c471741f8
2022-08-13 12:54:35.286 luup_log:4: DataGraph: Whisper query: CPU = 2.068 mS for 775 points
2022-08-13 12:54:35.289 openLuup.server:: request completed (20282 bytes, 2 chunks, 6 ms) tcp{client}: 0x556c471741f8
2022-08-13 12:54:35.290 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x556c471741f8
2022-08-13 12:54:57.889 openLuup.io.server:: HTTP:3480 connection from 92.255.85.183 tcp{client}: 0x556c482cf138
2022-08-13 12:54:57.889 openLuup.server:: /*: mstshash=Administr tcp{client}: 0x556c482cf138
2022-08-13 12:54:57.889 openLuup.context_switch:: ERROR: [dev #0] ./openLuup/server.lua:238: attempt to concatenate local 'method' (a nil value)
2022-08-13 12:54:57.889 luup.incoming_callback:: function: 0x556c4753ff20 ERROR: ./openLuup/server.lua:238: attempt to concatenate local 'method' (a nil value)at 12:54 openluup stopped to write and read the datayours files
Is a possible attack ?
-
Looks like an attack, from what I read online.
-
Hi akbooer,
in order to set firewall rules can you give me some info on the openluup log records ? Following there are few normal log lines of datayours read/write :
2022-08-13 12:52:21.921 luup.variable_set:: 4.urn:akbooer-com:serviceId:DataYours1.AppMemoryUsed was: 6568 now: 6871 #hooks:0
2022-08-13 12:52:26.570 openLuup.io.server:: HTTP:3480 connection from xx.xx.xx.xx tcp{client}: 0x556c474b0348
2022-08-13 12:52:26.571 openLuup.server:: GET /data_request?id=lr_render&target=Vera-yyyyyyyy.024.urn:upnp-org:serviceId:VContainer1.Variable3&from=-2h&format=json HTTP/1.1 tcp{client}: 0x556c474b0348
2022-08-13 12:52:26.571 luup_log:4: DataGraph: Whisper query: CPU = 0.405 mS for 121 points
2022-08-13 12:52:26.572 openLuup.server:: request completed (3359 bytes, 1 chunks, 1 ms) tcp{client}: 0x556c474b0348
2022-08-13 12:52:26.572 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x556c474b0348
2022-08-13 12:52:26.574 openLuup.io.server:: HTTP:3480 connection from xx.xx.xx.xx tcp{client}: 0x556c47810548
2022-08-13 12:52:26.574 openLuup.server:: GET /data_request?id=lr_render&target=Vera-yyyyyyyy.024.urn:upnp-org:serviceId:VContainer1.Variable3&from=2022-08-13T00:00&format=json HTTP/1.1 tcp{client}: 0x556c47810548
2022-08-13 12:52:26.576 luup_log:4: DataGraph: Whisper query: CPU = 2.085 mS for 773 points
2022-08-13 12:52:26.580 openLuup.server:: request completed (20228 bytes, 2 chunks, 6 ms) tcp{client}: 0x556c47810548
2022-08-13 12:52:26.581 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x556c47810548
2022-08-13 12:52:35.363 openLuup.io.server:: HTTP:3480 connection from xx.xx.xx.xx tcp{client}: 0x556c4756a4b8
2022-08-13 12:52:35.364 openLuup.server:: GET /data_request?id=lr_render&target=Vera-yyyyyyyy.024.urn:upnp-org:serviceId:VContainer1.Variable3&from=-2h&format=json HTTP/1.1 tcp{client}: 0x556c4756a4b8
2022-08-13 12:52:35.364 luup_log:4: DataGraph: Whisper query: CPU = 0.418 mS for 121 points
2022-08-13 12:52:35.366 openLuup.server:: request completed (3359 bytes, 1 chunks, 1 ms) tcp{client}: 0x556c4756a4b8
2022-08-13 12:52:35.366 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x556c4756a4b8
2022-08-13 12:52:35.368 openLuup.io.server:: HTTP:3480 connection from xx.xx.xx.xx tcp{client}: 0x556c47294958
2022-08-13 12:52:35.368 openLuup.server:: GET /data_request?id=lr_render&target=Vera-yyyyyyyy.024.urn:upnp-org:serviceId:VContainer1.kwdaily3&from=2016-07-01&format=json HTTP/1.1 tcp{client}: 0x556c47294958
2022-08-13 12:52:35.375 luup_log:4: DataGraph: Whisper query: CPU = 6.521 mS for 2235 points
2022-08-13 12:52:35.392 openLuup.server:: request completed (62445 bytes, 4 chunks, 23 ms) tcp{client}: 0x556c47294958
2022-08-13 12:52:35.397 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x556c47294958
2022-08-13 12:52:35.398 openLuup.io.server:: HTTP:3480 connection from xx.xx.xx.xx tcp{client}: 0x556c47158248
2022-08-13 12:52:35.398 openLuup.server:: GET /data_request?id=lr_render&target=Vera-yyyyyyyy.024.urn:upnp-org:serviceId:VContainer1.Variable3&from=2022-08-13T00:00&format=json HTTP/1.1 tcp{client}: 0x556c47158248
2022-08-13 12:52:35.401 luup_log:4: DataGraph: Whisper query: CPU = 2.409 mS for 773 points
2022-08-13 12:52:35.406 openLuup.server:: request completed (20228 bytes, 2 chunks, 7 ms) tcp{client}: 0x556c47158248
2022-08-13 12:52:35.406 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x556c47158248
2022-08-13 12:53:26.581 openLuup.io.server:: HTTP:3480 connection from xx.xx.xx.xx tcp{client}: 0x556c4877f9d8
2022-08-13 12:53:26.581 openLuup.server:: GET /data_request?id=lr_render&target=Vera-yyyyyyyy.024.urn:upnp-org:serviceId:VContainer1.Variable3&from=-2h&format=json HTTP/1.1 tcp{client}: 0x556c4877f9d8
2022-08-13 12:53:26.582 luup_log:4: DataGraph: Whisper query: CPU = 0.735 mS for 121 pointsThe read commands of whisper files are all of kind "http://server-ip:3480......."
the following log record :
openLuup.io.server:: HTTP:3480 connection from xx.xx.xx.xx tcp{client}
is from a http read ?Can I see UDP write log record ?
The write commands come from remote datayours through UDP to "server-ip" .
All consolidated whisper files I read/write are on "server-ip".
Is it correct in this scenario that all the regular and normal commands (read/write) must come from "server-ip" ?
tnks
-
If your system is exposed to the internet (which I assume it must be, given that IP address is in HK) have you considered either setting up some port forwarding, or, a VPN and locking it down to internal access only? Would seem simpler than trying to set up firewall rules, assuming your Datayours server is on the same LAN?
I'm sure you have a good reason for your set up, just my $0.0002 worth
C
-
Yes, the server logs the initial HTTP connection, and the hex number at the end of the log line is an internal reference for the client socket. That same socket reference occurs at the end of the actual HTTP request line.
IIRC, DataYours by default does not log UDP writes (because in many instances they would flood the log. I’d have to refer back to the source code to see if debug logging enables that.
Agree with the comment on VPNs.
-
This error:
2022-08-13 12:54:57.889 openLuup.context_switch:: ERROR: [dev #0] ./openLuup/server.lua:238: attempt to concatenate local 'method' (a nil value)
…is an error in my error reporting! I can fix this easily. The message should just report an unsupported HTTP request and then carry on as usual. I’ll post an update shortly.
It still doesn’t address the issue that you’re receiving a request from someone/somewhere that you shouldn’t.
-
OK, latest development version (v220814) should fix the error message.
-
tnks akbooer for your fix.
About VPN, my server is on a cloud hosting and the web app is accessed by authenticated users so I suppose the only solution is to activate some fw rule on the openluup/datayours server.