openLuup startup error

I installed the latest main branch 2018 Release 6.26 (vera bridge 18.6.22) and I get the following error messages when I do a luup reload. In the startup log:

2018-06-26 15:42:23.366 luup.register_handler:: global_function_name=CameraUDPcallback, request=udp:8099 2018-06-26 15:42:23.366 openLuup.io.udp:: address already in use 2018-06-26 15:42:23.366 luup_log:0: startup code completed 2018-06-26 15:42:23.367 openLuup.init:: init phase completed

CameraUDPcallback is called from start-up code.

And in the running log:

2018-06-26 15:42:23.367 :: openLuup LOG ROTATION :: (runtime 0.0 days) 2018-06-26 15:42:23.367 openLuup.init:: init phase completed 2018-06-26 15:42:23.367 openLuup.io.server:: error starting server: address already in use

The log entries stop at this point.

The condition allows me to access the UI of altUI, however, I get continuous controller not responding messages and I cannot access the openLupp console. I also see some outdated device statuses on the device page (some devices show as on when they are off). If I then do a browser refresh, I cannot access the UI at all.

A reboot of the machine clears this condition and afterwards, all of openLuup seems to function normally-- until I reload the luup engine from the menu, whereby the condition reappears.

To try and track down the issue, I removed all startup code. I still get the same error message in the running logs (log entry stops here)

2018-06-26 18:22:17.949 :: openLuup LOG ROTATION :: (runtime 0.0 days) 2018-06-26 18:22:17.953 openLuup.init:: init phase completed 2018-06-26 18:22:17.953 openLuup.io.server:: error starting server: address already in use

however, the start–up log does not show any errors.

2018-06-26 18:22:17.949 openLuup.userdata:: ...user_data loading completed 2018-06-26 18:22:17.949 openLuup.init:: running _openLuup_STARTUP_ 2018-06-26 18:22:17.949 luup_log:0: startup code completed 2018-06-26 18:22:17.949 openLuup.init:: init phase completed 2018-06-26 18:22:17.949 :: openLuup LOG ROTATION :: (runtime 0.0 days)

Edit: I did a complete deletion of the cmh-ludl folder and all subfolders. I then restored the folder using a complete backup I created last week (it may be a test version). The openLuup version # is 18.6.5 and verabridge 18.6.4. openLuup comes up with no problems from this restored version.

I then did an update using the plugin page without any parameters. First I updated verabridge, and I now see a dropdown in version to 18.3.2. openLuup works as expected without any problems.

Then an update to openLuup gets continuous controller did not respond messages in the UI. The following error is in the startup log:

2018-06-26 22:19:07.352   luup.create_device:: ERROR [82] D_BroadLink_Mk2_1.xml / I_BroadLink_Mk2_1.xml / D_BroadLink_Mk2_1.json : ./openLuup/loader.lua:326: bad argument #1 to 'ipairs' (table expected, got string)

I tried doing this entire routine twice with the same result so there is definitely something in this plugin that is causing openLuup to crash, though it performed without problem prior to the update.

Edit#2 And finally, after deleting the broadlink plugin, the latest version (18.3.23) of openLuup loads and runs correctly. I updated to development version 18.6.26 and everything seems to be running normally.

Reading your edits, I’m unsure as to whether of not you still have a problem?

I don’t know anything about the Broadlink plugin. It looks like it might be an error reading one of the device files. However, the problem is clearly mine. I 'll go and learn something about it.


Edit: your original error “error starting server: address already in use” is clearly from an unclosed IP connection. It definitely need a better error message to identify which one.

Edit2: It’s actually looks like the HTTP server, in which case you simply had an earlier copy of openLuup running, and not correctly shut down.

I had to reboot the machine each time, so doubtful that a server survived the reboot.

I’m now seeing this in the log. Sensor 17 is a motion sensor on my honeywell alarm panel. It is picked up by the EVL honeywell plugin. I don’t see anything on the variables page that looks out of place.

2018-06-26 23:53:25.515 luup.variable_set:: 17.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-06-26 23:53:25.515 openLuup.context_switch:: ERROR: ./openLuup/luup.lua:289: attempt to index a number value 2018-06-26 23:53:25.515 openLuup.io:: ./openLuup/luup.lua:289: attempt to index a number value

The original condition is fixed in that I deleted the broadlink plugin, but I’d like to reinstall the device as it controls a minor part of my security system (TV monitors).

[quote=“Buxton, post:4, topic:199403”]I’m now seeing this in the log. Sensor 17 is a motion sensor on my honeywell alarm panel. It is picked up by the EVL honeywell plugin. I don’t see anything on the variables page that looks out of place.

2018-06-26 23:53:25.515 luup.variable_set:: 17.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-06-26 23:53:25.515 openLuup.context_switch:: ERROR: ./openLuup/luup.lua:289: attempt to index a number value 2018-06-26 23:53:25.515 openLuup.io:: ./openLuup/luup.lua:289: attempt to index a number value[/quote]

I hope to have caught this error (although I’m unsure as to the root cause of the value being a number and not a string.) I have also improved the error message from the server startup module to be more explicit.

