openLuup: Visonic Powermax

Plugins & Plugin Development openLuup
#1

I’ve been testing openLuup / AltUI with the Visonic Powermax plugin.

A few hurdles to jump over (detailed elsewhere) but the plugin was up and running, I just needed to test it against a live alarm panel.

I was following the recent changes to openLuup in the Ademco thread as the IO work completed there was very relevant :slight_smile:

So I’ve gone further today and removed my live panel from my real Vera and across to openLuup using an RS232 <-> Ethernet connector and all seems OK - plugin starts and connects, downloads zone data, I can interact with the panel (arm/disarm/etc) … all seems pretty much identical to running on my real Vera which is pretty awesome!

BUT (sorry!) after a random amount of time the plugin stops running :frowning:

I’m not sure if this is a problem with openLuup, or perhaps an issue with the RS232 <-> Ethernet connector - although this seems to still be alive and a simple openLuup reload gets things working again.

I can move the real Vera over to using IP (it was previously using direct RS232 <-> USB before) and see if the problem still occurs as I guess that would rule out the hardware side.

The only thing I can see from the logs is a socket closed message, but no indication why it’s closed. There are no timeouts on the RS232 <-> Ethernet connector, that is, it’s set to never timeout, so as far as I can see openLuup should never get a failure from the connector.

There’s obviously a lot of moving parts here (pretty amazing that it’s gotten this far) but any ideas on where to begin troubleshooting?

2016-02-02 11:54:45.112 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.112 luup_log:5: POWERMAX: Message AB; pmIncomingPduLen = 15 2016-02-02 11:54:45.113 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.130 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.130 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.130 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.130 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.130 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.130 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.131 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.131 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.131 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.131 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.131 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.131 luup.io.incoming:5: bytes received: 1, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:45.131 luup_log:5: POWERMAX: PDU received 0D AB 03 00 1E 00 33 34 32 35 00 00 43 21 0A 2016-02-02 11:54:45.131 luup_log:5: POWERMAX: PDU sent to panel: 0D 02 43 BA 0A 2016-02-02 11:54:45.131 luup.io.write:5: message length: 5, bytes sent: 5, status: OK tcp{client}: 0x1710c58 2016-02-02 11:54:48.135 luup_log:4: xAP Notifier - INFO: updateDeviceStatusWithValue for w_switch#38#urn:upnp-org:serviceId:SwitchPower1#Status with value 0 2016-02-02 11:54:48.135 luup_log:4: xAP Notifier - INFO: w_switch(38/urn:upnp-org:serviceId:SwitchPower1/Status/0/0) room:Downstairs Hall description:PGM (PowerMax) 2016-02-02 11:54:50.137 luup_log:5: POWERMAX: Checking last alive message (delta = 5.0059721469879) 2016-02-02 11:54:50.137 luup.call_timer:5: interval: time=20s, days={} 2016-02-02 11:55:01.152 openLuup.server:: request completed (411 bytes, 1 chunks, 60185 ms) tcp{client}: 0x171bac8 2016-02-02 11:55:01.258 openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=413431999&Timeout=60&MinimumDelay=1500&_=1454412043895 tcp{client}: 0x171bac8 2016-02-02 11:55:10.269 luup_log:5: POWERMAX: Checking last alive message (delta = 25.137422084808) 2016-02-02 11:55:10.269 luup.call_timer:5: interval: time=20s, days={} 2016-02-02 11:55:30.292 luup_log:5: POWERMAX: Checking last alive message (delta = 45.160835981369) 2016-02-02 11:55:30.292 luup.call_timer:5: interval: time=20s, days={} 2016-02-02 11:55:39.319 openLuup.io:5: socket connection closed tcp{client}: 0x1710c58 2016-02-02 11:55:50.332 luup_log:5: POWERMAX: Checking last alive message (delta = 65.201023101807) 2016-02-02 11:55:50.332 luup_log:5: POWERMAX: Clear Powerlink communication error 2016-02-02 11:55:50.332 luup_log:5: POWERMAX: PDU sent to panel: 0D AB 06 00 00 00 00 00 00 00 00 00 43 0B 0A 2016-02-02 11:55:55.338 luup.io.write:5: error: timeout tcp{client}: 0x1710c58 2016-02-02 11:55:55.338 luup_log:5: POWERMAX: cannot send PDU 2016-02-02 11:55:55.338 luup.set_failure:5: status = true 2016-02-02 11:55:55.338 luup_log:5: POWERMAX: *** Re-sending PDU (got no response) *** 2016-02-02 11:55:55.338 openLuup.context_switch:: ERROR: ./L_Powermax.lua:605: assertion failed! 2016-02-02 11:55:55.338 luup.delay_callback:: function: 0x170d820 ERROR: ./L_Powermax.lua:605: assertion failed!

