Insteon ManualChange event not recognised correctly OH2

mcqwerty · April 14, 2017, 9:39pm

OpenHAB 2.0 release build
Insteon plugin
2477D Switchlinc Dimmer firmware v0x45

The dimmer and the fastonoff are working as expected but manualchange is not.

Items:

Dimmer	MainFloor_Office_Dimmer__MainFloor_Office_CanLights__Dimmer			"Can Lights"				(gOffice)	{insteonplm="3D.F3.8C:F00.00.01#dimmer"}
Switch	MainFloor_Office_Dimmer__MainFloor_Office_CanLights_FastOnOff    	"Can Lights Fast OnOff"		(gOffice)	{insteonplm="3D.F3.8C:F00.00.01#fastonoff"}
Number	MainFloor_Office_Dimmer__MainFloor_Office_CanLights_ManualChange	"Can Lights Manual Change"	(gOffice)	{insteonplm="3D.F3.8C:F00.00.01#manualchange"}

Sitemap:

Frame label=“Office” {
Slider item=MainFloor_Office__Dimmer__Dimmer
Switch item=MainFloor_Office__Dimmer__FastOnOff
Text item=MainFloor_Office__Dimmer__ManualChange
}

When I hold down the paddle the light responds as expected, ramping up or down depending on the paddle direction and then stopping at the current value when the paddle is released.

I cannot get this ‘manualchange’, which I believe is represented as a number:
0=“DOWN”, 1=“STOP”, 2=“UP”
to be recognised by OpenHAB either in the sitemap or any rules.

I have been digging around in the log and in the source code of the plugin and I suspect the following is the culprit:

From the log:

2017-04-14 15:46:09 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-14 15:46:09 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-14 15:46:09 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-14 15:46:09 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-14 15:46:09 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-14 15:46:09 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 3D.F3.8C:GenericLastTime publishing: 2017-04-14T15:46:09
2017-04-14 15:46:11 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-14 15:46:11 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-14 15:46:11 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-14 15:46:11 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-14 15:46:11 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:3D.F3.8C|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-14 15:46:11 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 3D.F3.8C:GenericLastTime publishing: 2017-04-14T15:46:11

These messages look suspicious: messageFlags:0xCF=ALL_LINK_BROADCAST:3:3| since I found this in the plugin code:

/**
* The different kinds of Insteon ALL Link (Group) messages that can be received.
* Here is a typical sequence:
* BCAST:
* IN:Cmd:0x50|fromAddress:20.AC.99|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x13|
* command2:0x00|
* CLEAN:
* IN:Cmd:0x50|fromAddress:20.AC.99|toAddress:23.9B.65|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x13|command2
* :0x01|
* SUCCESS:
* IN:Cmd:0x50|fromAddress:20.AC.99|toAddress:13.03.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|
* command2:0x00|
*/

here: https://github.com/openhab/openhab1-addons/blob/db62be70e9cd9561036d8925a177a2e37aaa4bd4/bundles/binding/org.openhab.binding.insteonplm/src/main/java/org/openhab/binding/insteonplm/internal/device/GroupMessageStateMachine.java

Notice my messages are 0xCF, not 0xCB and also the numbers after the ‘ALL_LINK_MESSAGES’ are 3:3 and not 3:2.

I may be way off on my assumptions here, but I do know that I have tried this with multiple different devices of different types and always get a similar result, i.e nothing registered in the sitemap or by the rules.

Any insight would be greatly appreciated.
Thanks

mcqwerty · April 16, 2017, 7:07pm

@Bernd_Pfrommer, @dan_pfrommer, Hi, sorry for naming you explicitly, but I see from other posts you guys are the main players when it comes to Insteon in OpenHAB and I think my issue is quite specific to expect a good response from the general community.

Any help or suggestions would be gratefully received.

Thanks!

Bernd_Pfrommer · April 16, 2017, 9:32pm

I will get a message the moment something is tagged “insteon”, but a direct reference will also do

