InsteonPLM binding not starting

antoine · December 31, 2017, 3:19pm

Hi,

I’m new to OpenHAB and I need your help. I think the InsteonPLM binding is not starting.

I tried 2 installs with the same results, I first installed OpenHAB2 on my Raspberry Pi 2 and I also installed openhabian to try. Both were version 2.2 of OpenHAB.

I then configured the files insteonplm.cfg, insteonplm.items, test.sitemap. And it works! I can turn on and off the 2 devices I have.

The problem is that after 30 minutes or so later, I install the Astro binding and restart OH using (sudo systemctl restart openhab2.service) and it doesn’t work anymore.

My setup is with a Hub 2245-222 and 2 plugin modules.

I’ve attached the log file while it’s working:

2017-12-27 22:25:45.251 [INFO ] [er.internal.HomeBuilderDashboardTile] - Started Home Builder at /homebuilder
2017-12-27 22:26:00.760 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.0.139:8080
2017-12-27 22:26:01.013 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.0.139:8443
2017-12-27 22:27:29.367 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'insteonplm.items'
2017-12-27 22:27:56.837 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2017-12-27 22:28:01.711 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
2017-12-27 22:28:36.145 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-12-27 22:28:37.866 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-12-27 22:28:40.236 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-12-27 22:28:42.058 [INFO ] [nding.insteonplm.InsteonPLMActivator] - Insteon PLM binding has been started.
2017-12-27 22:28:44.322 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - dead device timeout set to 3000s
2017-12-27 22:28:44.433 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - config: port_0 -> /hub2/user:password@192.168.0.117:25105,poll_time=1000
2017-12-27 22:28:44.481 [INFO ] [b.core.service.AbstractActiveService] - InsteonPLM has been started
2017-12-27 22:28:44.629 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - devices:   0 configured,   0 polling, msgs received:     0
2017-12-27 22:28:45.116 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - config: service.pid -> org.openhab.insteonplm
2017-12-27 22:29:04.800 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - modem database has 5 entries!
2017-12-27 22:29:04.848 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 47.18.E7 found in the modem database and the modem controls groups [0x00,0x03] and responds to groups [0x01].
2017-12-27 22:29:04.970 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.3E.80 found in the modem database and the modem controls groups [0x00,0x03] and responds to groups [0x01].
2017-12-27 22:29:05.110 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 40.33.59 found in the modem database, but is not configured as an item and the modem responds to groups [0x02].
2017-12-27 22:29:05.135 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 44.91.24 found in the modem database, but is not configured as an item and the modem responds to groups [0x01].
2017-12-27 22:29:05.819 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 47.18.E7 to level 0
==> /var/log/openhab2/events.log <==
2017-12-27 22:29:06.426 [vent.ItemStateChangedEvent] - xmas_module_dimmer changed from NULL to 0
==> /var/log/openhab2/openhab.log <==
2017-12-27 22:30:05.668 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 49.3E.80 to OFF
==> /var/log/openhab2/events.log <==
2017-12-27 22:30:05.794 [vent.ItemStateChangedEvent] - xmas_module_on_off changed from NULL to OFF

And log file while is it’s not working (including the stopping of OH):

2017-12-28 15:00:50.501 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2017-12-28 15:00:51.024 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-12-28 15:00:51.160 [INFO ] [er.internal.HomeBuilderDashboardTile] - Stopped Home Builder
2017-12-28 15:00:51.406 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard
2017-12-28 15:00:56.691 [ERROR] [org.openhab.core.compat1x           ] - [org.openhab.core.compat1x.eventpublisherdelegate(184)] Timeout waiting for reg change to complete unregistered
2017-12-28 15:05:16.358 [INFO ] [er.internal.HomeBuilderDashboardTile] - Started Home Builder at /homebuilder
2017-12-28 15:05:34.110 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.0.139:8080
2017-12-28 15:05:34.438 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.0.139:8443
2017-12-28 15:09:01.783 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'insteonplm.items'
2017-12-28 15:10:39.595 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2017-12-28 15:11:01.326 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
2017-12-28 15:11:04.688 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-12-28 15:11:07.306 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-12-28 15:11:11.308 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-12-28 15:11:11.831 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-insteonplm1'
2017-12-28 16:07:20.088 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2017-12-28 16:07:36.920 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2017-12-28 16:07:37.139 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-12-28 16:07:37.239 [INFO ] [er.internal.HomeBuilderDashboardTile] - Stopped Home Builder
2017-12-28 16:07:37.476 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard

I enabled TRACE level for InsteonPLM, but it gives no information about Insteon using search.

My Insteon ios app is working fine.

This turns on one of my device:

curl http://user:password@192.168.0.117:25105/3?0262493E800F13FF=I=3

I dont know what to do…

Thank you for your help!

antoine · January 1, 2018, 3:12pm

I made some progress. Looking at the second log file it said:

2017-12-28 15:11:11.831 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-insteonplm1'

I thought I checked in the beginning in the Paper UI -> Addon -> Bindings page to see if the binding was still installed but I checked yesterday and it turns out it wasn’t installed… I re-installed it and it works now.

Do you know if there is another way to know if a binding is installed other than the Paper UI -> Addon -> Bindings page ?

Thanks

antoine · January 1, 2018, 8:37pm

Well it worked for a few hours until the binding was shutdown!

2018-01-01 10:43:58.365 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-insteonplm'
2018-01-01 10:44:05.190 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2018-01-01 10:44:07.254 [DEBUG] [eonplm.internal.device.InsteonDevice] - qe taken off direct: GenericSwitch(1:1:6) OUT:Cmd:0x62|toAddress:49.3E.80|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2018-01-01 10:44:07.326 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:49.3E.80|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|
2018-01-01 10:44:07.337 [DEBUG] [eonplm.internal.device.InsteonDevice] - next request queue processed in 500 msec, quiettime = 500
2018-01-01 10:44:07.721 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 49.3E.80 is empty!
2018-01-01 10:44:08.882 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:49.3E.80|toAddress:49.ED.CD|messageFlags:0x20=ACK_OF_DIRECT:0:0|command1:0x00|command2:0xFF|
2018-01-01 10:44:08.909 [DEBUG] [eonplm.internal.device.InsteonDevice] - ----- applying message to feature: GenericSwitch
2018-01-01 10:44:08.929 [DEBUG] [lm.internal.device.MessageDispatcher] - 49.3E.80:GenericSwitch DIRECT_ACK: q:QUERY_PENDING cmd: 80
2018-01-01 10:44:08.982 [DEBUG] [lm.internal.device.MessageDispatcher] - changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:49.3E.80|toAddress:49.ED.CD|messageFlags:0x20=ACK_OF_DIRECT:0:0|command1:0x00|command2:0xFF|
2018-01-01 10:44:08.999 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 49.3E.80 to ON
2018-01-01 10:44:09.024 [DEBUG] [eonplm.internal.device.DeviceFeature] - 49.3E.80:GenericSwitch publishing: ON
2018-01-01 10:44:09.050 [DEBUG] [lm.internal.device.MessageDispatcher] - defdisp: 49.3E.80:GenericSwitch set status to: QUERY_ANSWERED
2018-01-01 10:44:09.094 [DEBUG] [eonplm.internal.device.DeviceFeature] - 49.3E.80:GenericLastTime publishing: 2018-01-01T10:44:09
2018-01-01 10:44:40.497 [DEBUG] [org.openhab.core.compat1x           ] - BundleEvent STOPPING - org.openhab.core.compat1x
2018-01-01 10:44:40.663 [DEBUG] [org.openhab.core.compat1x           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.autoupdate.AutoUpdateBindingConfigProvider}={component.name=org.openhab.core.compat1x.autoupdateproviderdelegate, component.id=182, service.id=306, service.bundleid=214, service.scope=bundle} - org.openhab.core.compat1x
2018-01-01 10:44:40.771 [DEBUG] [org.openhab.core.compat1x           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.model.item.BindingConfigReader}={service.id=307, service.bundleid=214, service.scope=singleton} - org.openhab.core.compat1x
2018-01-01 10:44:40.903 [DEBUG] [org.openhab.core.compat1x           ] - ServiceEvent UNREGISTERING - {org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventSubscriber}={event.topics=smarthome/*, component.name=org.openhab.core.compat1x.eventbridge, component.id=185, service.id=308, service.bundleid=214, service.scope=bundle} - org.openhab.core.compat1x
2018-01-01 10:44:41.052 [DEBUG] [org.openhab.binding.insteonplm      ] - ServiceEvent UNREGISTERING - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.insteonplm, component.name=org.openhab.binding.insteonplm.activebinding, component.id=179, service.id=310, service.bundleid=213, service.scope=bundle} - org.openhab.binding.insteonplm
2018-01-01 10:44:41.115 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - deactivating binding!
2018-01-01 10:44:41.147 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - shutting down binding
2018-01-01 10:44:41.177 [ERROR] [ding.insteonplm.internal.driver.Port] - got interrupted exception in write thread
2018-01-01 10:44:41.190 [DEBUG] [ding.insteonplm.internal.driver.Port] - waiting for read thread to exit for port /hub2/user:password@192.168.0.117:25105,poll_time=1000
2018-01-01 10:44:41.207 [DEBUG] [ding.insteonplm.internal.driver.Port] - exiting writer thread!

I did add this to addons.cfg:

binding = insteonplm,astro

And it stopped working right after.

I re-started the openhab service
and got this log (filtered with “insteon” keyword):

2018-01-01 12:27:58.039 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'insteonplm.items'

2018-01-01 12:30:12.530 [DEBUG] [org.openhab.binding.insteonplm      ] - BundleEvent STARTING - org.openhab.binding.insteonplm

2018-01-01 12:30:12.836 [INFO ] [nding.insteonplm.InsteonPLMActivator] - Insteon PLM binding has been started.

2018-01-01 12:30:13.206 [DEBUG] [org.openhab.binding.insteonplm      ] - BundleEvent STARTED - org.openhab.binding.insteonplm

2018-01-01 12:30:16.358 [DEBUG] [org.openhab.binding.insteonplm      ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.insteonplm.InsteonPLMBindingProvider}={component.name=org.openhab.binding.insteonplm.genericbindingprovider, component.id=172, service.id=290, service.bundleid=213, service.scope=bundle} - org.openhab.binding.insteonplm

2018-01-01 12:30:16.427 [DEBUG] [org.openhab.binding.insteonplm      ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.insteonplm, component.name=org.openhab.binding.insteonplm.activebinding, component.id=170, service.id=292, service.bundleid=213, service.scope=bundle} - org.openhab.binding.insteonplm

2018-01-01 12:30:17.649 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - activating binding

2018-01-01 12:30:17.821 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - global binding config has arrived.

2018-01-01 12:30:17.901 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - dead device timeout set to 3000s

2018-01-01 12:30:17.982 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - configuration update complete!

2018-01-01 12:30:18.093 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - initializing...

2018-01-01 12:30:18.181 [INFO ] [b.core.service.AbstractActiveService] - InsteonPLM has been started

2018-01-01 12:30:18.177 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - config: port_0 -> /hub2/user:password@192.168.0.117:25105,poll_time=1000

2018-01-01 12:30:18.685 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - devices:   0 configured,   0 polling, msgs received:     0

2018-01-01 12:30:18.791 [DEBUG] [ng.insteonplm.internal.driver.Poller] - starting poll thread.

2018-01-01 12:30:19.579 [DEBUG] [ng.insteonplm.internal.driver.Driver] - added new port: port_0 /hub2/user:password@192.168.0.117:25105,poll_time=1000

2018-01-01 12:30:19.665 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - config: service.pid -> org.openhab.insteonplm

2018-01-01 12:30:19.704 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - setting driver listener

2018-01-01 12:30:19.836 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - starting 0 ports

2018-01-01 12:30:19.966 [DEBUG] [ding.insteonplm.internal.driver.Port] - starting port /hub2/user:password@192.168.0.117:25105,poll_time=1000

2018-01-01 12:30:22.643 [DEBUG] [ding.insteonplm.internal.driver.Port] - starting reader...

2018-01-01 12:30:22.734 [DEBUG] [ding.insteonplm.internal.driver.Port] - starting writer...

2018-01-01 12:30:26.696 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x60|

2018-01-01 12:30:26.723 [DEBUG] [ding.insteonplm.internal.driver.Port] - clearing modem db!

2018-01-01 12:30:26.711 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - ports started

2018-01-01 12:30:26.774 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - initialization complete, found 1 port!

2018-01-01 12:30:26.832 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - item xmas_module_on_off             binding changed: addr=49.3E.80|prodKey:F00.00.1B|feature:switch

2018-01-01 12:30:28.950 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-insteonplm'

2018-01-01 12:30:30.399 [DEBUG] [plm.internal.device.DeviceTypeLoader] - F00.00.22 ->pk:F00.00.22|model:2982-222|desc:Insteon Smoke Bridge|features:notification=ReceiveBroadcast:lastheardfrom=GenericLastTime|groups

2018-01-01 12:30:30.456 [DEBUG] [plm.internal.device.DeviceTypeLoader] - F00.00.21 ->pk:F00.00.21|model:2441V|desc:Insteon Thermostat Adaptor for Venstar|features:fanmode=VenstarFanMode:iscooling=VenstarIsCooling:heatsetpoint=VenstarHeatSetPoint:tempfahrenheit=VenstarTemperatureFahrenheit:coolsetpoint=VenstarCoolSetPoint:humidity=VenstarHumidity:lastheardfrom=GenericLastTime:systemmode=VenstarSystemMode:isheating=VenstarIsHeating|groups:data1b_group=coolsetpoint,heatsetpoint,systemmode,fanmode,tempfahrenheit,humidity,isheating,iscooling

2018-01-01 12:30:32.047 [DEBUG] [plm.internal.device.DeviceTypeLoader] - F00.00.18 ->pk:F00.00.18|model:2441TH|desc:Insteon Thermostat|features:tempcelsius=ThermostatTemperatureCelsius:humidityhigh=ThermostatHumidityHigh:tempfahrenheit=ThermostatTemperatureFahrenheit:stage1duration=ThermostatStage1Duration:humiditylow=ThermostatHumidityLow:systemmode=ThermostatSystemMode:isheating=ThermostatIsHeating:fanmode=ThermostatFanMode:iscooling=ThermostatIsCooling:heatsetpoint=ThermostatHeatSetPoint:coolsetpoint=ThermostatCoolSetPoint:humidity=ThermostatHumidity:lastheardfrom=GenericLastTime:acdelay=ThermostatACDelay:backlightduration=ThermostatBackLightDuration|groups:data1b_group=humidityhigh,humiditylow,stage1duration:data2_group=coolsetpoint,heatsetpoint,systemmode,fanmode,isheating,iscooling,tempcelsius,tempfahrenheit,humidity:data1_group=backlightduration,acdelay

2018-01-01 12:30:39.924 [DEBUG] [ding.insteonplm.internal.driver.Port] - found modem 49.ED.CD in device_types: 49.ED.CD|broadcastonoff->GroupBroadcastOnOff(0:1:0)

2018-01-01 12:30:40.211 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x69|

2018-01-01 12:30:41.017 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - item xmas_module_dimmer             binding changed: addr=47.18.E7|prodKey:F00.00.19|feature:dimmer

2018-01-01 12:30:41.648 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:47.18.E7|LinkData1:0x01|LinkData2:0x0E|LinkData3:0x43|

2018-01-01 12:30:41.764 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x6A|

2018-01-01 12:30:42.841 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x57|RecordFlags:0xA2|ALLLinkGroup:0x01|LinkAddr:47.18.E7|LinkData1:0x00|LinkData2:0x00|LinkData3:0x00|

2018-01-01 12:30:42.882 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x6A|

2018-01-01 12:30:43.955 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:49.3E.80|LinkData1:0x01|LinkData2:0x37|LinkData3:0x48|

2018-01-01 12:30:44.025 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x6A|

2018-01-01 12:30:45.077 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x57|RecordFlags:0xA2|ALLLinkGroup:0x01|LinkAddr:49.3E.80|LinkData1:0x00|LinkData2:0x00|LinkData3:0x00|

2018-01-01 12:30:45.137 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x6A|

2018-01-01 12:30:46.179 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x03|LinkAddr:47.18.E7|LinkData1:0x01|LinkData2:0x0E|LinkData3:0x43|

2018-01-01 12:30:46.244 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x6A|

2018-01-01 12:30:47.368 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x03|LinkAddr:49.3E.80|LinkData1:0x01|LinkData2:0x37|LinkData3:0x48|

2018-01-01 12:30:47.414 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x6A|

2018-01-01 12:30:48.429 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x57|RecordFlags:0xA2|ALLLinkGroup:0x01|LinkAddr:44.91.24|LinkData1:0x00|LinkData2:0x00|LinkData3:0x00|

2018-01-01 12:30:48.464 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x6A|

2018-01-01 12:30:49.529 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x57|RecordFlags:0xA2|ALLLinkGroup:0x02|LinkAddr:40.33.59|LinkData1:0x00|LinkData2:0x00|LinkData3:0x00|

2018-01-01 12:30:49.574 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (0): OUT:Cmd:0x6A|

2018-01-01 12:30:51.164 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - modem database has 5 entries!

2018-01-01 12:30:51.180 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - modem db entry: 47.18.E7

2018-01-01 12:30:51.217 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - modem db entry: 40.33.59

2018-01-01 12:30:51.246 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - modem db entry: 49.3E.80

2018-01-01 12:30:51.280 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - modem db entry: 49.ED.CD

2018-01-01 12:30:51.320 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - modem db entry: 44.91.24

2018-01-01 12:30:51.372 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 47.18.E7 found in the modem database and the modem controls groups [0x00,0x03] and responds to groups [0x01].

2018-01-01 12:30:51.445 [DEBUG] [ng.insteonplm.internal.driver.Poller] - start polling device 47.18.E7|fastonoff->FastOnOff(0:1:2)|lastheardfrom->GenericLastTime(0:0:0)|manualchange->ManualChange(0:1:2)|dimmer->GenericDimmer(1:3:8)

2018-01-01 12:30:51.566 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.3E.80 found in the modem database and the modem controls groups [0x00,0x03] and responds to groups [0x01].

2018-01-01 12:30:51.627 [DEBUG] [ng.insteonplm.internal.driver.Poller] - start polling device 49.3E.80|lastheardfrom->GenericLastTime(0:0:0)|switch->GenericSwitch(1:1:6)

2018-01-01 12:30:51.777 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 40.33.59 found in the modem database, but is not configured as an item and the modem responds to groups [0x02].

2018-01-01 12:30:51.818 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 44.91.24 found in the modem database, but is not configured as an item and the modem responds to groups [0x01].

2018-01-01 12:30:51.839 [DEBUG] [eonplm.internal.device.InsteonDevice] - qe taken off direct: GenericDimmer(1:3:8) OUT:Cmd:0x62|toAddress:47.18.E7|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|

2018-01-01 12:30:51.888 [DEBUG] [eonplm.internal.device.InsteonDevice] - next request queue processed in 500 msec, quiettime = 500

2018-01-01 12:30:51.902 [DEBUG] [ding.insteonplm.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:47.18.E7|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x00|

2018-01-01 12:30:52.817 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - got msg: IN:Cmd:0x50|fromAddress:47.18.E7|toAddress:49.ED.CD|messageFlags:0x20=ACK_OF_DIRECT:0:0|command1:0x00|command2:0xFF|

2018-01-01 12:30:52.858 [DEBUG] [eonplm.internal.device.InsteonDevice] - ----- applying message to feature: FastOnOff

2018-01-01 12:30:52.885 [DEBUG] [eonplm.internal.device.InsteonDevice] - ----- applying message to feature: ManualChange

2018-01-01 12:30:52.918 [DEBUG] [eonplm.internal.device.InsteonDevice] - ----- applying message to feature: GenericDimmer

2018-01-01 12:31:49.207 [DEBUG] [org.openhab.binding.insteonplm      ] - BundleEvent STOPPING - org.openhab.binding.insteonplm

2018-01-01 12:31:49.292 [DEBUG] [org.openhab.binding.insteonplm      ] - ServiceEvent UNREGISTERING - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.insteonplm, component.name=org.openhab.binding.insteonplm.activebinding, component.id=170, service.id=292, service.bundleid=213, service.scope=bundle} - org.openhab.binding.insteonplm

2018-01-01 12:31:49.368 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - deactivating binding!

2018-01-01 12:31:49.398 [DEBUG] [g.insteonplm.InsteonPLMActiveBinding] - shutting down binding

2018-01-01 12:31:49.433 [DEBUG] [ding.insteonplm.internal.driver.Port] - waiting for read thread to exit for port /hub2/useer:passwordx@192.168.0.117:25105,poll_time=1000

2018-01-01 12:31:49.431 [ERROR] [ding.insteonplm.internal.driver.Port] - got interrupted exception in write thread

2018-01-01 12:31:49.469 [DEBUG] [ding.insteonplm.internal.driver.Port] - exiting writer thread!

Why is the binding being deactivated?

Any help would be appreciated.

Thanks

antoine · January 1, 2018, 8:52pm

Using Karaf:

openhab> bundle:list
START LEVEL 100 , List Threshold: 50
... 
213 │ Stopping │  80 │ 1.11.0                 │ openHAB Insteon PLM Binding
214 │ Active   │  80 │ 2.2.0                  │ openHAB 1.x Compatibility
openhab> bundle:stop 213
Error executing command: Error executing command on bundles:
        Error stopping bundle213: Unable to acquire the state change lock for the module: osgi.identity; type="osgi.bundle"; version:Version="1.11.0"; osgi.identity="org.openhab.binding.insteonplm" [id=213] STOPPED [STOPPED]
openhab> bundle:start 213
Error executing command: Error executing command on bundles:
        Error starting bundle 213: Unable to acquire the state change lock for the module: osgi.identity; type="osgi.bundle"; version:Version="1.11.0"; osgi.identity="org.openhab.binding.insteonplm" [id=213] STARTED [STOPPED]