#2

Oh wow! A lot of moving parts, as you say.

Glad the I/O improvements got you further. Interested, of course, in your hardware check on Vera.

Whilst you say the socket close occurs randomly, I notice that its about 60 seconds after the last activity on the socket. if you’ve got other logs to look at, can you check to see if this is consistent?

The LuaSocket library timeouts are turning out to be a real pain - I’ll go through the code again and see if I can see anything, but my testing hasn’t shown up this problem. (OK, I need better testing.) I’ll also take a look to see if I can (again) improve the log messages to get a better diagnostic.

One of the fundamental failings of the MiOS I/O architecture is that there is no luup.io.close() which would allow failover code to be written to recover from situations such as this. Whilst I can do anything I like in openLuup, I’m very loathe to depart from the real Luup behaviour. What surprises me is that plugin developers for this type of application have opted to use the built-in luup ‘capabilities’ rather than going directly for a LuaSocket implementation.

I’m keen that you get this going, no least because I’m hoping for a write-up from you of the ethernet-serial bridge, because this can be a lot of help to others and widens the type of devices which can easily attach to openLuup.

#3

Hey akbooer, thanks for the quick response!

I changed the real Vera to use the serial/ethernet bridge just after I posted the last message and it’s been running rock solid since then (I temporarily stopped openLuup).

I can re-check the timing on when the socket close occurs, I said random but of course I never actually timed it, so it could be consistent.

As far as I can see the Visonic plugin sends a “keep-alive” message every 20 seconds, so there shouldn’t be a reason for the socket to close due to lack of activity?

The serial/ethernet stuff is pretty interesting :slight_smile: There should be no reason why any plugin that uses serial can’t function under openLuup because as far as I can see Vera actually uses serial<->ethernet behind the scenes anyway for all serial devices.

Every time you add a serial port it starts an instance of a serial proxy and “serves” the serial connection over tcp. So any plugin that is using a serial port is actually using serial over ethernet, it just doesn’t know it.

And of course, no problem in writing up once it’s all up and running :slight_smile:

#4

Just thought I’d follow up on this, I left the serial <-> ethernet converter running on the panel with my real Vera and it’s been rock solid for the past few days.

So something is definitely different when running under openLuup :frowning:

Hopefully will find some time at the weekend to switch back to openLuup and see if I can figure out what is causing the socket to close and see if it’s a repeatable pattern or timing.

#5

OK, good luck. The only possible programming trick I’ve found so far is that you might try:

sock: setoption ("keepalive", true)

According to the documentation at LuaSocket: TCP/IP support it says:

'keepalive': Setting this option to true enables the periodic transmission of messages on a connected socket. Should the connected party fail to respond to these messages, the connection is considered broken and processes using the socket are notified;

This should not interfere with the regular TCP message protocol AFAIK

#6

I was impatient and tried adding the keepalive option straight away:-)

Seems to have done the trick, been running on openLuup for 4 hours now without issue! Previously it would only last randomly for a five or ten minutes or so.

I’ll leave it running overnight and then remove the keepalive tomorrow and retest - IF the keepalive is the solution then I would expect the same socket close issues to re-occur once the keepalive has been removed.

Will let you know!

#7

Any update on this? I realise I haven’t put the keep alive option into the latest GitHub release yet…

#8

Hey akbooer,

Yes, sorry, I did re-test after removing the keepalive and got the same socket close issues as before.

Re-adding the keepalive got things working again and I’ve let it run since then to be sure it’s all good before posting back.

So yeah, all working perfectly and 100% stable - there’s been several AltUI updates along the way, each with an associated openLuup reload and as far as I can see it’s never missed a beat.

