X10 devices through Insteon 2242-222 Hub VERY SLOW

asjohnson9 · October 10, 2015, 3:13pm

I am a 1 day old OpenHAB user but a 15 year old MisterHouse user. I have successfully gotten a few lights to respond from OH via an insteon 2242-222 hub. As an example, we will use X10 Code B1. The problems seems to be that OH “instantly” sends the B-1 command out on the powerline, but does not send the B-on or B-off command until 20 or 30 seconds later. Running V1.8 with the V1.8 bindings

items: Switch StudioLight “Studio Light” (FF_Desk){insteonplm=“B.1:X00.00.01#switch”}

config: insteonplm:port_0=/hub/192.168.0.11:9761
insteonplm:poll_interval=300000
insteonplm:refresh=600000

LogFile:
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActivator[:34]- Insteon PLM binding has been started.
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:155]- activating binding
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:262]- global binding config has arrived.
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:278]- refresh interval set to 600s
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:287]- poll interval set to 300000 per config file
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:310]- dead device timeout set to 3000s
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:266]- configuration update complete!
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:349]- initializing…
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:361]- config: poll_interval -> 300000
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:361]- config: port_0 -> /hub/192.168.0.11:9761
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:603]- devices: 0 configured, 0 polling, msgs received: 0
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Poller[:176]- starting poll thread.
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Driver[:75]- added new port: port_0 /hub/192.168.0.11:9761
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:361]- config: refresh -> 600000
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:361]- config: service.pid -> org.openhab.insteonplm
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:367]- setting driver listener
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:369]- starting 0 ports
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Port[:132]- starting port /hub/192.168.0.11:9761
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Port[:239]- starting reader…
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Port[:369]- starting writer…
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.ModemDBBuilder[:50]- querying port for first link record
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Port[:122]- clearing modem db!
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (0): OUT:Cmd:0x60|
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:371]- ports started
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:377]- initialization complete, found 1 port!
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:217]- item StudioLight binding changed: addr=B.1|prodKey:X00.00.01|feature:switch
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:195]- loaded 38 devices:
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x000041 ->pk:0x000041|model:2484DWH8|desc:KeypadLinc Countdown Timer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.0A ->pk:F00.00.0A|model:2852-222|desc:Leak Sensor|features:contact=LeakSensorContact:lastheardfrom=GenericLastTime|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.0D ->pk:F00.00.0D|model:2634-222|desc:On/Off Dual-Band Outdoor Module|features:lastheardfrom=GenericLastTime:switch=GenericSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x000049 ->pk:0x000049|model:2843-222|desc:Wireless Open/Close Sensor|features:contact=GenericContact:lastheardfrom=GenericLastTime|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.0C ->pk:F00.00.0C|model:2476D|desc:SwitchLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.0B ->pk:F00.00.0B|model:2672-422|desc:LED Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x000068 ->pk:0x000068|model:2472D|desc:OutletLincDimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x000045 ->pk:0x000045|model:2413U|desc:PowerLinc 2413U USB modem|features:control=GenericModemControl|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x00004A ->pk:0x00004A|model:2842-222|desc:Motion Sensor|features:data=MotionSensorData:contact=WirelessMotionSensorContact:lastheardfrom=GenericLastTime|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.01 ->pk:F00.00.01|model:2477D|desc:SwitchLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.05 ->pk:F00.00.05|model:2456D3|desc:LampLinc V2|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.04 ->pk:F00.00.04|model:2876S|desc:ICON Switch|features:lastheardfrom=GenericLastTime:switch=GenericSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.03 ->pk:F00.00.03|model:2845-222|desc:Hidden Door Sensor|features:data=HiddenDoorSensorData:contact=WirelessMotionSensorContact:lastheardfrom=GenericLastTime|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.02 ->pk:F00.00.02|model:2477S|desc:SwitchLinc Switch|features:lastheardfrom=GenericLastTime:switch=GenericSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.09 ->pk:F00.00.09|model:2458-A1|desc:MorningLinc RF Lock Controller|features:switch=GenericSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.08 ->pk:F00.00.08|model:2452-222|desc:DIN Rail Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.07 ->pk:F00.00.07|model:2453-222|desc:DIN Rail On/Off|features:lastheardfrom=GenericLastTime:switch=GenericSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.06 ->pk:F00.00.06|model:2442-222|desc:Micro Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x000051 ->pk:0x000051|model:2486DWH8|desc:KeypadLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x000050 ->pk:0x000050|model:2486DWH6|desc:KeypadLinc Dimmer - 6 Button|features:loaddimmer=LoadDimmerButton:keypadbuttonA=KeyPadButton3:keypadbuttonD=KeyPadButton6:keypadbuttonB=KeyPadButton4:keypadbuttonC=KeyPadButton5:lastheardfrom=GenericLastTime|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.1B ->pk:F00.00.1B|model:2635-222|desc:On/Off Module|features:lastheardfrom=GenericLastTime:switch=GenericSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.1A ->pk:F00.00.1A|model:2475SDB|desc:In-LineLinc Relay|features:lastheardfrom=GenericLastTime:switch=GenericSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x000037 ->pk:0x000037|model:2486D|desc:KeypadLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.1C ->pk:F00.00.1C|model:2475F|desc:FanLinc Module|features:fancontrol=FanLincFanControl:lightdimmer=GenericDimmer:lastheardfrom=GenericLastTime|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.12 ->pk:F00.00.12|model:2466S|desc:ToggleLinc Switch|features:lastheardfrom=GenericLastTime:switch=GenericSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.11 ->pk:F00.00.11|model:2466D|desc:ToggleLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.10 ->pk:F00.00.10|model:2342-2|desc:Mini Remote|features:buttonD=RemoteButtonD:buttonB=RemoteButtonB:buttonC=RemoteButtonC:lastheardfrom=GenericLastTime:buttonA=RemoteButtonA|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- X00.00.03 ->pk:X00.00.03|model:X10 motion sensor|desc:Generic X10 motion sensor|features:contact=X10Contact|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.16 ->pk:F00.00.16|model:2334-232|desc:Keypad Dimmer Switch, 8-Button |features:loaddimmer=LoadDimmerButton:keypadbuttonD=KeyPadButton4:keypadbuttonE=KeyPadButton5:keypadbuttonB=KeyPadButton2:keypadbuttonC=KeyPadButton3:keypadbuttonH=KeyPadButton8:lastheardfrom=GenericLastTime:keypadbuttonF=KeyPadButton6:keypadbuttonG=KeyPadButton7|groups:button_group=keypadbuttonB,keypadbuttonC,keypadbuttonD,keypadbuttonE,keypadbuttonF,keypadbuttonG,keypadbuttonH
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- X00.00.02 ->pk:X00.00.02|model:X10 dimmer|desc:Generic X10 Dimmer without preset|features:dimmer=X10Dimmer:switch=X10Switch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.15 ->pk:F00.00.15|model:2334-232|desc:Keypad Dimmer Switch, 6-Button |features:loaddimmer=LoadDimmerButton:keypadbuttonA=KeyPadButton3:keypadbuttonD=KeyPadButton6:keypadbuttonB=KeyPadButton4:keypadbuttonC=KeyPadButton5:lastheardfrom=GenericLastTime|groups:button_group=keypadbuttonA,keypadbuttonB,keypadbuttonC,keypadbuttonD
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- X00.00.01 ->pk:X00.00.01|model:X10 switch|desc:any simple X10 switch|features:switch=X10Switch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.14 ->pk:F00.00.14|model:2487S|desc:KeypadLinc On/Off 6-Button Scene Control |features:keypadbuttonA=KeyPadButton3:keypadbuttonD=KeyPadButton6:keypadbuttonB=KeyPadButton4:keypadbuttonC=KeyPadButton5:lastheardfrom=GenericLastTime:loadswitch=LoadSwitchButton|groups:button_group=keypadbuttonA,keypadbuttonB,keypadbuttonC,keypadbuttonD
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.13 ->pk:F00.00.13|model:2672-222|desc:LED Bulb|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.19 ->pk:F00.00.19|model:2457D2|desc:LampLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.18 ->pk:F00.00.18|model:2441TH|desc:Insteon Thermostat|features:mastercontrol=ThermostatMasterControl:fancontrol=ThermostatFanControl:heatsetpoint=ThermostatHeatSetPoint:coolsetpoint=ThermostatCoolSetPoint:temperature=ThermostatTemperature:humidity=ThermostatHumidity:lastheardfrom=GenericLastTime:modecontrol=ThermostatModeControl|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- 0x00001A ->pk:0x00001A|model:2450|desc:IO Link|features:contact=IOLincContact:lastheardfrom=GenericLastTime:switch=IOLincSwitch|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:175]- F00.00.17 ->pk:F00.00.17|model:2423A1|desc:iMeter Solo Power Meter|features:meter=PowerMeter:lastheardfrom=GenericLastTime|groups
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:217]- item GreatRoomFloorLamp binding changed: addr=A.10|prodKey:X00.00.01|feature:switch
2015-10-10 10:06:16 DEBUG o.o.b.i.InsteonPLMActiveBinding[:217]- item DeskLamp binding changed: addr=B.4|prodKey:X00.00.02|feature:switch
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Port[:430]- found modem 2A.AA.26 in device_types: 2A.AA.26|control->GenericModemControl(0:1:0)
2015-10-10 10:06:16 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (0): OUT:Cmd:0x69|
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.ModemDBBuilder[:104]- got all link records.
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.ModemDBBuilder[:130]- MDB ------- start of modem link records ------------------
2015-10-10 10:06:16 DEBUG o.o.b.i.i.d.ModemDBBuilder[:144]- MDB ---------------- end of modem link records -----------
2015-10-10 10:06:16 INFO o.o.b.i.InsteonPLMActiveBinding[:536]- modem database has 0 entries!
2015-10-10 10:06:16 WARN o.o.b.i.InsteonPLMActiveBinding[:538]- the modem link database is empty!
2015-10-10 10:06:46 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:06:47 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:06:47 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:06:50 INFO o.o.b.i.InsteonPLMActiveBinding[:122]- Item: StudioLight got command ON
2015-10-10 10:06:50 DEBUG o.o.b.i.i.device.InsteonDevice[:170]- processing command ON features: 1
2015-10-10 10:06:50 DEBUG o.o.b.i.i.d.RequestQueueManager[:93]- starting request queue thread
2015-10-10 10:06:50 INFO o.o.b.i.i.d.CommandHandler[:228]- X10OnOffCommandHandler: sent msg to switch B.1 ON
2015-10-10 10:06:50 DEBUG o.o.b.i.i.device.InsteonDevice[:344]- qe taken off direct: X10Switch(1:3:2) OUT:Cmd:0x63|rawX10:0xE6|X10Flag:0x00|
2015-10-10 10:06:50 DEBUG o.o.b.i.i.device.InsteonDevice[:364]- next request queue processed in 2000 msec, quiettime = 2000
2015-10-10 10:06:50 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (500): OUT:Cmd:0x63|rawX10:0xE6|X10Flag:0x00|
2015-10-10 10:06:52 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 27999 usec
2015-10-10 10:06:54 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 25999 usec
2015-10-10 10:06:56 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 23999 usec
2015-10-10 10:06:58 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 21999 usec
2015-10-10 10:07:00 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 19999 usec
2015-10-10 10:07:02 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 17999 usec
2015-10-10 10:07:04 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 15999 usec
2015-10-10 10:07:06 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 13999 usec
2015-10-10 10:07:08 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 11998 usec
2015-10-10 10:07:10 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 9998 usec
2015-10-10 10:07:12 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 7998 usec
2015-10-10 10:07:14 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 5998 usec
2015-10-10 10:07:16 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 3998 usec
2015-10-10 10:07:18 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 1998 usec
2015-10-10 10:07:20 WARN o.o.b.i.i.device.InsteonDevice[:339]- gave up waiting for query reply from device B.1
2015-10-10 10:07:20 DEBUG o.o.b.i.i.device.InsteonDevice[:344]- qe taken off direct: X10Switch(1:3:2) OUT:Cmd:0x63|rawX10:0xE2|X10Flag:0x80|
2015-10-10 10:07:20 DEBUG o.o.b.i.i.device.InsteonDevice[:364]- next request queue processed in 2000 msec, quiettime = 2000
2015-10-10 10:07:20 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (500): OUT:Cmd:0x63|rawX10:0xE2|X10Flag:0x80|
2015-10-10 10:07:22 DEBUG o.o.b.i.i.d.RequestQueueManager[:129]- device queue for B.1 is empty!
2015-10-10 10:07:23 INFO o.o.b.i.InsteonPLMActiveBinding[:122]- Item: StudioLight got command OFF
2015-10-10 10:07:23 DEBUG o.o.b.i.i.device.InsteonDevice[:170]- processing command OFF features: 1
2015-10-10 10:07:23 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 27147 usec
2015-10-10 10:07:23 INFO o.o.b.i.i.d.CommandHandler[:228]- X10OnOffCommandHandler: sent msg to switch B.1 OFF
2015-10-10 10:07:23 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 27147 usec
2015-10-10 10:07:25 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:07:25 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 25147 usec
2015-10-10 10:07:25 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:07:25 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:07:27 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 23146 usec
2015-10-10 10:07:29 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 21146 usec
2015-10-10 10:07:31 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 19146 usec
2015-10-10 10:07:33 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 17146 usec
2015-10-10 10:07:33 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:07:34 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:07:34 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:07:35 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 15146 usec
2015-10-10 10:07:37 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 13146 usec
2015-10-10 10:07:39 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 11146 usec
2015-10-10 10:07:41 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 9146 usec
2015-10-10 10:07:43 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:07:43 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:07:43 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:07:43 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 7145 usec
2015-10-10 10:07:45 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 5145 usec
2015-10-10 10:07:47 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 3145 usec
2015-10-10 10:07:49 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:07:49 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:07:49 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:07:49 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 1145 usec
2015-10-10 10:07:50 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0xEB|X10Flag:0x00|
2015-10-10 10:07:50 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0xE3|X10Flag:0x80|
2015-10-10 10:07:50 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address B.12
2015-10-10 10:07:51 WARN o.o.b.i.i.device.InsteonDevice[:339]- gave up waiting for query reply from device B.1
2015-10-10 10:07:51 DEBUG o.o.b.i.i.device.InsteonDevice[:344]- qe taken off direct: X10Switch(1:3:2) OUT:Cmd:0x63|rawX10:0xE6|X10Flag:0x00|
2015-10-10 10:07:51 DEBUG o.o.b.i.i.device.InsteonDevice[:364]- next request queue processed in 2000 msec, quiettime = 2000
2015-10-10 10:07:51 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (500): OUT:Cmd:0x63|rawX10:0xE6|X10Flag:0x00|
2015-10-10 10:07:53 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 28000 usec
2015-10-10 10:07:55 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 26000 usec
2015-10-10 10:07:57 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 24000 usec
2015-10-10 10:07:59 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 22000 usec
2015-10-10 10:08:01 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 19999 usec
2015-10-10 10:08:03 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 17999 usec
2015-10-10 10:08:04 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x65|X10Flag:0x00|
2015-10-10 10:08:04 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x62|X10Flag:0x80|
2015-10-10 10:08:04 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address A.7
2015-10-10 10:08:05 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 15999 usec
2015-10-10 10:08:07 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 13999 usec
2015-10-10 10:08:09 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 11999 usec
2015-10-10 10:08:11 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 9999 usec
2015-10-10 10:08:13 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 7999 usec
2015-10-10 10:08:15 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 5999 usec
2015-10-10 10:08:17 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 3999 usec
2015-10-10 10:08:19 DEBUG o.o.b.i.i.device.InsteonDevice[:335]- still waiting for query reply from B.1 for another 1998 usec
2015-10-10 10:08:20 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:08:20 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:08:20 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:08:21 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:08:21 WARN o.o.b.i.i.device.InsteonDevice[:339]- gave up waiting for query reply from device B.1
2015-10-10 10:08:21 DEBUG o.o.b.i.i.device.InsteonDevice[:344]- qe taken off direct: X10Switch(1:3:2) OUT:Cmd:0x63|rawX10:0xE3|X10Flag:0x80|
2015-10-10 10:08:21 DEBUG o.o.b.i.i.device.InsteonDevice[:364]- next request queue processed in 2000 msec, quiettime = 2000
2015-10-10 10:08:21 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (500): OUT:Cmd:0x63|rawX10:0xE3|X10Flag:0x80|
2015-10-10 10:08:21 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:08:21 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:08:23 DEBUG o.o.b.i.i.d.RequestQueueManager[:129]- device queue for B.1 is empty!
2015-10-10 10:08:24 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:08:24 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:08:24 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:08:30 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:08:30 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:08:30 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:08:38 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:08:38 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:08:38 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:08:48 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x4E|X10Flag:0x00|
2015-10-10 10:08:48 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x43|X10Flag:0x80|
2015-10-10 10:08:48 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address O.2
2015-10-10 10:08:53 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x61|X10Flag:0x00|
2015-10-10 10:08:53 DEBUG o.o.b.i.InsteonPLMActiveBinding[:522]- got msg: IN:Cmd:0x52|rawX10:0x62|X10Flag:0x80|
2015-10-10 10:08:53 DEBUG o.o.b.i.InsteonPLMActiveBinding[:595]- dropping message from unknown device with address A.5

