We have moved at community.getvera.com

Author Topic: openLuup startup error  (Read 527 times)

Offline Buxton

  • Full Member
  • ***
  • Posts: 209
  • Karma: +12/-0
openLuup startup error
« on: June 26, 2018, 07:12:59 pm »
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:
Code: [Select]
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:
Code: [Select]
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.

Offline Buxton

  • Full Member
  • ***
  • Posts: 209
  • Karma: +12/-0
Re: openLuup startup error
« Reply #1 on: June 26, 2018, 09:29:13 pm »
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)

Code: [Select]
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.

Code: [Select]
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:
Code: [Select]
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.
« Last Edit: June 27, 2018, 02:03:23 am by Buxton »

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: openLuup startup error
« Reply #2 on: June 27, 2018, 02:08:48 am »
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.


« Last Edit: June 27, 2018, 02:21:05 am by akbooer »
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.

Offline Buxton

  • Full Member
  • ***
  • Posts: 209
  • Karma: +12/-0
Re: openLuup startup error
« Reply #3 on: June 27, 2018, 03:07:09 am »
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.

Code: [Select]
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).
« Last Edit: June 27, 2018, 03:11:25 am by Buxton »

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: openLuup startup error
« Reply #4 on: June 27, 2018, 01:09:06 pm »
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.

Code: [Select]
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

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.

Quote
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.

Code: [Select]
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
« Last Edit: June 27, 2018, 01:17:50 pm by akbooer »
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.

Offline Buxton

  • Full Member
  • ***
  • Posts: 209
  • Karma: +12/-0
Re: openLuup startup error
« Reply #5 on: June 27, 2018, 06:12:36 pm »
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:
Code: [Select]
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.
« Last Edit: June 28, 2018, 12:57:07 am by Buxton »

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: openLuup startup error
« Reply #6 on: June 28, 2018, 06:07:57 am »
I did the update and I'm still seeing the sensor error.  I set a watch for the offending variable as follows;

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

Quote
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!
« Last Edit: June 28, 2018, 08:05:13 am by akbooer »
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.

Offline Buxton

  • Full Member
  • ***
  • Posts: 209
  • Karma: +12/-0
Re: openLuup startup error
« Reply #7 on: June 28, 2018, 06:42:01 pm »
No errors. Here's the log:
Code: [Select]
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?

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: openLuup startup error
« Reply #8 on: June 28, 2018, 06:48:18 pm »
Yes.  Unix epoch in seconds.
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.