Let’s first make sure the binding does not produce any events on the bus. Can you look at the openhab events log and see what (if any) comes across the event bus. Only if you don’t see events there (but see on/off and other events just fine) should we start looking at the debug log and wrecking our brains as to what’s going wrong in the binding.

mcqwerty · April 16, 2017, 10:40pm

@Bernd_Pfrommer Thanks for the reply.

I decided to shut down OpenHAB, delete the logs and restart to get a better view of what was happening. I noticed something interesting…
After everything had started up, I used my lamplinc (since it is close to my desk) to ‘manual change up’ then ‘stop’.
Later I used the same lamplinc to ‘manual change down’ then stop.

Both the events.log and insteonplm.log files are below. You can see the ‘manual change up’ occur at 17:12:xx in both the events.log and insteonplm.log but the ‘manual change down’, (17:13:xx) in the insteonplm.log, is never shown in the events.log.

I tried this a few times for a few devices and it seems the very first manual change, up or down then stop, (per device) after a restart is captured as an event, but after that no further events are captured.

events.log:

2017-04-16 17:12:46.225 [ItemStateChangedEvent ] - lamplinc__ManualChange changed from NULL to 2
2017-04-16 17:12:49.959 [ItemStateChangedEvent ] - lamplinc__ManualChange changed from 2 to 1

insteonplm.log