Bernd_Pfrommer · October 11, 2015, 1:50am

I actually no longer have the X10 devices. I had them for a brief period. Need to get up to speed again with X10.
Could you please reformat your post (mark the log as “code block”) so that it’s more readable?
Thanks!

Bernd

Bernd_Pfrommer · October 11, 2015, 1:51am

never mind, when I cut and paste it it looks o.k.

Bernd_Pfrommer · October 11, 2015, 2:12am

Yep, it’s taken an OpenNAP between sending the unit code and sending the command code.

2015-10-10 10:06:50 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (500): OUT:Cmd:0x63|rawX10:0xE6|X10Flag:0x00|
2015-10-10 10:07:20 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (500): OUT:Cmd:0x63|rawX10:0xE2|X10Flag:0x80|
2015-10-10 10:07:51 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (500): OUT:Cmd:0x63|rawX10:0xE6|X10Flag:0x00|
2015-10-10 10:08:21 DEBUG o.o.b.i.internal.driver.Port[:378]- writing (500): OUT:Cmd:0x63|rawX10:0xE3|X10Flag:0x80|

Ah, I found the reason. After developing the X10 stuff finished, I added logic that if a device does not respond to a direct command with an “ACK” no more new messages will be sent for a while (30sec). I need to switch off that logic for X10, since there is never any ACK.