I’ll pull all the steps I took together for a write up in the next few days … it’s a bit hacky because I had to set things like IP addresses and config variables manually as the UI side for configuring the plugin is messed up, so anybody that wants that working would probably need to approach the original plugin author.

But from a functionality point of view it’s all there … and this has been fantastic for me as I’ve been slowly moving my Veras towards being “radio only” (no logic, no plugins, just Z-Wave devices). The Visonic plugin was the last headache that I’d been struggling with in trying to replicate the functions elsewhere :slight_smile:

Well pleased!

#9

Excellent news! Glad you’re pleased too. I’ll update GitHub appropriately. Where, exactly DID you put the keepalive? Just after the socket open, I presume.

#10

I put it in the connect function in io.lua just after the other sock:setoption:

 if sock then
      sock:settimeout (OPEN_SOCKET_TIMEOUT)
      sock:setoption ("tcp-nodelay", true)    -- so that alternate read/write works as expected (no buffering)
      sock:setoption ("keepalive", true)    -- keepalive
      ok, msg = sock:connect (ip, port) 
end
#11

Thanks - the GitHub master has now been updated with a hot fix.

#12

Hi,

I test to run openLuup / AltUI with the Visonic Powermax plugin on my Rpi2 but this don’t work.
How add plugin Powermax in the AltUI ?

Thank you

#13

Hi,

I’ve been meaning to retrace my steps and write this up for a while now!

The following assumptions are made:

[ol][li]You already have a working installation of openLuup and AltUI[/li]
[li]You have a way to present your Visonic Alarm Panel over IP (either a serial (from the panel) to IP device or a USB to FTDI (at the panel) device with something like ser2net)[/li]
[li]You have tested the above connectivity and it is working (likely using the plugin on a real Vera)[/li]
[li]You have some experience in tinkering & fiddling with the lower workings of Vera :)[/li][/ol]

The following are the steps I took to get the latest version of the Visonic plugin working under openLuup and AltUI:

[ol][li]Transfer the latest plugin files to your openLuup base directory (I pulled the plugin files off a working Vera, you could also download them from the MiOS repo)[/li]
[li]Add the function listed at the bottom of this post to J_Powermax.js (this fixes an issue where the plugin relies on a function included in one of the real Vera UI files)[/li]
[li]Transfer any supporting files to your openLuup base directory (from memory these were D_DoorSensor1., D_MotionSensor1., D_SmokeSensor1., D_BinaryLight1., D_DimmableLight1., D.Siren1., D_Keypad1.*). You’ll probably want to make sure that appropriate icons are in place too - you might have already done this during openLuup setup[/li]
[li]Create the alarm panel device in AltUI (using D_Powermax.xml)[/li]
[li]Reload openLuup and tail the log file to see if any errors are thrown[/li]
[li]Install any missing dependencies appropriately (these will vary depending on your openLuup base install, I had to install the LUA “bit” library and also had to fix some issues with the socket & ssl libs due to running on an older version of Debian)[/li]
[li]Repeat above two steps until log file looks clean - should now get as far as the plugin asking to set the serial port[/li]
[li]The config settings that you normally access on the alarm panel device are messed up, so you’ll need to set the ip and port of your serial <-> ethernet / ser2net instance. I did this directly by modifying the file L_Powermax.lua in function pmStartup, you can also do it by setting the ip attribute from AltUI I believe[/li]
[li]Reload openLuup and tail the log file again to see if there are any errors - the plugin should now at least make contact with the panel[/li]
[li]Use AltUi to manually set the appropriate variables on the alarm panel device to match your installation (for example to auto create the zones)[/li]
[li]Reload openLuup once more and that should be it, the plugin should be up and running, I used the auto create zones setting and several reloads later all my zones were present[/li]
[li]During this process keep tailing the log file and watch for any errors (missing .xml files for device types mostly) - correct them as required and reload openLuup again[/li]
[li]You can also set the debug variable for the plugin which will create additional files in your /var/log/cmh folder that look like "?powermax.txt - these can be helpful for tracing errors[/li][/ol]

That was pretty much it, sounds complicated but really wasn’t ;D