2017-04-16 17:12:46 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 35.87.D5:FastOnOff->DefaultMsgHandler cmd1:0x17 group 1/-1:IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageHandler$DefaultMsgHandler.handleMessage(MessageHandler.java:338) - DefaultMsgHandler drop unimpl message 0x17: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 35.87.D5:ManualChange->StartManualChangeHandler cmd1:0x17 group 1/-1:IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageHandler$StartManualChangeHandler.handleMessage(MessageHandler.java:621) - StartManualChangeHandler: dev 35.87.D5 manual state change: UP
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 35.87.D5:ManualChange publishing: 2
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 35.87.D5:GenericDimmer->NoOpMsgHandler cmd1:0x17 group 1/1:IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-16 17:12:46 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 35.87.D5:GenericLastTime publishing: 2017-04-16T17:12:46
2017-04-16 17:12:47 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:459) - qe taken off direct: KeypadButtonGroup(0:0:0) OUT:Cmd:0x62|toAddress:33.0F.1C|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-04-16 17:12:47 org.openhab.binding.insteonplm.internal.driver.Port$IOStreamWriter.run(Port.java:415) - writing (500): OUT:Cmd:0x62|toAddress:33.0F.1C|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2017-04-16 17:12:47 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:479) - next request queue processed in 500 msec, quiettime = 500
2017-04-16 17:12:47 org.openhab.binding.insteonplm.internal.device.RequestQueueManager$RequestQueueReader.run(RequestQueueManager.java:137) - device queue for 33.0F.1C is empty!
2017-04-16 17:12:48 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.0F.1C|toAddress:44.31.A5|messageFlags:0x2B=ACK_OF_DIRECT:3:2|command1:0x16|command2:0x00|
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultGroupDispatcher.dispatch(MessageDispatcher.java:214) - 33.0F.1C:KeypadButtonGroup qs:QUERY_PENDING cmd: 80
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultGroupDispatcher.dispatch(MessageDispatcher.java:219) - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:33.0F.1C|toAddress:44.31.A5|messageFlags:0x2B=ACK_OF_DIRECT:3:2|command1:0x16|command2:0x00|
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.MessageHandler$SwitchRequestReplyHandler.handleMessage(MessageHandler.java:510) - SwitchRequestReplyHandler: dev 33.0F.1C button 2 switched to OFF
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.0F.1C:KeypadButton2 publishing: OFF
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.MessageHandler$SwitchRequestReplyHandler.handleMessage(MessageHandler.java:510) - SwitchRequestReplyHandler: dev 33.0F.1C button 3 switched to OFF
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.0F.1C:KeypadButton3 publishing: OFF
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.MessageHandler$SwitchRequestReplyHandler.handleMessage(MessageHandler.java:510) - SwitchRequestReplyHandler: dev 33.0F.1C button 4 switched to OFF
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.0F.1C:KeypadButton4 publishing: OFF
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.MessageHandler$SwitchRequestReplyHandler.handleMessage(MessageHandler.java:510) - SwitchRequestReplyHandler: dev 33.0F.1C button 5 switched to OFF
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.0F.1C:KeypadButton5 publishing: OFF
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultGroupDispatcher.dispatch(MessageDispatcher.java:244) - 33.0F.1C:KeypadButtonGroup set status to: QUERY_ANSWERED
2017-04-16 17:12:48 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.0F.1C:GenericLastTime publishing: 2017-04-16T17:12:48
2017-04-16 17:12:49 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 35.87.D5:ManualChange->StopManualChangeHandler cmd1:0x18 group 1/-1:IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.MessageHandler$StopManualChangeHandler.handleMessage(MessageHandler.java:637) - StopManualChangeHandler: dev 35.87.D5 manual state change: 0
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 35.87.D5:ManualChange publishing: 1
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 35.87.D5:GenericDimmer->DimmerStopManualChangeHandler cmd1:0x18 group 1/1:IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 35.87.D5:GenericLastTime publishing: 2017-04-16T17:12:49
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:459) - qe taken off direct: GenericDimmer(1:3:8) OUT:Cmd:0x62|toAddress:35.87.D5|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:473) - message write failed for msg OUT:Cmd:0x62|toAddress:35.87.D5|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
java.io.IOException: no ports configured for instrument 35.87.D5
at org.openhab.binding.insteonplm.internal.device.InsteonDevice.getPort(InsteonDevice.java:140)[211:org.openhab.binding.insteonplm:1.9.0]
at org.openhab.binding.insteonplm.internal.device.InsteonDevice.writeMessage(InsteonDevice.java:514)[211:org.openhab.binding.insteonplm:1.9.0]
at org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:471)[211:org.openhab.binding.insteonplm:1.9.0]
at org.openhab.binding.insteonplm.internal.device.RequestQueueManager$RequestQueueReader.run(RequestQueueManager.java:128)[211:org.openhab.binding.insteonplm:1.9.0]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-04-16 17:12:49 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:479) - next request queue processed in 2000 msec, quiettime = 2000
2017-04-16 17:12:51 org.openhab.binding.insteonplm.internal.device.RequestQueueManager$RequestQueueReader.run(RequestQueueManager.java:137) - device queue for 35.87.D5 is empty!
2017-04-16 17:12:52 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:19.8E.62|toAddress:44.31.A5|messageFlags:0x41=ALL_LINK_CLEANUP:1:0|command1:0x13|command2:0x01|
2017-04-16 17:12:52 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.handleMessage(InsteonPLMActiveBinding.java:676) - dropping message from unknown device with address 19.8E.62
2017-04-16 17:12:53 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:19.8E.62|toAddress:44.31.A5|messageFlags:0x47=ALL_LINK_CLEANUP:3:1|command1:0x13|command2:0x01|
2017-04-16 17:12:53 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.handleMessage(InsteonPLMActiveBinding.java:676) - dropping message from unknown device with address 19.8E.62
2017-04-16 17:13:14 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-16 17:13:14 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-16 17:13:14 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-16 17:13:14 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-16 17:13:14 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 35.87.D5:GenericLastTime publishing: 2017-04-16T17:13:14
2017-04-16 17:13:16 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:13:16 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:13:16 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:13:16 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:35.87.D5|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-16 17:13:16 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 35.87.D5:GenericLastTime publishing: 2017-04-16T17:13:16

Other events (standard dimmer and fastonoff are working fine)

