I’m trying to resolve an issue with the Powermaster 30 and this plugin (Running on a VeraLite, latest UI7). It looks like every now and then, the link between the alarm panel and the plugin is lost momentarily.
When the panel is disarmed, door sensor changes come through almost instantly, and I can have the setup run for days without a single Comms Error. The error appears to happen when arming / disarming the panel or when tripping a sensor while the panel is armed. Updates stop coming in and commands aren’t going out, until after a minute or so, when the log shows a pile of messages coming in, or Vera resets and shows another Comm Error in the plugin’s variables.
At first I suspected the serial cable, but I have tried with 2 different Serial to USB converters plugged into the Visonic serial board, and with one FTDI USB to TTL (3.3v) cable plugged directly into the 10 pin PC port on the alarm panel. Results are the same in all cases.
I talked to a reseller of Visonic Panels who has experienced the same issues in a similar setup (using VeraLite and UI7), but other people seem to have no issues using this alarm panel and the plugin.
At this stage, what can I do to diagnose this further? The logs are inconclusive, I posted a few snippets from a couple of trouble moments below.
06 08/18/17 12:13:49.848 Device_Variable::m_szValue_set device: 102 service: urn:micasaverde-com:serviceId:AlarmPartition2 variable: VendorStatus was: Away Exit Delay ,MEM,TRBL now: Armed Away ,MEM,TRBL #hooks: 0 upnp: 0 skip: 0 v:0xecc3f0/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.861 Device_Variable::m_szValue_set device: 102 service: urn:micasaverde-com:serviceId:AlarmPartition2 variable: VendorStatusCode was: 0217 now: 0547 #hooks: 0 upnp: 0 skip: 0 v:0xecc538/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.862 Device_Variable::m_szValue_set device: 102 service: urn:micasaverde-com:serviceId:AlarmPartition2 variable: VendorStatusData was: Ready, Alert in memory, Trouble, Last 10 seconds now: Ready, Alert in memory, Trouble, Status changed #hooks: 0 upnp: 0 skip: 0 v:0xecc608/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.862 Device_Variable::m_szValue_set device: 102 service: urn:micasaverde-com:serviceId:AlarmPartition2 variable: ArmMode was: Disarmed now: Armed #hooks: 0 upnp: 0 skip: 0 v:0xe73130/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.863 Device_Variable::m_szValue_set device: 102 service: urn:micasaverde-com:serviceId:AlarmPartition2 variable: ArmModeNum was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.864 Device_Variable::m_szValue_set device: 102 service: urn:micasaverde-com:serviceId:AlarmPartition2 variable: DetailedArmMode was: ExitDelay now: Armed #hooks: 0 upnp: 0 skip: 0 v:0xeca2c0/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.865 Device_Variable::m_szValue_set device: 103 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Armed was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xe75ba0/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.867 Device_Variable::m_szValue_set device: 104 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Armed was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xe75ba0/NONE duplicate:0 <0x2e840680>
50 08/18/17 12:13:49.869 luup_log:101: POWERMAX: Start of new PDU detected <0x2e840680>
50 08/18/17 12:13:49.870 luup_log:101: POWERMAX: Message A7; pmIncomingPduLen = 15 <0x2e840680>
50 08/18/17 12:13:49.890 luup_log:101: POWERMAX: PDU received 0D A7 FF 52 61 52 01 FF 00 06 00 00 43 08 0A <0x2e840680>
50 08/18/17 12:13:49.892 luup_log:101: POWERMAX: PDU sent to panel: 0D 02 43 BA 0A <0x2e840680>
50 08/18/17 12:13:49.894 luup_log:101: POWERMAX: System message: Arm Away / UNKNOWN <0x2e840680>
06 08/18/17 12:13:49.895 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusCode was: 1C now: 52 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.896 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusData was: General Restore / X10 07 now: Arm Away / UNKNOWN #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.897 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelAlarmType was: None now: None #hooks: 0 upnp: 0 skip: 0 v:0xc5c9b0/NONE duplicate:1 <0x2e840680>
06 08/18/17 12:13:49.897 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelTroubleType was: None now: None #hooks: 0 upnp: 0 skip: 0 v:0xe73840/NONE duplicate:1 <0x2e840680>
50 08/18/17 12:13:49.898 luup_log:101: POWERMAX: System message: / Zone 01 <0x2e840680>
06 08/18/17 12:13:49.899 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusCode was: 52 now: FF #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.900 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusData was: Arm Away / UNKNOWN now: / Zone 01 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.901 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelAlarmType was: None now: None #hooks: 0 upnp: 0 skip: 0 v:0xc5c9b0/NONE duplicate:1 <0x2e840680>
06 08/18/17 12:13:49.902 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelTroubleType was: None now: None #hooks: 0 upnp: 0 skip: 0 v:0xe73840/NONE duplicate:1 <0x2e840680>
50 08/18/17 12:13:49.902 luup_log:101: POWERMAX: System message: Tamper / System <0x2e840680>
06 08/18/17 12:13:49.903 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusCode was: FF now: 06 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.904 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusData was: / Zone 01 now: Tamper / System #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.905 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelAlarmType was: None now: Tamper #hooks: 0 upnp: 0 skip: 0 v:0xc5c9b0/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.906 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelTroubleType was: None now: None #hooks: 0 upnp: 0 skip: 0 v:0xe73840/NONE duplicate:1 <0x2e840680>
50 08/18/17 12:13:49.907 luup_log:101: POWERMAX: System message: None / System <0x2e840680>
06 08/18/17 12:13:49.907 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusCode was: 06 now: 00 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.908 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusData was: Tamper / System now: None / System #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.909 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelAlarmType was: Tamper now: None #hooks: 0 upnp: 0 skip: 0 v:0xc5c9b0/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.910 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelTroubleType was: None now: None #hooks: 0 upnp: 0 skip: 0 v:0xe73840/NONE duplicate:1 <0x2e840680>
50 08/18/17 12:13:49.911 luup_log:101: POWERMAX: System message: Tamper Alarm / X10 07 <0x2e840680>
06 08/18/17 12:13:49.912 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusCode was: 00 now: 08 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.912 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelStatusData was: None / System now: Tamper Alarm / X10 07 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.913 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelAlarmType was: None now: Tamper #hooks: 0 upnp: 0 skip: 0 v:0xc5c9b0/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:13:49.914 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PanelTroubleType was: None now: None #hooks: 0 upnp: 0 skip: 0 v:0xe73840/NONE duplicate:1 <0x2e840680>
01 08/18/17 12:13:49.915 LuaInterface::CallFunction-2 lu_incoming failed [string "module("L_Powermax", package.seeall)..."]:1889: bad argument #1 to 'band' (number expected, got nil) <0x2e840680>
50 08/18/17 12:16:57.101 luup_log:101: POWERMAX: Checking last alive message (delta = 80.00035905838) <0x2d9ff680>
50 08/18/17 12:16:57.101 luup_log:101: POWERMAX: Clear Powerlink communication error <0x2d9ff680>
50 08/18/17 12:16:57.103 luup_log:101: POWERMAX: PDU sent to panel: 0D AB 06 00 00 00 00 00 00 00 00 00 43 0B 0A <0x2d9ff680>
06 08/18/17 12:16:57.105 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: PowerlinkMode was: Powerlink now: Standard #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2d9ff680>
50 08/18/17 12:16:57.169 luup_log:101: POWERMAX: Truncating PDU 0D A7 FF 58 61 55 01 FF 00 06 00 00 43 FE 0A 0D 02 43 BA 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D 02 43 BA 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D 02 43 BA 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D 02 43 BA 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D 02 43 BA 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A 0D 02 43 <0x2e840680>
50 08/18/17 12:16:57.171 luup_log:101: POWERMAX: Start of new PDU detected; Expecting 02 A5 <0x2e840680>
50 08/18/17 12:16:57.171 luup_log:101: POWERMAX: Message A5; pmIncomingPduLen = 15 <0x2e840680>
50 08/18/17 12:16:57.176 luup_log:101: POWERMAX: PDU received 0D A5 10 01 00 00 00 00 00 00 00 00 43 06 0A <0x2e840680>
50 08/18/17 12:16:57.178 luup_log:101: POWERMAX: PDU sent to panel: 0D 02 43 BA 0A <0x2e840680>
50 08/18/17 12:16:57.180 luup_log:101: POWERMAX: *** Re-sending PDU (expected 02 got A5) *** <0x2e840680>
06 08/18/17 12:16:57.182 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: CommExceptions was: 2 now: 3 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
06 08/18/17 12:16:57.183 Device_Variable::m_szValue_set device: 101 service: urn:micasaverde-com:serviceId:PowermaxAlarmPanel1 variable: CommLastException was: 1502721305 now: 1503051417 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2e840680>
50 08/18/17 12:16:57.184 luup_log:101: POWERMAX: *** Houston - we have a communication problem (wrong response)! Executing a reload. *** <0x2e840680>
50 08/18/17 12:16:57.185 luup_log:101: POWERMAX: *** Send message delayed *** <0x2e840680>
50 08/18/17 12:28:47.506 luup_log:101: POWERMAX: Start of new PDU detected <0x2e9d0680>
50 08/18/17 12:28:47.507 luup_log:101: POWERMAX: Message B0; pmIncomingPduLen = 0 <0x2e9d0680>
50 08/18/17 12:28:47.509 luup_log:101: POWERMAX: Message B0; pmIncomingPduLen = 33 <0x2e9d0680>
50 08/18/17 12:28:47.538 luup_log:101: POWERMAX: CRC check failed (expected 4D, got 43) <0x2e9d0680>
50 08/18/17 12:28:47.539 luup_log:101: POWERMAX: PDU with CRC error 0D B0 03 24 1A FF 08 FF 15 00 00 00 00 02 00 00 00 0A 1C 0C 12 08 11 14 06 01 00 86 00 00 A2 43 0A <0x2e9d0680>