Hoping I can get some support from some debug logs I pulled off my insteon system. The symptom is I have a few items on my network that seem to randomly fire when openhab is running. There are no unexpected log entries in “events” and nothing in “openhab” info level logs… but the “insteon” log I created at debug level shows activity, including a couple lines I can’t explain.
For reference: 2C.79.CE is the light in question (INSTEON 2443-222 Micro On/Off Module). 2B.91.48 is my controller (Insteon 2413U).
The times inquestion are:
2015-09-23 00:39:17 - LT_FF_MasterBath_ShowerLight state updated to ON
2015-09-23 01:49:17 - LT_FF_MasterBath_ShowerLight state updated to OFF
And here’s the debug log from the insteon binding:
2015-09-23 00:39:16 DEBUG o.o.b.i.i.device.InsteonDevice[:344]- qe taken off direct: GenericSwitch(1:1:4) OUT:Cmd:0x62|toAddress:2C.79.CE|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2015-09-23 00:39:16 DEBUG o.o.b.i.i.device.InsteonDevice[:364]- next request queue processed in 500 msec, quiettime = 500
2015-09-23 00:39:16 DEBUG o.o.b.i.internal.driver.Port[:320]- writing (500): OUT:Cmd:0x62|toAddress:2C.79.CE|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2015-09-23 00:39:17 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from 2F.74.A4 for another 19001 usec
2015-09-23 00:39:17 DEBUG o.o.b.i.i.device.InsteonDevice[:344]- qe taken off direct: ThermostatCoolSetPoint(1:1:2) OUT:Cmd:0x62|toAddress:31.70.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x01|userData2:0x00|userData3:0x01|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0x00|
2015-09-23 00:39:17 DEBUG o.o.b.i.i.device.InsteonDevice[:364]- next request queue processed in 1500 msec, quiettime = 500
2015-09-23 00:39:17 DEBUG o.o.b.i.i.d.RequestQueueManager[:129]- device queue for 2C.79.CE is empty!
2015-09-23 00:39:17 DEBUG o.o.b.i.InsteonPLMActiveBinding[:511]- got msg: IN:Cmd:0x50|fromAddress:2C.79.CE|toAddress:2B.91.48|messageFlags:0x27=ACK_OF_DIRECT:3:1|command1:0x00|command2:0xFF|
2015-09-23 00:39:17 DEBUG o.o.b.i.i.d.MessageDispatcher[:123]- defdisp: 2C.79.CE:GenericSwitch qs:QUERY_PENDING cmd: 80
2015-09-23 00:39:17 DEBUG o.o.b.i.i.d.MessageDispatcher[:129]- changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:2C.79.CE|toAddress:2B.91.48|messageFlags:0x27=ACK_OF_DIRECT:3:1|command1:0x00|command2:0xFF|
2015-09-23 00:39:17 DEBUG o.o.b.i.i.d.MessageDispatcher[:139]- 2C.79.CE:GenericSwitch->SwitchRequestReplyHandler DIRECT: IN:Cmd:0x50|fromAddress:2C.79.CE|toAddress:2B.91.48|messageFlags:0x27=ACK_OF_DIRECT:3:1|command1:0x00|command2:0xFF|
2015-09-23 00:39:17 INFO o.o.b.i.i.d.MessageHandler[:336]- SwitchRequestReplyHandler: set device 2C.79.CE to ON
2015-09-23 00:39:17 DEBUG o.o.b.i.i.device.DeviceFeature[:250]- 2C.79.CE:GenericSwitch publishing: ON
2015-09-23 00:39:17 DEBUG o.o.b.i.i.d.MessageDispatcher[:145]- defdisp: 2C.79.CE:GenericSwitch set status to: QUERY_ANSWERED
2015-09-23 00:39:17 DEBUG o.o.b.i.i.device.DeviceFeature[:250]- 2C.79.CE:GenericLastTime publishing: 2015-09-23T00:39:17
2015-09-23 00:39:17 DEBUG o.o.b.i.internal.driver.Port[:320]- writing (500): OUT:Cmd:0x62|toAddress:31.70.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x01|userData2:0x00|userData3:0x01|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0x00|
just before “set device 2C.79.CE to ON”, my controller seems to be the one sending the message: “changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:2C.79.CE|toAddress:2B.91.48”
any ideas what could be causing this?
Joe,
The outgoing message is a poll, querying the status of the device:
2015-09-23 00:39:16 DEBUG o.o.b.i.internal.driver.Port[:320]- writing
(500):
OUT:Cmd:0x62|toAddress:2C.79.CE|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
Back comes the reply: light level is at 0xFF, meaning the light is on:
interesting. Thanks Bernd. If the controller isn’t plugged in (i’ve had it disconnected for days), I never see this behavior. Is it possible the response in the log isn’t exactly what was sent… or is it more likely that the poll request is causing the relay to report a status and it’s reporting a faulty one… ultimately resulting in OH turning the device on
I guess I could power cycle the relay from my breaker box and see if the symptoms go away.
My last message was cut short. The part the was lost was a question as to what exactly the problem was.
Are the lights going on/off at times that you don’t want them? Seems like things are happening in the wee hours.
Disconnected controller… you mean the PLM modem was not plugged in?
I didn’t see any commands going out that would cause it to turn on. You have another controller running? Maybe an Insteon HUB? Anything else that could be switching the lights on/off?
Yes - this light, another light in our dining room, and one of my garage doors seem to randomly fire. It’s easiest to see it at night cause nothing else is going on, but I’ve noticed it during the day as well. Happens very sporadically, no pattern I’ve noticed yet.
yes, controller = plm modem. My apologies on confusion. My modem is plugged in. What I meant was, when I first noticed the issue, I unplugged it for a couple days to see if the problems went away, and they did. Testing further… I plugged the modem back in, but left OH offline, still no problem. Then turned OH on, and within a couple days, noticed the random fires again.
No other controllers running… I’ve thought about my switches and perhaps there’s a rogue association in them that i need to clean up (not easy)… but that wouldn’t explain the late night fires when no one is touching anything.
Got it.
One possibility is that the query message sent by the PLM somehow triggers the light to go on. Could be the message is garbled during transit (the extended messages have a checksum, but I don’t know about the standard messages used for On/Off and query), and triggers the wrong action then.
As far as the associations of your lights go, I suggest to have a look at the insteon terminal.
I am using it now all the time to link complicated devices like thermostats. I’d love to get feedback and improve it. It’s my bare bones HouseLinc replacement. And unlike HouseLinc it won’t eat your modem database (unless you really ask it to).
After a few lines of configuration you can type interactively:
kitchenLight.getdb()
and it will show you what devices the light is linked to as controller or responder, which group is being used etc.
help(kitchenLight) will tell you what methods you can use on the object.
If you have another controller (you have a spare Hub 2014 IIRC), you can use the insteon terminal to monitor the traffic going over the insteon network (using e.g. myhub.startWatch()).
That terminal looks amazing… First on my list to look at later this
week… Any chance this can run in parallel with the oh service?
Access to the serial port is exclusive, so you can run only one or the other on the same box.
But you can of course run the insteon terminal against a hub 2014 while openhab is running over your PLM modem.
So last night my son’s bathroom fan switched on multiple times when we were not even home, then again at 2am. It happens reliably when the device is queried. Rather than responding to the query, it suddenly acknowledges the receipt of a “ramp rate on command” cmd1=0x2e cmd2=0x02. No such command was ever sent to the device from anywhere. The switch is only linked to the modem, so no other device can possibly trigger it. How come it claims to have gotten a 0x2e 0x02 command?
It turns out that 3sec before the switch gets queried, the thermostat is queried via an extended command, which starts with … drum roll … 0x2e 0x02. So somehow every now and then this command gets picked up by the switch, although it is for a totally different device.
Bernd