2017-04-16 17:14:13.449 [ItemStateChangedEvent ] - lamplinc changed from NULL to 100
2017-04-16 17:14:19.500 [ItemStateChangedEvent ] - lamplinc changed from 100 to 0
2017-04-16 17:14:50.570 [ItemStateChangedEvent ] - lamplinc__FastOnOff changed from NULL to ON
2017-04-16 17:14:50.572 [ItemStateChangedEvent ] - lamplinc changed from 0 to 100
2017-04-16 17:14:56.759 [ItemStateChangedEvent ] - lamplinc__FastOnOff changed from ON to OFF
2017-04-16 17:14:56.761 [ItemStateChangedEvent ] - lamplinc changed from 100 to 0

I found it interesting that the fastonoff event also triggered an event on the standard dimmer item but the manualchange event (even the initial one that was registered), did not trigger an event on the standard dimmer item as I would have expected it to do.

More questions than answers here I know!

Thanks,

mcqwerty · April 22, 2017, 2:44pm

@Bernd_Pfrommer
Still trying to solve this issue… I did a factory reset on my PLM and a factory reset on one of my 2477D dimmers.
Using the button on the PLM, set it to linking mode, then linked to the 2477D using the button on the 2477D.
Using the button on the 2477D, set it to linking mode and then linked to the PLM using the button on the PLM.

Deleted my .items file and created a new one with only