function pulldown_from_array(dataArray,objID,selectedValue,extra){
    var html = '';
    try {
        var dataLen=dataArray.length;
        html='<select id="'+objID+'" '+extra+' class="styled">';
        for(var i=0;i<dataLen;i++){
            html+='<option value="'+dataArray[i]['value']+'" '+((dataArray[i]['value']==selectedValue)?'selected':'')+'>'+dataArray[i]['label']+'</option>';
        }
        html+='</select>';
    } catch (exception) {
        //Utils.logError('Legacy code: pulldown_from_array(): ' + exception);
    }

    return html;
}
#14

Thanks for that comprehensive write up. It almost makes me wish I had a Visionic system!

#15

Thank you for this information… :slight_smile:

I purchased a RS232 by Ethernet.
I test at the delivery…

#16

Hey akbooer,

Had a small blip with openLuup a few days ago where I experienced a timeout and the Visonic plugin died. This may have been caused by external events (I relocated the RS232 <-> Ethernet adapter a few hours earlier) so I’m fairly sure that there’s no specific problem.

But what I wanted to check is the logging around the time it happened as there seemed to be a couple of errors that looked like openLuup errors:

2016-02-27 20:11:02.950   luup_log:5: POWERMAX: PDU received 0D A5 00 02 00 00 00 02 00 00 00 00 43 13 0A 
2016-02-27 20:11:02.950   luup_log:5: POWERMAX: PDU sent to panel: 0D 02 43 BA 0A 
2016-02-27 20:11:02.950   luup.io.write:5: message length: 5, bytes sent: 5, status: OK tcp{client}: 0x1d26b78
2016-02-27 20:11:02.950   luup_log:5: POWERMAX: Received zone status message
2016-02-27 20:11:17.468   luup_log:5: POWERMAX: Checking last alive message (delta = 16.555998802185)
2016-02-27 20:11:17.468   luup.call_timer:5: interval: time=20s, days={}
2016-02-27 20:11:37.492   luup_log:5: POWERMAX: Checking last alive message (delta = 36.580392837524)
2016-02-27 20:11:37.492   luup.call_timer:5: interval: time=20s, days={}
2016-02-27 20:11:45.001   openLuup.heartbeat:: memory: 3.8Mb, uptime: 0.13 days, cpu: 4.2 sec (0.04%)
2016-02-27 20:11:48.523   openLuup.server:: request completed (412 bytes, 1 chunks, 60446 ms) tcp{client}: 0x1d3c218
2016-02-27 20:11:48.631   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=592379727&Timeout=60&MinimumDelay=1500&_=1456483430844 tcp{client}: 0x1d3c218
2016-02-27 20:11:57.142   luup_log:5: POWERMAX: Checking last alive message (delta = 56.230008840561)
2016-02-27 20:11:57.142   luup.call_timer:5: interval: time=20s, days={}
2016-02-27 20:12:17.166   luup_log:5: POWERMAX: Checking last alive message (delta = 76.253706932068)
2016-02-27 20:12:17.166   luup_log:5: POWERMAX: Clear Powerlink communication error
2016-02-27 20:12:17.166   luup_log:5: POWERMAX: PDU sent to panel: 0D AB 06 00 00 00 00 00 00 00 00 00 43 0B 0A 
2016-02-27 20:12:17.166   luup.io.write:5: message length: 15, bytes sent: 15, status: OK tcp{client}: 0x1d26b78
2016-02-27 20:12:17.166   luup.call_timer:5: interval: time=20s, days={}
2016-02-27 20:12:17.171   openLuup.io:5: socket connection closed tcp{client}: 0x1d26b78
2016-02-27 20:12:37.195   luup_log:5: POWERMAX: Checking last alive message (delta = 20.029561042786)
2016-02-27 20:12:37.195   luup_log:5: POWERMAX: *** Re-sending PDU (got no response) ***
2016-02-27 20:12:37.195   luup_log:5: POWERMAX: PDU sent to panel: 0D AB 06 00 00 00 00 00 00 00 00 00 43 0B 0A 
2016-02-27 20:12:42.200   luup.io.write:5: error: timeout tcp{client}: 0x1d26b78
2016-02-27 20:12:42.200   luup_log:5: POWERMAX: cannot send PDU
2016-02-27 20:12:42.200   luup.set_failure:5: status = true
2016-02-27 20:12:42.201   luup.call_timer:5: interval: time=20s, days={}
2016-02-27 20:12:48.710   openLuup.server:: request completed (412 bytes, 1 chunks, 60078 ms) tcp{client}: 0x1d3c218
2016-02-27 20:12:48.818   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=592379727&Timeout=60&MinimumDelay=1500&_=1456483430845 tcp{client}: 0x1d3c218
2016-02-27 20:13:02.334   luup_log:5: POWERMAX: Checking last alive message (delta = 45.168638944626)
2016-02-27 20:13:02.334   luup_log:5: POWERMAX: *** Re-sending PDU (got no response) ***
2016-02-27 20:13:02.334   openLuup.context_switch::  ERROR: ./L_Powermax.lua:605: assertion failed!
2016-02-27 20:13:02.334   luup.delay_callback:: function: 0x1d23740 ERROR: ./L_Powermax.lua:605: assertion failed!

