Insteon Binding - Lights Turn Off 17 Seconds After Event Log Reports State Change to Off

[Burzin_Sumariwalla]

Platform Information

• Hardware: Raspberry Pi 3B+
• OS: Raspberry Pi OS (32 Bit - Buster)
• Java Runtime Environment:
• openjdk version “1.8.0_152”
• OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
• OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
• Jython 2.7.0
• openHAB 2.5.5 (Release Build)

Hello,

I’m using the new Insteon binding for openHAB2. While migrating to JSR223/Python rules, I discovered that my lights are turning off many seconds after the state is reporting off. Based upon
timings, this doesn’t appear to related to the JSR223/Python migration. Rather, there seems to be a significant delay between a report of a state change to off and the actual time the off command is received and executed by the Insteon switches.

I’ve repeated this several times, though I have not measured it each time. For this particular occurrence, I enabled TRACE logging on the Insteon binding. The TRACE logging is rather significant, so I attached the logs for the timeline reported below.

Insteon_TRACE_log.txt (492.3 KB)

Does anyone have any clue as why the non-trace logging seems to indicate that the switches (and therefore the lights) turned off at one time, while the trace logging shows a significantly different time.

This is the timeline of a sample occurrence.

• Phone goes offline: 2020-06-13 21:14:56.194. This time is accurate
• gPhone_Presence (actual item being watched for trigger condition goes offline: 2020-06-13 21:14:56.197. This time is accurate.
• Rule executes: 2020-06-13 21:14:56.216 to 2020-06-13 21:14:56.290. This time is accurate.
• Insteon light switches receive commands: 2020-06-13 21:14:56.562 to 2020-06-13 21:14:57.495. This time seems accurate based upon the rule execution time.
• Insteon light switches report as changed state: 2020-06-13 21:14:57.903 to 2020-06-13 21:14:57.918. This time seems accurate based upon the time the commands were received.
• Lights turn off: 2020-06-13, approximately 21:15:15. This is approximate, only because I’ve issued a “watch date” command to note the time the lights actually turn off.

Items

Group:Switch:OR(ON, OFF) gUpstairs_Hallway_Lights "Upstairs Hallway Lights" <switch> (gInsteon)
Switch Upstairs_Hallway_Lights_A "Upstairs Hallway Lights A" <switch> (gUpstairs_Hallway_Lights) { channel="insteon:device:41CF94:switch" }
Switch Upstairs_Hallway_Lights_B "Upstairs Hallway Lights B" <switch> (gUpstairs_Hallway_Lights) { channel="insteon:device:28743C:switch" }
Switch Upstairs_Hallway_Lights_C "Upstairs Hallway Lights C" <switch> (gUpstairs_Hallway_Lights) { channel="insteon:device:28866A:switch" }

Group:Switch:AND(ON, OFF) gPhone_Presence "Family Phone Presence" <switch> (gPhone_Presence)
Switch Burzin_Phone_Presence "Burzin's Phone Presence" (gPhone_Presence) { channel="network:pingdevice:2d798662:online" }

Rules

def lights_out(event):
    events.sendCommand("Front_Porch_Lights", "OFF")
    events.sendCommand("gKitchen_Island_Lights", "OFF")
    events.sendCommand("Kitchen_Over_Cabinet_Lights","OFF")
    events.sendCommand("Kitchen_Under_Cabinet_Lights", "OFF")
    events.sendCommand("gKitchen_Table_Lights", "OFF")
    events.sendCommand("gDining_Room_Lights", "OFF")
    events.sendCommand("gFamily_Room_Lights", "OFF")
    events.sendCommand("Bar_Light", "OFF")
    events.sendCommand("gFireplace_Light", "OFF")
    events.sendCommand("Sunroom_Window_Lights", "OFF")
    events.sendCommand("gPatio_Lights", "OFF")
    events.sendCommand("gFoyer_Light", "OFF")
    events.sendCommand("gLiving_Room_Lights", "OFF")
    events.sendCommand("gUpstairs_Hallway_Lights", "OFF")
    events.sendCommand("Balcony_Light", "OFF")

@rule("Lights Off When Nobody is Home")
@when("Member of gPhone_Presence changed to OFF")
def lights_off_when_nobody_is_home(event):
    lights_off_when_nobody_is_home.log.info("Rule 'Lights Off When Nobody is Home' is executing.")
    gPhone_Presence=filter(lambda item: item.state == ON, ir.getItem("gPhone_Presence").members)
    if not gPhone_Presence:
        lights_out(event)
    lights_off_when_nobody_is_home.log.info("Rule 'Lights Off When Nobody is Home' has completed.")

Events Log Snippet

2020-06-13 21:14:56.194 [vent.ItemStateChangedEvent] - Burzin_Phone_Presence changed from ON to OFF
2020-06-13 21:14:56.197 [GroupItemStateChangedEvent] - gPhone_Presence changed from ON to OFF through Burzin_Phone_Presence
2020-06-13 21:14:56.562 [ome.event.ItemCommandEvent] - Item 'gUpstairs_Hallway_Lights' received command OFF
2020-06-13 21:14:57.421 [ome.event.ItemCommandEvent] - Item 'Upstairs_Hallway_Lights_A' received command OFF
2020-06-13 21:14:57.465 [ome.event.ItemCommandEvent] - Item 'Upstairs_Hallway_Lights_B' received command OFF
2020-06-13 21:14:57.495 [ome.event.ItemCommandEvent] - Item 'Upstairs_Hallway_Lights_C' received command OFF
2020-06-13 21:14:57.903 [GroupItemStateChangedEvent] - gUpstairs_Hallway_Lights changed from OFF to ON through Upstairs_Hallway_Lights_A
2020-06-13 21:14:57.906 [vent.ItemStateChangedEvent] - Upstairs_Hallway_Lights_A changed from ON to OFF
2020-06-13 21:14:57.910 [vent.ItemStateChangedEvent] - Upstairs_Hallway_Lights_B changed from ON to OFF
2020-06-13 21:14:57.914 [GroupItemStateChangedEvent] - gUpstairs_Hallway_Lights changed from ON to OFF through Upstairs_Hallway_Lights_C
2020-06-13 21:14:57.918 [vent.ItemStateChangedEvent] - Upstairs_Hallway_Lights_C changed from ON to OFF

openHAB Log Snippet

2020-06-13 21:14:56.216 [INFO ] [ython.Lights Off When Nobody is Home] - Rule 'Lights Off When Nobody is Home' is executing.
2020-06-13 21:14:56.290 [INFO ] [ython.Lights Off When Nobody is Home] - Rule 'Lights Off When Nobody is Home' has completed.

Regards,
Burzin

[rossko57]

@Burzin_Sumariwalla

there seems to be a significant delay between a report of a state change to off

That’s the normal effect of autoupdate, doing what it is is supposed to do, pre-empting the effect of a command, for the appearance of a responsive UI
It’s enabled for each Item by default, but can be disabled where you don’t want it (or during diagnostics)

@Burzin_Sumariwalla

the actual time the off command is received and executed by the Insteon switches.

That’s your real problem, of course. Is there a hub involved, what kind?

[ranielsen (Rob Nielsen)]

Yeah, this is how things work with the Insteon network, it can take time for events to propagate through the network and it’s easy to overload it. You’ll have better experience if you switch to Insteon groups: https://www.openhab.org/addons/bindings/insteon/#direct-sending-of-group-broadcasts-triggering-scenes. Otherwise put a delay between sending multiple events of a second or two.

[Burzin_Sumariwalla]

Hi Rossko57,

That’s the normal effect of autoupdate , doing what it is is supposed to do, pre-empting the effect of a command, for the appearance of a responsive UI
It’s enabled for each Item by default, but can be disabled where you don’t want it (or during diagnostics

What’s autoupdate and how is it disabled? I’m more curious b/c I’ve run across something new to me.

That’s your real problem, of course. Is there a hub involved, what kind?

There’s no Insteon Hub, only an Insteon 2413U.

Regards,
Burzin

[Burzin_Sumariwalla]

Hi Rob,

Thanks for the link on Insteon groups. I forgot about that when I migrated to your binding. With regard to Insteon Groups, I think I have all my switches on Group 1. The setup isn’t physically complicated, it’s just single and multiway switches/dimmers, and I’m only controlling about 16 different loads through 1 or more switches/dimmers. Is the recommendation for each load to be in its own Insteon Group?

Also, I’ve started using openHAB groups for my multiway switches/dimmers. Is part of my problem also that I’m sending commands to the openHAB group instead of directly to the device controlling the load?

Regards,
Burzin

[rossko57]

@Burzin_Sumariwalla

What’s autoupdate

Xiaomi Mi IO Binding - String-Item and received command rule problem

Yes. When you send an openHAB command to your Item (from UI or rule), the autoupdate feature sees it - as well as your actual binding which will pass the command to the cleaner. Autoupdate makes an educated guess about the likely outcome of the command, and issues its prediction. That in turn causes an internal update of your Item. The idea is to make a responsive user interface, even if the target device responds slowly (like yours) or even not at all. In your case, shortly (100mS) after a…

@Burzin_Sumariwalla

I’m sending commands to the openHAB group

The effect of that is that the command gets distributed to all Group members.
That’s to say, each individual member Item gets a new command.
If a binding or technology isn’t very good at managing/queuing a blast of commands to multiple devices, it sometimes doesn’t work well.

[tommycw10 (Tom)]

@Burzin_Sumariwalla,

All of the normal linkages between the PLM and a device are on group 1, this is used to turn on/off brighten/dim etc single devices. The PLM sends a group 1 message to a specific address and that addressed device responds.

To create “scenes” there you can use groups other than 1. In a scene, rather than your PLM commanding one device at a time, it is commanding every device in a given group at the same time. Each device can be set to respond differently to the group broadcast, with a unique ON level and Ramp Rate or OFF.

To build a scene, you need 3rd party software to create the links in your devices’ databases. There is Insteon Terminal: https://github.com/pfrommerd/insteon-terminal but be warned that there is some learning curve this Insteon-Terminal. Other’s use the very old and unsupported Insteon HouseLinc software: https://www.smarthome.com/houselinc.html. Maybe there are some others too?

Anyway, basically you choose a group number. It can be anything but it does have to be unique on your system. I use 12 different groups to create scenes in my house and one of these I use as an ALL OFF scene. For that I happen to use Group 7.

For the ALL OFF example above I used Insteon-Terminal to set up the links in my device databases. I made my PLM a controller for group 7 and I made all of my devices responders to group 7. I also set each device with its own on level or off and ramp rate. In this case I set all devices to OFF.

Next in openHAB I create a group broadcast “thing”:

Thing insteon:device:xxyyzz "Insteon - Group Broadcasts" (insteon:network:local) [address="xx.yy.zz", productKey="0x000045"] {
Channels:
	Type switch : broadcastOnOff#7  "Alloff"
}

Then create an item and link to that “thing”:

Switch	Alloff	{channel="insteon:device:40D16E:broadcastOnOff#7"}	

Then in my rules I can command just this scene:

sendCommand(Alloff, ON)

Then rather than openHAB serially commanding off every light one at a time, the group broadcast goes out, all devices respond at the same time, greatly improving the speed at which your system can respond. I HIGHLY recommend using scenes wherever possible in OH. The Insteon network bandwidth is just not that great and is easily overloaded. Anytime I have to command more than two lights to do something I create a scene. If for some reason I cannot, I add in a wait between commands of 500-1000ms.