Dimmer porch {insteonplm=“33.81.AD:F00.00.01#dimmer”}
Number porch_manchange {insteonplm=“33.81.AD:F00.00.01#manualchange”}

Shut down OpenHAB, deleted logs and restarted.

As far as I can see, my setup is now as clean and simple as it could be to test this issue.

I manually adjusted the dimmer using the sitemap and verified that an event was seen in the log and that the physical dimmer reacted.

2017-04-22 09:20:52.978 [ItemCommandEvent ] - Item ‘porch’ received command 54
2017-04-22 09:20:52.994 [ItemStateChangedEvent ] - porch changed from 0 to 54

I went to the dimmer switch and ‘manualchanged’ down using the paddle.
As seen before, OpenHAB registered this change, both, the manualchange start and end.
As expected it also registered the change in the ‘dimmer’ state

2017-04-22 09:21:32.881 [ItemStateChangedEvent ] - porch_manchange changed from NULL to 0
2017-04-22 09:21:34.393 [ItemStateChangedEvent ] - porch_manchange changed from 0 to 1
2017-04-22 09:21:34.822 [ItemStateChangedEvent ] - porch changed from 54 to 19

I then ‘manualchanged’ the dimmer up but nothing was registered in the event.log. I tried manualchanging down and nothing registered.

As before, only the the first manualchange then stop is ever registered as an event in the events.log.

My debug log is below, I really think it has something to do with the fact that my messages are 0xCF, not 0xCB and also the numbers after the ALL_LINK_MESSAGES are 3:3 and not 3:2.

Since the first event that worked, is in the format expected 0xCB=ALL_LINK_BROADCAST:3:2 format.

Please help as I have no more ideas and can’t get the OpenHAB code to build so I can’t even try to fix it myself.

Thanks!

2017-04-22 09:21:32 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 33.81.AD:FastOnOff->DefaultMsgHandler cmd1:0x17 group 1/-1:IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageHandler$DefaultMsgHandler.handleMessage(MessageHandler.java:338) - DefaultMsgHandler drop unimpl message 0x17: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 33.81.AD:DimmerRamp->DefaultMsgHandler cmd1:0x17 group 1/-1:IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageHandler$DefaultMsgHandler.handleMessage(MessageHandler.java:338) - DefaultMsgHandler drop unimpl message 0x17: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 33.81.AD:ManualChange->StartManualChangeHandler cmd1:0x17 group 1/-1:IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageHandler$StartManualChangeHandler.handleMessage(MessageHandler.java:621) - StartManualChangeHandler: dev 33.81.AD manual state change: DOWN
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:ManualChange publishing: 0
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 33.81.AD:Dimmer->NoOpMsgHandler cmd1:0x17 group 1/1:IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x00|
2017-04-22 09:21:32 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:GenericLastTime publishing: 2017-04-22T09:21:32
2017-04-22 09:21:34 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x18|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x18|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x18|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x18|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 33.81.AD:ManualChange->StopManualChangeHandler cmd1:0x18 group 1/-1:IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x18|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageHandler$StopManualChangeHandler.handleMessage(MessageHandler.java:637) - StopManualChangeHandler: dev 33.81.AD manual state change: 0
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:ManualChange publishing: 1
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x18|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:77) - all link message is no duplicate: true/true
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:79) - 33.81.AD:Dimmer->DimmerStopManualChangeHandler cmd1:0x18 group 1/1:IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x18|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:GenericLastTime publishing: 2017-04-22T09:21:34
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:459) - qe taken off direct: Dimmer(1:3:8) OUT:Cmd:0x62|toAddress:33.81.AD|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:479) - next request queue processed in 2000 msec, quiettime = 2000
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.driver.Port$IOStreamWriter.run(Port.java:415) - writing (500): OUT:Cmd:0x62|toAddress:33.81.AD|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:2F.B9.A3|messageFlags:0x2B=ACK_OF_DIRECT:3:2|command1:0x02|command2:0x32|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultDispatcher.dispatch(MessageDispatcher.java:149) - 33.81.AD:Dimmer DIRECT_ACK: q:QUERY_PENDING cmd: 80
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultDispatcher.dispatch(MessageDispatcher.java:154) - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:2F.B9.A3|messageFlags:0x2B=ACK_OF_DIRECT:3:2|command1:0x02|command2:0x32|
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageHandler$DimmerRequestReplyHandler.handleMessage(MessageHandler.java:588) - DimmerRequestReplyHandler: set device 33.81.AD to level 19
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:Dimmer publishing: 19
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultDispatcher.dispatch(MessageDispatcher.java:176) - defdisp: 33.81.AD:Dimmer set status to: QUERY_ANSWERED
2017-04-22 09:21:34 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:GenericLastTime publishing: 2017-04-22T09:21:34
2017-04-22 09:21:36 org.openhab.binding.insteonplm.internal.device.RequestQueueManager$RequestQueueReader.run(RequestQueueManager.java:137) - device queue for 33.81.AD is empty!
2017-04-22 09:22:58 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-22 09:22:58 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-22 09:22:58 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-22 09:22:58 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-22 09:22:58 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x17|command2:0x01|
2017-04-22 09:22:58 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:GenericLastTime publishing: 2017-04-22T09:22:58
2017-04-22 09:23:00 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-22 09:23:00 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-22 09:23:00 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-22 09:23:00 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-22 09:23:00 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-22 09:23:00 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:GenericLastTime publishing: 2017-04-22T09:23:00
2017-04-22 09:23:01 org.openhab.binding.insteonplm.InsteonPLMActiveBinding.logDeviceStatistics(InsteonPLMActiveBinding.java:684) - devices: 1 configured, 1 polling, msgs received: 11
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:459) - qe taken off direct: Dimmer(1:3:8) OUT:Cmd:0x62|toAddress:33.81.AD|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.InsteonDevice.processRequestQueue(InsteonDevice.java:479) - next request queue processed in 500 msec, quiettime = 500
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.driver.Port$IOStreamWriter.run(Port.java:415) - writing (500): OUT:Cmd:0x62|toAddress:33.81.AD|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2017-04-22 09:23:06 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:2F.B9.A3|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x02|command2:0xC5|
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultDispatcher.dispatch(MessageDispatcher.java:149) - 33.81.AD:Dimmer DIRECT_ACK: q:QUERY_PENDING cmd: 80
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultDispatcher.dispatch(MessageDispatcher.java:154) - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:2F.B9.A3|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x02|command2:0xC5|
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.MessageHandler$DimmerRequestReplyHandler.handleMessage(MessageHandler.java:588) - DimmerRequestReplyHandler: set device 33.81.AD to level 77
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:Dimmer publishing: 77
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.MessageDispatcher$DefaultDispatcher.dispatch(MessageDispatcher.java:176) - defdisp: 33.81.AD:Dimmer set status to: QUERY_ANSWERED
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:GenericLastTime publishing: 2017-04-22T09:23:06
2017-04-22 09:23:06 org.openhab.binding.insteonplm.internal.device.RequestQueueManager$RequestQueueReader.run(RequestQueueManager.java:137) - device queue for 33.81.AD is empty!
2017-04-22 09:24:07 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-22 09:24:07 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-22 09:24:07 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-22 09:24:07 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-22 09:24:07 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC7=ALL_LINK_BROADCAST:3:1|command1:0x17|command2:0x00|
2017-04-22 09:24:07 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:GenericLastTime publishing: 2017-04-22T09:24:07
2017-04-22 09:24:09 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x18|command2:0x00|
2017-04-22 09:24:09 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x18|command2:0x00|
2017-04-22 09:24:09 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x18|command2:0x00|
2017-04-22 09:24:09 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x18|command2:0x00|
2017-04-22 09:24:09 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:75) - all link message: IN:Cmd:0x50|fromAddress:33.81.AD|toAddress:00.00.01|messageFlags:0xC3=ALL_LINK_BROADCAST:3:0|command1:0x18|command2:0x00|
2017-04-22 09:24:09 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 33.81.AD:GenericLastTime publishing: 2017-04-22T09:24:09

