openhab/openhab — pull request #1706 by cfrede001 (2014-11-22 03:21:17+00:00)
Title: Fix PLM DeviceTypeLoader race condition

It appears that on binding startup there is a race condition related to when the internal device_types.xml is loaded. The fix assumes this should be explicitly performed during InsteonPLMActiveBinding.initialize(). Based on the code flow for method updated (#234), this may be obfuscated or worked around by explicitly setting more_devices XML in binding config. This would force a reference to the DeviceTypeLoader instance on #278. This happens much earlier in startup sequence than the actual initialize() method.

Steps to reproduce:

* Start OpenHAB
* Wait for insteon binding to initialize
* Logs should say something like "ERROR o.o.b.i.InsteonPLMActiveBinding[:424]- unknown product key: F00.00.0B for config: addr=2F.45.57|prodKey:F00.00.0B|feature:dimmer. Add definition to xml file and try again"
* Test light nothing will happen.
* Make non-impacting change (i.e. label modification) to items file to force reload.
* Logs should now say "2014-11-22 02:39:38 DEBUG o.o.b.i.InsteonPLMActiveBinding[:214]- item familyRoomMain binding changed: addr=2F.F9.99|prodKey:F00.00.0C|feature:dimmer
2014-11-22 02:39:38 INFO o.o.b.i.InsteonPLMActiveBinding[:459]- device 2F.F9.99 found in the modem database!"

NOTE: I have a small number of items in my list 3-6 at any given time right now.

Full log for above sequence:

2014-11-22 02:32:07 INFO o.o.b.i.internal.driver.Port[:166]- successfully opened port /dev/ttyUSB0
2014-11-22 02:32:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:345]- initialization complete, found 1 port!
2014-11-22 02:32:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:214]- item familyRoomMain binding changed: addr=2F.F9.99|prodKey:F00.00.0C|feature:dimmer
2014-11-22 02:32:07 ERROR o.o.b.i.InsteonPLMActiveBinding[:424]- unknown product key: F00.00.0C for config: addr=2F.F9.99|prodKey:F00.00.0C|feature:dimmer. Add definition to xml file and try again
2014-11-22 02:32:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:214]- item familyRoomLight binding changed: addr=2F.45.57|prodKey:F00.00.0B|feature:dimmer
2014-11-22 02:32:07 ERROR o.o.b.i.InsteonPLMActiveBinding[:424]- unknown product key: F00.00.0B for config: addr=2F.45.57|prodKey:F00.00.0B|feature:dimmer. Add definition to xml file and try again
2014-11-22 02:32:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:214]- item downstairsHallway binding changed: addr=2F.41.43|prodKey:F00.00.0B|feature:dimmer
2014-11-22 02:32:07 ERROR o.o.b.i.InsteonPLMActiveBinding[:424]- unknown product key: F00.00.0B for config: addr=2F.41.43|prodKey:F00.00.0B|feature:dimmer. Add definition to xml file and try again
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:158]- loaded 21 devices:
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- 0x000049 ->pk:0x000049|model:2843-222|desc:Wireless Open/Close Sensor|features:lastheardfrom=GenericLastTime:contact=GenericContact
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.0A ->pk:F00.00.0A|model:2852-222|desc:Leak Sensor|features:lastheardfrom=GenericLastTime:contact=LeakSensorContact
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- 0x000037 ->pk:0x000037|model:2486D|desc:KeypadLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- 0x000045 ->pk:0x000045|model:2413U|desc:PowerLinc 2413U USB modem|features:control=GenericModemControl
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- 0x000051 ->pk:0x000051|model:2486DWH8|desc:KeypadLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.0B ->pk:F00.00.0B|model:2672-422|desc:LED Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.0C ->pk:F00.00.0C|model:2476D|desc:SwitchLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.0D ->pk:F00.00.0D|model:2634-222|desc:On/Off Dual-Band Outdoor Module|features:lastheardfrom=GenericLastTime:switch=GenericSwitch
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.10 ->pk:F00.00.10|model:2342-2|desc:Mini Remote|features:lastheardfrom=GenericLastTime:switch=MultiButtonRemote
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.01 ->pk:F00.00.01|model:2477D|desc:SwitchLinc Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.07 ->pk:F00.00.07|model:2453-222|desc:DIN Rail On/Off|features:lastheardfrom=GenericLastTime:switch=GenericSwitch
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.06 ->pk:F00.00.06|model:2442-222|desc:Micro Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.09 ->pk:F00.00.09|model:2458-A1|desc:MorningLinc RF Lock Controller|features:switch=GenericSwitch
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- 0x000068 ->pk:0x000068|model:2472D|desc:OutletLincDimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- 0x00004A ->pk:0x00004A|model:2842-222|desc:Motion Sensor|features:lastheardfrom=GenericLastTime:lightlevel=MotionSensorLightLevel:contact=WirelessMotionSensorContact:batterylevel=MotionSensorBatteryLevel
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.08 ->pk:F00.00.08|model:2452-222|desc:DIN Rail Dimmer|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.03 ->pk:F00.00.03|model:2845-222|desc:Hidden Door Sensor|features:lastheardfrom=GenericLastTime:contact=GenericContact
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- 0x00001A ->pk:0x00001A|model:2450|desc:IO Link|features:lastheardfrom=GenericLastTime:switch=IOLincSwitch:contact=IOLincContact
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.02 ->pk:F00.00.02|model:2477S|desc:SwitchLinc Switch|features:lastheardfrom=GenericLastTime:switch=GenericSwitch
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.05 ->pk:F00.00.05|model:2456D3|desc:LampLinc V2|features:lastheardfrom=GenericLastTime:dimmer=GenericDimmer
2014-11-22 02:32:07 DEBUG o.o.b.i.i.d.DeviceTypeLoader[:137]- F00.00.04 ->pk:F00.00.04|model:2876S|desc:ICON Switch|features:lastheardfrom=GenericLastTime:switch=GenericSwitch
2014-11-22 02:32:07 DEBUG o.o.b.i.internal.driver.Port[:384]- found modem 2F.B5.D1 in device_types: 2F.B5.D1|control->GenericModemControl(0:1:0)
2014-11-22 02:32:07 DEBUG o.o.b.i.internal.driver.Port[:332]- writing (0): OUT:Cmd:0x69|
2014-11-22 02:32:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:504]- got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:2F.F9.99|LinkData1:0x01|LinkData2:0x00|LinkData3:0x00|
2014-11-22 02:32:07 DEBUG o.o.b.i.internal.driver.Port[:332]- writing (0): OUT:Cmd:0x6A|
2014-11-22 02:32:07 DEBUG o.o.b.i.InsteonPLMActiveBinding[:504]- got msg: IN:Cmd:0x57|RecordFlags:0xA2|ALLLinkGroup:0x01|LinkAddr:2F.F9.99|LinkData1:0x00|LinkData2:0x00|LinkData3:0x00|
2014-11-22 02:32:07 DEBUG o.o.b.i.internal.driver.Port[:332]- writing (0): OUT:Cmd:0x6A|
2014-11-22 02:32:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:504]- got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:2F.45.57|LinkData1:0x01|LinkData2:0x00|LinkData3:0x00|
2014-11-22 02:32:08 DEBUG o.o.b.i.internal.driver.Port[:332]- writing (0): OUT:Cmd:0x6A|
2014-11-22 02:32:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:504]- got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:2F.41.43|LinkData1:0x01|LinkData2:0x00|LinkData3:0x00|
2014-11-22 02:32:08 DEBUG o.o.b.i.internal.driver.Port[:332]- writing (0): OUT:Cmd:0x6A|
2014-11-22 02:32:08 DEBUG o.o.b.i.i.d.ModemDBBuilder[:60]- got all link records.
2014-11-22 02:32:08 INFO o.o.b.i.InsteonPLMActiveBinding[:531]- modem database has 3 entries!
2014-11-22 02:32:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:536]- modem db entry: 2F.45.57
2014-11-22 02:32:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:536]- modem db entry: 2F.F9.99
2014-11-22 02:32:08 DEBUG o.o.b.i.InsteonPLMActiveBinding[:536]- modem db entry: 2F.41.43
root@raspberrypi:/opt/openhab# tail -f logs/insteonplm.log
2014-11-22 02:39:38 DEBUG o.o.b.i.InsteonPLMActiveBinding[:214]- item familyRoomMain binding changed: null
2014-11-22 02:39:38 DEBUG o.o.b.i.InsteonPLMActiveBinding[:214]- item familyRoomMain binding changed: addr=2F.F9.99|prodKey:F00.00.0C|feature:dimmer
2014-11-22 02:39:38 INFO o.o.b.i.InsteonPLMActiveBinding[:459]- device 2F.F9.99 found in the modem database!
2014-11-22 02:39:38 DEBUG o.o.b.i.internal.driver.Poller[:56]- start polling device 2F.F9.99|lastheardfrom->GenericLastTime(0:0:0)|dimmer->GenericDimmer(0:2:7)
2014-11-22 02:39:39 DEBUG o.o.b.i.InsteonPLMActiveBinding[:214]- item familyRoomLight binding changed: addr=2F.45.57|prodKey:F00.00.0B|feature:dimmer
2014-11-22 02:39:39 INFO o.o.b.i.InsteonPLMActiveBinding[:459]- device 2F.45.57 found in the modem database!
2014-11-22 02:39:39 DEBUG o.o.b.i.internal.driver.Poller[:56]- start polling device 2F.45.57|lastheardfrom->GenericLastTime(0:0:0)|dimmer->GenericDimmer(0:2:7)
2014-11-22 02:39:39 DEBUG o.o.b.i.InsteonPLMActiveBinding[:214]- item downstairsHallway binding changed: addr=2F.41.43|prodKey:F00.00.0B|feature:dimmer
2014-11-22 02:39:39 INFO o.o.b.i.InsteonPLMActiveBinding[:459]- device 2F.41.43 found in the modem database!
2014-11-22 02:39:39 DEBUG o.o.b.i.internal.driver.Poller[:56]- start polling device 2F.41.43|lastheardfrom->GenericLastTime(0:0:0)|dimmer->GenericDimmer(0:2:7)