OpenLuup unavailable
-
I could perhaps make this user-supplied string.
-
This error counting in the log is a great idea. It triggered my OCD tendencies and got me to track down a couple of typos along with loading the upnp proxy server... not as a plugin but as a systemd service to get rid of the sonos errors in the log.
Suggestion @akbooer: Don't isolate the lines showing errors. Instead it would be nice if they could be highlighted or colored on the log visualization page.
-
@mrfarmer said in OpenLuup unavailable:
The Ezlo json responses include the word error even is there is none
What does one of those responses actually look like (around the part that says error.). I could search for just an isolated word...
-
I too am now seeing the following syntax being counted as an error from the sonos speakers through the UPnP proxy:
TVConfigurationError="0"
-
-
Working great! Thanks for the quick turnaround.
Something very strange is going on though. Without the MQTT server enabled at all, I have observed the same problem as @ArcherS twice today. The only major change I made was to enable the LuaUPnP proxy for the sonos app. Prior to this, I have had no memory of openLuup hanging this way for quite some time, probably a year. Looked at the logs and found nothing useful. I seem to remember having some strange problems with the luasocket the last time I had seen this while trying to get fix another plugin. I will keep an eye on this.
The only errors I am currently seeing look like this:
openLuup.server:: error 'closed' sending 5 bytes to tcp{client}: 0x7f49d5fe98f8
Whereby it seems like openLuup is trying to send bytes to an incoming tcp connection which has been closed by the client. I have several such servers sending http commands to openLuup.
Link to the previous thread about it https://smarthome.community/topic/105/openluup-hangs
-
Thanks for raising this issue... I nearly missed it because you edited a previous post rather than started a new one.
We need to nail down this issue, which is clearly genuine, but infrequent and difficult to replicate at will. It’s good to note that it’s not apparently connected with MQTT. The strange thing is that, with very minor exceptions, none of the major server modules have been changed for over a year. Are we all just stressing our system a bit more these days?
I have introduced some extra socket checks specifically into the MQTT code, so my first line of attack will be to retrofit these to HTTP transactions. This gets me thinking again that it would be great to use a real HTTP server, rather than one I have written myself. But it’s a bit daunting to consider the installation and configuration needed to do that. Ideally, I’d need something that supports the WSAPI CGI interface. Apache does, as, I believe, does lighttpd.
-
The latest development version v21.3.24 has the extra socket send check in place for every send done on an openLuup server (HTTP, MQTT, SMTP, POP3.)
Let's see if that helps anything.
-
Hi AK,
No longer seeing the high error count, great work as always.
What I notice is that the longest gaps are always for a poll to one of my Vera's even though that is set for async poll (running on Debian PI cone VM). I do not see that on my main V20.4.30 running on a PI3 with Debian.
Cheers Rene
-
@akbooer I have have the system up and running over two nights in a row without doing any changes and without any crashes. Today at approx 12:24 the system however crashed again. I think it is no single device that causes the crash but instead that a socket overload or something similar.
The current setup I have for the sensors pushing data via http adds up to quite a lot of http requests, since one sensor can update a number of OpenLuup devices (approx foru to eight) at one occation. Mqtt will reduce this quite a lot since all data for that sensor will be in one message.
I will install v21.3.24 and see if anything changes.
When looking in the log a few minutes before the crash I can see the following in the log, don't know if this could give more clues.
... 2021-03-24 12:21:22.883 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=181&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=11.1 HTTP/1.1 tcp{client}: 0x557824e372d8 2021-03-24 12:21:22.883 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=183&id=variableset&serviceId=urn:micasaverde-com:serviceId:LightSensor1&Variable=CurrentLevel&Value=1181 HTTP/1.1 tcp{client}: 0x5578241755b8 2021-03-24 12:21:22.883 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=182&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=48.9 HTTP/1.1 tcp{client}: 0x5578246d66f8 2021-03-24 12:21:22.884 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=180&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=0.7 HTTP/1.1 tcp{client}: 0x557825862ea8 2021-03-24 12:21:22.884 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=184&id=variableset&serviceId=urn:micasaverde-com:serviceId:GenericSensor1&Variable=CurrentLevel&Value=1006.9 HTTP/1.1 tcp{client}: 0x557824e808c8 2021-03-24 12:21:22.884 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=152&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=12.6 HTTP/1.1 tcp{client}: 0x5578254dba88 2021-03-24 12:21:22.884 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=153&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=44.7 HTTP/1.1 tcp{client}: 0x557824553b88 2021-03-24 12:21:22.884 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=173&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=14.7 HTTP/1.1 tcp{client}: 0x557825687348 2021-03-24 12:21:22.884 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=188&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=23.0 HTTP/1.1 tcp{client}: 0x557825adb228 2021-03-24 12:21:22.885 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=154&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=0.9 HTTP/1.1 tcp{client}: 0x557824a5b168 2021-03-24 12:21:22.885 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=151&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=11.5 HTTP/1.1 tcp{client}: 0x557823bcd248 2021-03-24 12:21:22.885 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=175&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=45.0 HTTP/1.1 tcp{client}: 0x5578255cb878 2021-03-24 12:21:22.885 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=189&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=29.7 HTTP/1.1 tcp{client}: 0x55782415ca68 2021-03-24 12:21:22.885 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=150&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=41.8 HTTP/1.1 tcp{client}: 0x557824fdc308 2021-03-24 12:21:22.886 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=174&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=2.9 HTTP/1.1 tcp{client}: 0x55782411d778 2021-03-24 12:21:22.886 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=190&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=2.7 HTTP/1.1 tcp{client}: 0x5578243ea368 2021-03-24 12:21:22.886 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=149&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=-1.1 HTTP/1.1 tcp{client}: 0x557824eed778 2021-03-24 12:21:22.886 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=164&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=8.5 HTTP/1.1 tcp{client}: 0x5578249a9f38 2021-03-24 12:21:22.887 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x5578245a37b8 2021-03-24 12:21:22.887 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x5578245a37b8 2021-03-24 12:21:22.887 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmota_test_fb/# tcp{client}: 0x5578245a37b8 2021-03-24 12:21:22.887 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x5578245a37b8 2021-03-24 12:21:22.887 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmota_test/# tcp{client}: 0x5578245a37b8 2021-03-24 12:21:22.887 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x557824be7628 2021-03-24 12:21:22.887 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x557824be7628 2021-03-24 12:21:22.887 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/TasmotaCO2An_fb/# tcp{client}: 0x557824be7628 2021-03-24 12:21:22.887 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/TasmotaCO2An/# tcp{client}: 0x557824be7628 2021-03-24 12:21:22.887 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x557824be7628 ... 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824e372d8 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578241755b8 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578246d66f8 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557825862ea8 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824e808c8 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578254dba88 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824553b88 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557825687348 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557825adb228 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824a5b168 2021-03-24 12:21:22.928 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557823bcd248 2021-03-24 12:21:22.929 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578255cb878 2021-03-24 12:21:22.929 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x55782415ca68 2021-03-24 12:21:22.929 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824fdc308 2021-03-24 12:21:22.929 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x55782411d778 2021-03-24 12:21:22.929 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578243ea368 2021-03-24 12:21:22.929 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824eed778 2021-03-24 12:21:22.930 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x557823c0f808 2021-03-24 12:21:22.930 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x557823c0f808 2021-03-24 12:21:22.930 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/TasmotaCO2Ax/# tcp{client}: 0x557823c0f808 2021-03-24 12:21:22.930 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x557823c0f808 2021-03-24 12:21:22.930 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/TasmotaCO2Ax_fb/# tcp{client}: 0x557823c0f808 2021-03-24 12:21:22.971 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578249a9f38 2021-03-24 12:21:23.001 openLuup.mqtt:: tasmota_test SUBSCRIBE to cmnd/tasmota_test/# tcp{client}: 0x5578247df8a8 2021-03-24 12:21:23.002 openLuup.mqtt:: tasmota_test SUBSCRIBE to cmnd/tasmotas/# tcp{client}: 0x5578247df8a8 2021-03-24 12:21:23.002 openLuup.mqtt:: tasmota_test SUBSCRIBE to cmnd/tasmota_test_fb/# tcp{client}: 0x5578247df8a8 2021-03-24 12:21:23.004 openLuup.mqtt:: TasmotaCO2Ax SUBSCRIBE to cmnd/TasmotaCO2Ax/# tcp{client}: 0x55782502f428 2021-03-24 12:21:23.004 openLuup.mqtt:: TasmotaCO2Ax SUBSCRIBE to cmnd/tasmotas/# tcp{client}: 0x55782502f428 2021-03-24 12:21:23.005 openLuup.mqtt:: TasmotaCO2Ax SUBSCRIBE to cmnd/TasmotaCO2Ax_fb/# tcp{client}: 0x55782502f428 2021-03-24 12:21:23.005 openLuup.mqtt:: TasmotaCO2An SUBSCRIBE to cmnd/TasmotaCO2An/# tcp{client}: 0x557825ca05a8 2021-03-24 12:21:23.006 openLuup.mqtt:: TasmotaCO2An SUBSCRIBE to cmnd/tasmotas/# tcp{client}: 0x557825ca05a8 2021-03-24 12:21:23.006 openLuup.mqtt:: TasmotaCO2An SUBSCRIBE to cmnd/TasmotaCO2An_fb/# tcp{client}: 0x557825ca05a8 2021-03-24 12:21:23.020 openLuup.io.server:: HTTP:3480 connection from 192.168.1.53 tcp{client}: 0x557824728c98 ... 2021-03-24 12:24:27.723 openLuup.io.server:: HTTP:3480 connection from 192.168.1.54 tcp{client}: 0x5578254b0b78 2021-03-24 12:24:27.723 openLuup.io.server:: HTTP:3480 connection from 192.168.1.54 tcp{client}: 0x557824f80ef8 2021-03-24 12:24:27.723 openLuup.io.server:: HTTP:3480 connection from 192.168.1.51 tcp{client}: 0x557824f83988 2021-03-24 12:24:27.723 openLuup.io.server:: HTTP:3480 connection from 192.168.1.54 tcp{client}: 0x557824df10c8 2021-03-24 12:24:27.723 openLuup.io.server:: HTTP:3480 connection from 192.168.1.51 tcp{client}: 0x557824fb0048 2021-03-24 12:24:27.724 openLuup.io.server:: HTTP:3480 connection from 192.168.1.54 tcp{client}: 0x557824fb21e8 2021-03-24 12:24:27.724 openLuup.io.server:: HTTP:3480 connection from 192.168.1.51 tcp{client}: 0x557824e52928 2021-03-24 12:24:27.724 openLuup.io.server:: HTTP:3480 connection from 192.168.1.54 tcp{client}: 0x557824fd5f48 2021-03-24 12:24:27.724 openLuup.io.server:: HTTP:3480 connection from 192.168.1.52 tcp{client}: 0x557824fd7ff8 2021-03-24 12:24:27.724 openLuup.io.server:: HTTP:3480 connection from 192.168.1.52 tcp{client}: 0x5578241ee5a8 2021-03-24 12:24:27.725 openLuup.io.server:: HTTP:3480 connection from 192.168.1.55 tcp{client}: 0x557824d0f778 2021-03-24 12:24:27.725 openLuup.io.server:: HTTP:3480 connection from 192.168.1.52 tcp{client}: 0x557824d11828 2021-03-24 12:24:27.725 openLuup.io.server:: HTTP:3480 connection from 192.168.1.55 tcp{client}: 0x5578251ff6f8 2021-03-24 12:24:27.725 openLuup.io.server:: HTTP:3480 connection from 192.168.1.55 tcp{client}: 0x557825201b18 2021-03-24 12:24:27.726 openLuup.io.server:: HTTP:3480 connection from 192.168.1.50 tcp{client}: 0x55782562a688 2021-03-24 12:24:27.726 openLuup.io.server:: MQTT:1883 connection from 192.168.1.60 tcp{client}: 0x5578257d3ec8 2021-03-24 12:24:27.726 openLuup.io.server:: MQTT:1883 connection from 192.168.1.61 tcp{client}: 0x5578257d5f78 2021-03-24 12:24:27.727 openLuup.io.server:: MQTT:1883 connection from 192.168.1.62 tcp{client}: 0x5578252531e8 2021-03-24 12:24:27.728 luup_log:0: 50Mb, 2.1%cpu, 2.0days ... 2021-03-24 12:24:29.281 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=181&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=11.3 HTTP/1.1 tcp{client}: 0x5578254b0b78 2021-03-24 12:24:29.281 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=183&id=variableset&serviceId=urn:micasaverde-com:serviceId:LightSensor1&Variable=CurrentLevel&Value=1125 HTTP/1.1 tcp{client}: 0x557824f80ef8 2021-03-24 12:24:29.282 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=173&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=14.8 HTTP/1.1 tcp{client}: 0x557824f83988 2021-03-24 12:24:29.282 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=182&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=49.3 HTTP/1.1 tcp{client}: 0x557824df10c8 2021-03-24 12:24:29.282 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=175&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=45.0 HTTP/1.1 tcp{client}: 0x557824fb0048 2021-03-24 12:24:29.283 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=180&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=1.0 HTTP/1.1 tcp{client}: 0x557824fb21e8 2021-03-24 12:24:29.284 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=174&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=3.0 HTTP/1.1 tcp{client}: 0x557824e52928 2021-03-24 12:24:29.284 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=184&id=variableset&serviceId=urn:micasaverde-com:serviceId:GenericSensor1&Variable=CurrentLevel&Value=1006.8 HTTP/1.1 tcp{client}: 0x557824fd5f48 2021-03-24 12:24:29.285 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=188&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=23.9 HTTP/1.1 tcp{client}: 0x557824fd7ff8 2021-03-24 12:24:29.285 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=189&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=29.2 HTTP/1.1 tcp{client}: 0x5578241ee5a8 2021-03-24 12:24:29.286 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=151&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=11.7 HTTP/1.1 tcp{client}: 0x557824d0f778 2021-03-24 12:24:29.286 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=190&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=2.9 HTTP/1.1 tcp{client}: 0x557824d11828 2021-03-24 12:24:29.287 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=150&id=variableset&serviceId=urn:micasaverde-com:serviceId:HumiditySensor1&Variable=CurrentLevel&Value=41.5 HTTP/1.1 tcp{client}: 0x5578251ff6f8 2021-03-24 12:24:29.287 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=149&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=-1.0 HTTP/1.1 tcp{client}: 0x557825201b18 2021-03-24 12:24:29.288 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=152&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=12.9 HTTP/1.1 tcp{client}: 0x55782562a688 2021-03-24 12:24:29.289 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x557825ca05a8 2021-03-24 12:24:29.289 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x557825ca05a8 2021-03-24 12:24:29.289 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/TasmotaCO2An_fb/# tcp{client}: 0x557825ca05a8 2021-03-24 12:24:29.289 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/TasmotaCO2An/# tcp{client}: 0x557825ca05a8 2021-03-24 12:24:29.289 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x557825ca05a8 2021-03-24 12:24:29.290 luup_log:203: VirtualBinaryLight[2.40@203]:[updateMeters] KWH Path "meters[1].total" - Raw Value: 2805119 - Transformed Value: 4852230.7604 2021-03-24 12:24:29.290 luup.variable_set:: 203.urn:micasaverde-com:serviceId:EnergyMetering1.KWH was: 4852184.0084 now: 4852230.7604 #hooks:0 2021-03-24 12:24:29.291 luup_log:203: VirtualBinaryLight[2.40@203]:[updateMeters] Watts Path: "meters[1].power" - Value: 0 2021-03-24 12:24:29.291 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x55782502f428 2021-03-24 12:24:29.291 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x55782502f428 2021-03-24 12:24:29.291 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/TasmotaCO2Ax/# tcp{client}: 0x55782502f428 2021-03-24 12:24:29.291 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x55782502f428 2021-03-24 12:24:29.291 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/TasmotaCO2Ax_fb/# tcp{client}: 0x55782502f428 ... 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578254b0b78 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824f80ef8 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824f83988 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824df10c8 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824fb0048 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824fb21e8 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824e52928 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824fd5f48 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824fd7ff8 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578241ee5a8 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824d0f778 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557824d11828 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x5578251ff6f8 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557825201b18 2021-03-24 12:24:29.367 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x55782562a688 2021-03-24 12:24:29.368 openLuup.server:: GET /data_request?id=lu_action&DeviceNum=164&id=variableset&serviceId=urn:upnp-org:serviceId:TemperatureSensor1&Variable=CurrentTemperature&Value=8.6 HTTP/1.1 tcp{client}: 0x5578249f1658 2021-03-24 12:24:29.368 luup.variable_set:: 164.urn:upnp-org:serviceId:TemperatureSensor1.CurrentTemperature was: 8.6 now: 8.6 #hooks:0 2021-03-24 12:24:29.368 openLuup.server:: request completed (2 bytes, 1 chunks, 0 ms) tcp{client}: 0x5578249f1658 2021-03-24 12:24:29.371 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x5578247df8a8 2021-03-24 12:24:29.371 openLuup.mqtt:: closed tcp{client}: 0x5578247df8a8 2021-03-24 12:24:29.371 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmota_test_fb/# tcp{client}: 0x5578247df8a8 2021-03-24 12:24:29.371 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x5578247df8a8 2021-03-24 12:24:29.371 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmota_test/# tcp{client}: 0x5578247df8a8 2021-03-24 12:24:29.371 openLuup.mqtt:: ERROR publishing application message for mqtt:cmnd/tasmota_test/POWER : closed
-
I have been searching around and it appears to be a common yet infrequent problem reported for the luasocket. For good measure I updated my version of luasocket again to the latest development version (scm-2) but given how stagnant the development has been, I am wondering whether this would be the time to look for a different library... I have tinkered with libcurl in the past but I think it is only for POSIX platforms. I am sure there is a better lua library out there.
-
OK, that was clearly a BAD IDEA.
2021-03-24 14:49:58.979 openLuup.server:: GET /J_ALTUI_verabox.js HTTP/1.1 tcp{client}: 0x1cb6160 2021-03-24 14:49:58.982 openLuup.server:: error 'socket.select() not ready to send tcp{client}: 0x1cb6160' sending 2 bytes to tcp{client}: 0x1cb6160 2021-03-24 14:49:58.982 openLuup.server:: error 'socket.select() not ready to send tcp{client}: 0x1cb6160' sending 6 bytes to tcp{client}: 0x1cb6160 2021-03-24 14:49:58.982 openLuup.server:: error 'socket.select() not ready to send tcp{client}: 0x1cb6160' sending 97222 bytes to tcp{client}: 0x1cb6160 2021-03-24 14:49:58.982 openLuup.server:: error 'socket.select() not ready to send tcp{client}: 0x1cb6160' sending 2 bytes to tcp{client}: 0x1cb6160 2021-03-24 14:49:58.983 openLuup.server:: error 'socket.select() not ready to send tcp{client}: 0x1cb6160' sending 5 bytes to tcp{client}: 0x1cb6160
I've reverted that commit, so simply updating to development again (from the console!) should fix that.
-
I've pushed a new v21.3.24b release which includes the new checks, but, hopefully, without the deleterious effect on AltUI (or anything else.)
To make it easy to revert, I've also tagged the v21.3.23 version, so you can always revert to that by typing it into the update box.
-
Have not upgraded to 24b yet but this is what I am seeing:
2021-03-24 12:36:01.348 openLuup.io.server:: HTTP:3480 connection from 192.168.0.55 tcp{client}: 0x7fb153b396c8 2021-03-24 12:36:01.350 openLuup.server:: GET /data_request?id=variableset&serviceId=urn:upnp-org:serviceId:VSwitch1&Variable=Text2&DeviceNum=22&Value=10 HTTP/1.1 tcp{client}: 0x7fb153b396c8 2021-03-24 12:36:01.350 luup.variable_set:: 22.urn:upnp-org:serviceId:VSwitch1.Text2 was: 9 now: 10 #hooks:0 2021-03-24 12:36:01.351 openLuup.server:: error 'closed' sending 2 bytes to tcp{client}: 0x7fb153b396c8 2021-03-24 12:36:01.351 openLuup.server:: ...only 0 bytes sent 2021-03-24 12:36:01.351 openLuup.server:: error 'closed' sending 5 bytes to tcp{client}: 0x7fb153b396c8 2021-03-24 12:36:01.351 openLuup.server:: ...only 0 bytes sent 2021-03-24 12:36:01.351 openLuup.server:: request completed (2 bytes, 1 chunks, 1 ms) tcp{client}: 0x7fb153b396c8 2021-03-24 12:36:01.351 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x7fb153b396c8
I am nearly 100% convinced that the hangs are due to luasocket error or timeout handling. You can see here that likely the client which here is home-assistant sending an http call to update a device on openLuup, apparently closed the tcp connection to which openLuup is trying to send something. As a result, I am getting an error. The humor is that both home assistant and openLuup are on the same machine. I am seeing this type of errors a few times a day but have not had a hang up since my previous post (I have updated luasocket and luasec since by the way) so I don't know if they are related to this error. However my previous experience from last year seem to indicate a bug in luasocket causing it to hold up the entire lua thread.
-
@akbooer Upgraded to v21.2.24b, it works as supposed so far.
Also I modified my strategy a bit. I have now turned off the http reporting from the sensors. They generate quite a lot of http calls, the screenshot below is from approx 13:00 to 22:00.
Worth noting is that they have been doing this http reporting for a few months without any stability problems, the traffic they generate could however be part of seeing the problems on my particular server perhaps.
The three test devices reporting over Mqtt are left on, we will see what happens.
-
Today at 12:08 it crashed again.
Not many Mqtt calls since the restart yesterday evening.
Also very few http server sockets:
Log file errors before the crash:
.. 2021-03-25 12:05:33.879 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x563ca4502428 2021-03-25 12:05:33.879 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x563ca4502428 2021-03-25 12:05:33.879 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/TasmotaCO2An_fb/# tcp{client}: 0x563ca4502428 2021-03-25 12:05:33.879 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x563ca4502428 2021-03-25 12:05:33.879 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/TasmotaCO2An/# tcp{client}: 0x563ca4502428 2021-03-25 12:05:33.891 openLuup.mqtt:: TasmotaCO2An SUBSCRIBE to cmnd/TasmotaCO2An/# tcp{client}: 0x563ca41ea188 2021-03-25 12:05:33.894 openLuup.mqtt:: TasmotaCO2An SUBSCRIBE to cmnd/tasmotas/# tcp{client}: 0x563ca41ea188 .. 2021-03-25 12:08:44.921 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x563ca41ea188 2021-03-25 12:08:44.921 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x563ca41ea188 2021-03-25 12:08:44.921 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/TasmotaCO2An_fb/# tcp{client}: 0x563ca41ea188 2021-03-25 12:08:44.921 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x563ca41ea188 2021-03-25 12:08:44.921 openLuup.mqtt:: TasmotaCO2An UNSUBSCRIBE from cmnd/TasmotaCO2An/# tcp{client}: 0x563ca41ea188 2021-03-25 12:08:44.925 openLuup.server:: request completed (11424 bytes, 1 chunks, 3813 ms) tcp{client}: 0x563ca3ebc488 .. 2021-03-25 12:08:44.935 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x563ca3b9d058 2021-03-25 12:08:44.935 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x563ca3b9d058 2021-03-25 12:08:44.935 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x563ca3f8a488 2021-03-25 12:08:44.935 openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x563ca3f8a488 ... 2021-03-25 12:08:44.938 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x563ca47549f8 2021-03-25 12:08:44.938 openLuup.mqtt:: closed tcp{client}: 0x563ca47549f8 2021-03-25 12:08:44.938 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmota_test_fb/# tcp{client}: 0x563ca47549f8 2021-03-25 12:08:44.938 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmota_test/# tcp{client}: 0x563ca47549f8 2021-03-25 12:08:44.938 openLuup.mqtt:: tasmota_test UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x563ca47549f8 2021-03-25 12:08:44.938 openLuup.mqtt:: ERROR publishing application message for mqtt:cmnd/tasmota_test/POWER : closed 2021-03-25 12:08:44.939 openLuup.io.server:: MQTT:1883 connection closed tcp{client}: 0x563ca428dc98 2021-03-25 12:08:44.939 openLuup.mqtt:: closed tcp{client}: 0x563ca428dc98 2021-03-25 12:08:44.939 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/TasmotaCO2Ax/# tcp{client}: 0x563ca428dc98 2021-03-25 12:08:44.939 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/tasmotas/# tcp{client}: 0x563ca428dc98 2021-03-25 12:08:44.939 openLuup.mqtt:: TasmotaCO2Ax UNSUBSCRIBE from cmnd/TasmotaCO2Ax_fb/# tcp{client}: 0x563ca428dc98 2021-03-25 12:08:44.939 openLuup.mqtt:: ERROR publishing application message for mqtt:cmnd/TasmotaCO2Ax/POWER : closed
40/88