Bernd_Pfrommer · April 22, 2017, 4:16pm

I have the same problem, am looking into it.
I strongly doubt that 3:3 vs 3:2 makes the difference. You can read up what it means.

mcqwerty · April 22, 2017, 4:38pm

@Bernd_Pfrommer
I bow to your far greater knowledge on the probable cause
Glad you are able to replicate, thanks for letting me know you are looking into it, I’m really looking forward to your findings.

Please let me know if there is any more information I can provide to help.

Thanks again

Bernd_Pfrommer · April 24, 2017, 1:12am

It looks to me like in several scenarios, the device provides no follow-up point-to-point message or cleanup report. Not just for the start/stop messages, but also for instance for brightness status. I don’t know why this is the case, and how I missed this during testing. Maybe this is a side effect of me introducing the state machine to weed out duplicates.
So what happens now is that the first message that comes in gets processed correctly, and all subsequent messages are dumped as duplicates of the first message.

The fix could be very simple or quite involved, I don’t know until I do it, but probably until early june I cannot spend time on it because I have too much other stuff going on. I can maybe spend an hour on it some time in between, but if that doesn’t pan out this has to wait, sorry.

mcqwerty · April 24, 2017, 1:19am

@Bernd_Pfrommer that makes sense, I’m glad there is clear explanation and its not just some randomness.

As for the timeline on the fix, I completely understand. If it takes until June then I can live with that as I can build out my system with the assumption that this functionality will be available in the future.

Thanks for keeping me updated and thanks for all your help.
Looking forward to the updated version and of course, I will be happy to test it out as soon as it is available.

Bernd_Pfrommer · April 29, 2017, 5:24pm

@mcqwerty, can you please test the jar file referenced in this pull request:

Thanks!

PS: the start/stop apparently does not send cleanup messages after a broad cast. Why I didn’t catch this in testing, and why nobody else has reported it is strange. The broadcast messages do get lost quite frequently, so whatever system you build on them will be to some extend fragile.

mcqwerty · April 29, 2017, 7:12pm

@Bernd_Pfrommer Thanks for the updated code!
I uninstalled the 1.9.0 binding via PaperUI stopped OpenHAB, downloaded the .jar file, placed it in the \addons directory and restarted OpenHAB.
It doesn’t look like OpenHAB is loading the binding. I see nothing in the insteonplm.log file whereas with the ‘release’ binding I see all the usual messages about connecting to the PLM and finding devices etc.
Also with the snapshot binding the openhab.log describes my insteon devices as ‘unknown’