The original condition is fixed in that I deleted the broadlink plugin, but I'd like to reinstall the device as it controls a minor part of my security system (TV monitors).

Can you try this again with the latest development version (v18.6.27) ?


Edit: I have downloaded the BroadLink_Mk2 files and created a device in my development system with no problem.

2018-06-27 18:12:18.889   luup.create_device:: [416] D_BroadLink_Mk2_1.xml / I_BroadLink_Mk2_1.xml / D_BroadLink_Mk2_1.json
2018-06-27 18:12:18.889   openLuup.http:: request completed (64 bytes, 1 chunks, 62 ms) tcp{client}: 0x703b70
2018-06-27 18:12:18.889   openLuup.scheduler:: [416] BroadLink device startup
2018-06-27 18:12:18.889   luup_log:416: BroadLink_Mk2 debug: Initialising plugin: BroadLink_Mk2
2018-06-27 18:12:18.889   luup_log:416: BroadLink_Mk2 debug: Using: Lua 5.1
2018-06-27 18:12:18.889   luup_log:416: BroadLink_Mk2 debug: 0.54 --> PluginVersion
2018-06-27 18:12:18.890   luup.variable_set:: 416.urn:a-lurker-com:serviceId:BroadLink_Mk2_1.PluginVersion was: EMPTY now: 0.54 #hooks:0
2018-06-27 18:12:18.890   luup_log:416: BroadLink_Mk2 debug: 0 --> DebugEnabled
2018-06-27 18:12:18.890   luup.variable_set:: 416.urn:a-lurker-com:serviceId:BroadLink_Mk2_1.DebugEnabled was: EMPTY now: 0 #hooks:0
2018-06-27 18:12:18.890   luup.variable_set:: 416.urn:a-lurker-com:serviceId:BroadLink_Mk2_1.PluginEnabled was: EMPTY now: 1 #hooks:0
2018-06-27 18:12:18.890   luup.variable_set:: 416.urn:a-lurker-com:serviceId:BroadLink_Mk2_1.BroadLinkDevices was: EMPTY now: {} #hooks:0
2018-06-27 18:12:18.890   luup.variable_set:: 416.urn:a-lurker-com:serviceId:BroadLink_Mk2_1.PollEnable was: EMPTY now: 1 #hooks:0
2018-06-27 18:12:18.890   luup.variable_set:: 416.urn:a-lurker-com:serviceId:BroadLink_Mk2_1.PollInterval was: EMPTY now: 300 #hooks:0
2018-06-27 18:12:18.891   luup_log:416: BroadLink_Mk2 debug: Set socket name failed: permission denied
2018-06-27 18:12:18.891   luup.chdev.sync:: [416] BroadLink, syncing children
2018-06-27 18:12:18.891   luup.set_failure:: status = false
2018-06-27 18:12:18.891   luup.variable_set:: 416.urn:micasaverde-com:serviceId:HaDevice1.CommFailure was: EMPTY now: false #hooks:0
2018-06-27 18:12:18.891   luup.variable_set:: 416.urn:micasaverde-com:serviceId:HaDevice1.CommFailureTime was: EMPTY now: 1530119538 #hooks:0
2018-06-27 18:12:18.891   openLuup.scheduler:: [416] BroadLink device startup completed: status=true, msg=All OK, name=BroadLink_Mk2

I did the update and I’m still seeing the sensor error. I set a watch for the offending variable as follows;

if type(text) == “number” then _log (text, “MY ERROR " … name … " " … device … " " … text … " " …service … " End”) end

Here is the log entry:

2018-06-27 15:01:30.314 luup.variable_set:: 17.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-06-27 15:01:30.314 MY ERROR Tripped 17 1530136890 urn:micasaverde-com:serviceId:SecuritySensor1 End:: 1530136890 2018-06-27 15:01:30.314 openLuup.context_switch:: ERROR: ./openLuup/luup.lua:291: attempt to index a number value 2018-06-27 15:01:30.314 openLuup.io:: ./openLuup/luup.lua:291: attempt to index a number value

lua:291 would be line 290 without my log watch edit.

Also reinstalled the broadlink plugin and all works as before. I have no idea what happened there as I went so far as reinstalling openLuup twice, and rebooted several times, and each time my machine deadlocked in what appeared to be a race condition.

Damn spirits.

Helpful, thanks. All is explained, and I hope that development release v18.6.28b fixes this.

Also reinstalled the broadlink plugin and all works as before. I have no idea what happened there as I went so far as reinstalling openLuup twice, and rebooted several times, and each time my machine deadlocked in what appeared to be a race condition.

Damn spirits.

Indeed, although there are supposed to be less of them around for openLuup!

No errors. Here’s the log:

2018-06-28 15:36:00.428 luup.variable_set:: 17.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-06-28 15:36:00.428 luup.variable_set:: 17.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1530225329 now: 1530225360 #hooks:0 2018-06-28 15:36:00.429 luup.variable_set:: 17.urn:micasaverde-com:serviceId:SecuritySensor1.ArmedTripped was: 1 now: 0 #hooks:0

What is the value “1530225329” changing to “1530225360” ? Is it a time signature?

Yes. Unix epoch in seconds.