openLuup carried on running and a reload brought the plugin back to life without issue (and it’s been running again for 48 hours solid now), but those last two entries in the log looked like a problem raising the error (argument to assert was nil?). It may well be an issue in the error handling of the plugin of course, but from past experience the plugin has always raised errors correctly even in extreme error situations, so thought I’d check with you first :slight_smile:

#17

I’m not familiar with the plugin or the hardware, so some guesswork required here…

What’s clear is that there’s a delay callback, every 20 seconds, which checks the last communication time with the device. The last time it successfully does that, the interval has reached 76 seconds. What I don’t know, but you can find out, is what the normal operating value for this should be. I could guess that it was 60 seconds, in which case something has already gone wrong at the device.

In trying to clear the error, the plugin logic sends a message and reset the delay callback. However, the TCP socket then returns a ‘closed’ status, so I’m guessing again that the message doesn’t get sent. This is the fatal blow, because in the Vera/MiOS model of plugin I/O there’s no recovery mechanism: what do you do? Try to reopen a new socket to the device? … in fact, the plugin tries to send again.

The last two entries aren’t, per se, openLuup errors, although it reports them. They are from the same line of the plugin code (which I have yet to look at.)

As further diagnostic, I’d be really interested in what the Vera logs look like when you break the communication link with the panel, but this would probably be a pain to set up. You indicate that it seems robust, but unless I am missing something, Vera itself should not be able to recover from such a situation.

Great reporting of the error, if I may say. I wish everybody managed such brevity and clarity of a problem situation! The relevant log entries really help.

#18

If memory serves me correctly what used to happen on a real Vera is that the plugin would retry several times and on each failure it would increment the variable:

urn:micasaverde-com:serviceId:PowermaxAlamPanel1:CommExceptions

and set the date in

urn:micasaverde-com:serviceId:PowermaxAlamPanel1:CommLastException

I think that after 3 exceptions it would display an error message in the Vera UI (at the top) and stop trying to access the panel. You then had to fix the error, clear out the 2 variables and reload LUUP to get things up and running again.

I’ve attached a screenshot of the variables as they stand - you can see that the last time it was set was at the beginning of February which I think was when I got this stuff originally up and running.

Line 605 in the plugin seems to be a simple test true / false against the length:

function pmCalcCRC(pdu)
   local checksum = 0
   local newPDU
   local len = string.len(pdu)

   assert(len >= 2)
   for i = 2, (len - 2) do
      checksum = checksum + tonumber(string.byte(pdu, i))
   end   
   checksum = 0xFF - (checksum % 0xFF)
   if (checksum == 0xFF) then checksum = 0x00 end
   newPDU = string.sub(pdu, 1, len - 2) .. string.char(checksum, 0x0A)
   return newPDU
end

I guess I expected that the plugin would continue to try and re-connect as opposed to stop dead.

Apologies there’s a lot of guessing going on here, as you said, it will be a pain to setup and test this against a real Vera at this stage!

#19

We must be looking at slightly different versions - my line count is about 5 off from yours. I simply downloaded the plugin from the App store to Vera and then copied the file. What’s odd is that this code is called to calculate a checksum for sending a message, nothing directly to do with received data. I think it will be hard to continue. Let’s hope it was just a hardware glitch that doesn’t happen again for a long while.

#20

Yeah my version will probably be a bit different as I modified it a bit to hard code the IP address and a few other changes I think.

I think we can leave it for now, if it happens again I will setup another Vera with a test panel and see if I can reproduce it in order to determine what the correct behaviour should be.