I noticed in your comments in the GitHub item you wrote

Here is the link to a jar file that should be a drop-in for OH 1.8:

I am running OpenHAB 2.0 could this be the reason am having problems?

I am successfully running the 1.10.0-SNAPSHOT of the MyQ binding, and I installed that int the same way without issue so I’m not sure what I have done wrong.

Thanks!

Bernd_Pfrommer · April 29, 2017, 7:39pm

I don’t run OH 2.0 so I cannot rule out that this is an issue but from what I understand the 1.10 jar files should run under OH 2.0. They definitely run under OH 1.8. Even in OH 2.0 you should at the very least get some error messages from the OH 2.0 runtime environment that the jar file is not properly loading. Double check that you have put the jar file in the right folder, and that the file permissions are correct. Restart OH2.0 for good measure.

mcqwerty · April 29, 2017, 8:12pm

@Bernd_Pfrommer
Figured it out: I was getting Unresolved requirement: Import-Package: gnu.io in the log for other bindings after I uninstalled the release version of your InsteonPLM binding.

After some googleing I decided to install (via PaperUI) the serial binding since the google chatter seemed to link this error to bindings that use serial communication.

Anyway, that solved the problem! Looks like gnu.io was installed by your InsteonPLM binding in OH2 and then uninstalling the binding removed it even though it was a dependency of other bindings, but since they were installed via .jar files in the bindings directory they also failed. I don’t know if I am making any sense but those are my findings.

I tested out the manualchange and it works great! I only had time for a quick test but I was getting events for the first and subsequent changes.
I will test more later when I have more time.

Thanks for all your help and fast response!!!

mcqwerty · April 30, 2017, 6:59pm

@Bernd_Pfrommer While ‘manualchange’ now seems to be working great for my 2477D dimmers, (thanks again ), I am having trouble with my 2334-222 keypad.

Specifically, I am trying to detect a manualchange on the Keypad Button8.

Items:

Switch	Keypad_ButtonH__Switch			"ButtonH Switch"						{insteonplm="38.FC.C1:F00.00.16#keypadbuttonH,group=0xA8"}
Number	Keypad_ButtonH__ManualChange	"Window Shades {Manual Change} [%s]"	{insteonplm="38.FC.C1:F00.00.16#keypadbuttonHmanualchange"}

I enabled this feature by creating an updated version of the F00.00.16 device and ensuring it was loaded from my custom more_devices.xml

  <device productKey="F00.00.16">
     <model>2334-222</model>
     <description>KeypadLinc Dimmer, 8-Button </description>
     ...
	 <feature_group name="keypadbuttongroupmanualchange" type="ManualChangeButtonGroup">
     	...
		<feature name="keypadbuttonHmanualchange">ManualChangeButton8</feature>
     </feature_group>
	 ...
 </device>

I am confident that my custom device file is being loaded and used correclty. I am also confident that this keypad supports this feature as when included in a scene the button is able to ‘manually control’ a linked light for example.

The issue is that the state of the Keypad_ButtonH__ManualChange item is never updated when the button is ‘long pressed’ in either direction (dim up/dim down).

Log below:

2017-04-30 13:21:39 org.openhab.binding.insteonplm.InsteonPLMActiveBinding$PortListener.msg(InsteonPLMActiveBinding.java:591) - got msg: IN:Cmd:0x50|fromAddress:38.FC.C1|toAddress:00.00.08|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x18|command2:0x00|
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: KeyPadButton4
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: KeyPadButton5
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: KeyPadButton2
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: KeyPadButton3
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: KeyPadButtonGroup
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: LoadDimmerButton
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:83) - message ignored because matches group: false matches filter: true
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: LoadDimmerFastOnOff
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: KeyPadButton8
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: KeyPadButton6
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: KeyPadButton7
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: ManualChange
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:78) - 38.FC.C1:ManualChange->StopManualChangeHandler cmd1:0x18 group 8/-1
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageHandler$StopManualChangeHandler.handleMessage(MessageHandler.java:655) - StopManualChangeHandler: dev 38.FC.C1 manual state change: 0
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 38.FC.C1:ManualChange publishing: 1
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.InsteonDevice.handleMessage(InsteonDevice.java:306) - ----- applying message to feature: LoadDimmerRamp
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.MessageDispatcher.handleAllLinkMessage(MessageDispatcher.java:73) - msg is not for this feature
2017-04-30 13:21:39 org.openhab.binding.insteonplm.internal.device.DeviceFeature.publish(DeviceFeature.java:321) - 38.FC.C1:GenericLastTime publishing: 2017-04-30T13:21:39

Would you expect this to work and I have made a mistake somewhere in my setup or is this feature not currently implemented?

Thanks

Bernd_Pfrommer · May 1, 2017, 3:34pm

From the logs it logs like it’s publishing something. Is that not what you wanted?

mcqwerty · May 1, 2017, 4:37pm

This is what I wanted, and sorry I was totally unclear in my previous post.
The issue is that my rule(s) are not being triggered.

rule "changed"
when 
	Item Keypad_ButtonH__ManualChange changed
then
	logDebug("myLogger", "***Changed***")
	logDebug("myLogger", "Current state: " + Keypad_ButtonH__ManualChange.state)
	logDebug("myLogger", "Prev state: " + previousState)
end

rule "update"
when 
	Item Keypad_ButtonH__ManualChange received update
then
	logDebug("myLogger", "***Received Update***")
	logDebug("myLogger", "Current state: " + Keypad_ButtonH__ManualChange.state)
end

I am confident the logger is correctly set up as I see debug messages from other rules in this .rules file in the log.

Since the insteon.plm log shows that it is publishing something, does that mean my devices xml file is correct?
I don’t see any events in the OH2 events.log so I suppose that is why my rules are not firing.

Seems like I am close but missing something simple?

Thanks

Bernd_Pfrommer · May 1, 2017, 8:09pm

You should look in the openhab event log. If there is an openhab event generated, then the problem is with the rule, not with the binding. That’s the first thing to pin down.

mcqwerty · May 1, 2017, 8:53pm

@Bernd_Pfrommer I mentioned this in my previous post but the multiple typos (now fixed with an edit), must have caused you to miss it, sorry.

Since I am not getting anything in the events.log I am a bit stuck. If you think the insteonplm.log looks good then is this is a bug somewhere inside the OpenHAB code??

Bernd_Pfrommer · May 1, 2017, 10:11pm

I’m not sure. You can switch on trace logging (that will give you lots of data, please don’t post it). Then try to see if you see these trace messages from the DeviceFeatureListener class. They should definitely tell us if it goes out on the openhab bus.

    /**
 * Publishes a state change on the openhab bus
 * 
 * @param state the new state to publish on the openhab bus
 * @param changeType whether to always publish or not
 */
public void stateChanged(State state, StateChangeType changeType) {
    State oldState = m_state.get(state.getClass());
    if (oldState == null) {
        logger.trace("new state: {}:{}", state.getClass().getSimpleName(), state);
        // state has changed, must publish
        publishState(state);
    } else {
        logger.trace("old state: {}:{}=?{}", state.getClass().getSimpleName(), oldState, state);
        // only publish if state has changed or it is requested explicitly
        if (changeType == StateChangeType.ALWAYS || !oldState.equals(state)) {
            publishState(state);
        }
    }
    m_state.put(state.getClass(), state);
}

mcqwerty · May 4, 2017, 1:38am

Thanks for your patience and continued help, I found the problem and it was all user error.
Despite my confidence that my custom devices.xml was being loaded, it was not. I fixed the file location that was causing the issue and now everything is working!

Thank you @Bernd_Pfrommer!