I have another big pull request pending that I want to see go through before I fix this one. Hopefully I’ll get to it by Friday.

asjohnson9 · October 11, 2015, 2:20am

Thanks! That was very fast response and very fast troubleshooting.

asjohnson9 · October 18, 2015, 11:48pm

I see where you updated the file. I just tested. We are down to 8 second response. Any way to make it 0 seconds?

Bernd_Pfrommer · October 19, 2015, 1:31am

Oh, that’s true, I cut that parameter, almost by accident, and I think before you pointed out the problem with X10.
Yes, I was waiting for the pull request to be merged, now I’ll go after the X10 problem. Will work on it for half hour now, see how far I get.

asjohnson9 · October 19, 2015, 2:02am

Thank you very much.

Bernd_Pfrommer · October 19, 2015, 2:26am

You are welcome.

Here is the pull request with the fix. Includes link to compiled jar file (java 1.8).

Could not test directly since I don’t have X10 devices, but I can see the binding send out the messages now back-to-back without waiting for the ack. Please let me know if this fix works for you.

Bernd

asjohnson9 · October 19, 2015, 10:16pm

The new InsteonPLM binding works great with X10 now. Thank you so much for the quick solution. Those of us with a house full of X10 appreciate the chance to slowly migrate away from X10 to a more modern platform.

Bernd_Pfrommer · October 20, 2015, 12:50am

Great. Now we have an X10 tester on board

gregcarpentervistala · October 22, 2015, 12:16pm

Tester 2 here. Working good so far for me started at 30 sec now 1 sec. Thanks good work

Bernd_Pfrommer · October 22, 2015, 12:18pm

Great!
The fix has meanwhile been merged into the master repository, so you can pick up a working .jar file from the nightly builds on cloudbees.