I just installed an Insteon switch. However, OpenHAB does not seem to be properly recognizing the switch. It first reports that the device is not in the modem DB. (I linked it to the modem.) In short order, it then reports it’s found in the modem DB, but not configured as an item. Yet, I’ve configured the item. What’s going on, and how can I better troubleshoot this? Relevant excerpt are below. Note: I obfuscated the actual Insteon address as xx.yy.zz
The openhab.log file lists these entries of particular interest.
2017-12-29 20:12:06.868 [WARN ] [g.insteonplm.InsteonPLMActiveBinding] - device xx.yy.zz not found in the modem database. Did you forget to link?
2017-12-29 20:12:06.904 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device xx.yy.zz found in the modem database, but is not configured as an item and the modem controls groups [0xFE]
Can you provide more of the log file? No need to change the address of the device. From what I can see so far, you don’t have the device linked both ways. Here’s an example from my log file:
2017-12-23 10:19:03.248 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - modem database has 62 entries!
2017-12-23 10:19:03.260 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 23.9F.C9 found in the modem database and the modem controls groups [0xFE] and responds to groups [0x
01].
2017-12-23 10:19:03.284 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 24.33.F7 found in the modem database and the modem controls groups [0xFE] and responds to groups [0x
01].
2017-12-23 10:19:03.325 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 23.9F.82 found in the modem database and the modem controls groups [0xFE] and responds to groups [0x
01].
2017-12-23 10:19:03.337 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 19.8B.65 found in the modem database and the modem controls groups [0xFE] and responds to groups [0x
01].
...
2017-12-23 10:19:04.154 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 23.9F.C9 to level 100
2017-12-23 10:19:08.514 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 24.33.F7 to OFF
2017-12-23 10:19:09.513 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 23.9F.55 to level 100
2017-12-23 10:19:10.038 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 23.A0.D9 to level 100
2017-12-23 10:19:12.009 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 23.A0.D9 to level 100
@ranielsen I did a reboot (I suppose I could have simply restarted OpenHAB too. ) Here’s the log excerpt from the point of the reboot. I didn’t use Insteon Terminal to link the switches (2477s) with the PLM. Instead I used my previous home automation software (QW Home Automation) to do the linking. I linked several other switches/dimmers this way, but the last two I installed are giving me grief.
2017-12-30 15:33:51.899 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2017-12-30 15:33:51.919 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-12-30 15:33:51.942 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard
2017-12-30 15:34:39.953 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'insteonplm.items'
2017-12-30 15:34:40.128 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2017-12-30 15:34:47.862 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2017-12-30 15:34:52.657 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'insteonplm.rules'
2017-12-30 15:34:53.660 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2017-12-30 15:34:55.225 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.1.100:8080
2017-12-30 15:34:55.228 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.1.100:8443
2017-12-30 15:34:56.244 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-12-30 15:34:56.336 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-12-30 15:34:56.372 [INFO ] [nding.insteonplm.InsteonPLMActivator] - Insteon PLM binding has been started.
2017-12-30 15:34:56.557 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
2017-12-30 15:34:56.625 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 300 seconds
2017-12-30 15:34:56.750 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:home
2017-12-30 15:34:56.777 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:moon:home every 300 seconds
2017-12-30 15:34:56.792 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
2017-12-30 15:34:56.827 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 300 seconds
2017-12-30 15:34:56.878 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:home
2017-12-30 15:34:56.882 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:moon:home every 300 seconds
2017-12-30 15:34:57.104 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - dead device timeout set to 3000s
2017-12-30 15:34:57.120 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - config: port_0 -> /dev/ttyUSB0
2017-12-30 15:34:57.135 [INFO ] [b.core.service.AbstractActiveService] - InsteonPLM has been started
2017-12-30 15:34:57.156 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - devices: 0 configured, 0 polling, msgs received: 0
2017-12-30 15:34:57.166 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - config: port_4 -> /dev/ttyUSB0**
2017-12-30 15:34:57.168 [WARN ] [ng.insteonplm.internal.driver.Driver] - ignored attempt to add duplicate port: port_4 /dev/ttyUSB0**
2017-12-30 15:34:57.170 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - config: service.pid -> org.openhab.insteonplm
2017-12-30 15:34:57.250 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-12-30 15:34:57.274 [INFO ] [onplm.internal.driver.SerialIOStream] - successfully opened port /dev/ttyUSB0
2017-12-30 15:34:58.481 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - modem database has 23 entries!
2017-12-30 15:34:58.485 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 23.F0.1B found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.507 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 23.E7.D1 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.509 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 3B.36.46 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.581 [WARN ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.F2.2F not found in the modem database. Did you forget to link?
2017-12-30 15:34:58.583 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 43.14.90 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.586 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 43.15.EB found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.591 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 2F.C8.43 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.605 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 37.3F.82 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.608 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 43.1D.8D found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.611 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 29.D4.51 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.614 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 25.67.A3 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.616 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 41.CF.94 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.619 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 23.EF.0B found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.622 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 28.86.6A found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.624 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 46.B2.7D found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.627 [WARN ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.D2.49 not found in the modem database. Did you forget to link?
2017-12-30 15:34:58.629 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 43.59.20 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.631 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 28.74.3C found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.635 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 28.76.61 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.638 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 42.6F.CC found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.642 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 43.13.F2 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.646 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 43.48.66 found in the modem database and the modem controls groups [0xFE].
2017-12-30 15:34:58.650 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.D2.2F found in the modem database, but is not configured as an item and the modem controls groups [0xFE].
2017-12-30 15:34:58.653 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.D4.29 found in the modem database, but is not configured as an item and the modem controls groups [0xFE].
2017-12-30 15:34:58.994 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 23.F0.1B to OFF
2017-12-30 15:35:11.881 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 23.E7.D1 to OFF
2017-12-30 15:35:17.205 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 23.EF.0B to OFF
2017-12-30 15:35:22.537 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 23.E7.D1 to OFF
2017-12-30 15:35:24.989 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 3B.36.46 to level 0
2017-12-30 15:35:30.323 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 43.13.F2 to level 0
2017-12-30 15:35:35.646 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 3B.36.46 to level 0
2017-12-30 15:35:38.045 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 43.14.90 to level 0
2017-12-30 15:35:43.379 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 43.48.66 to level 0
2017-12-30 15:35:48.704 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 43.14.90 to level 0
2017-12-30 15:35:51.087 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 43.15.EB to level 0
2017-12-30 15:36:04.140 [INFO ] [onplm.internal.device.MessageHandler] - DimmerRequestReplyHandler: set device 2F.C8.43 to level 0
2017-12-30 15:36:17.198 [INFO ] [onplm.internal.device.MessageHandler] - SwitchRequestReplyHandler: set device 37.3F.82 to ON
I’m using a PLM. I do have an oddity with the PLM/OpenHAB2 configuration that I documented here though. Basically, OpenHAB is trying to initialize the PLM on a phantom port, and I con’t figure out where OpenHAB is pulling the configuration from. I never got an answer, but it doesn’t (didn’t) seem to be causing other problems. I don’t know if it’s related or not, but I thought I throw that out.
I wonder if you are using the wrong addresses in your .items file? I see this in your log file:
2017-12-30 15:34:58.581 [WARN ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.F2.2F not found in the modem database. Did you forget to link?
2017-12-30 15:34:58.627 [WARN ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.D2.49 not found in the modem database. Did you forget to link?
They have very similar addresses to the last two:
2017-12-30 15:34:58.650 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.D2.2F found in the modem database, but is not configured as an item and the modem controls groups [0xFE].
2017-12-30 15:34:58.653 [INFO ] [g.insteonplm.InsteonPLMActiveBinding] - device 49.D4.29 found in the modem database, but is not configured as an item and the modem controls groups [0xFE].
I also was using QW Home Automation and still use it to link my devices. One thing you might want to also set up is the devices as a controller (plm responder) so you can get notified when the dimmers and switches are turned on/off
As for port_4, you must have some extraneous config somewhere.
@Burzin_Sumariwalla
Have a look at Rob’s comment. You probably have a config error 49.d2.49 vs 49.d4.29. I don’t recall ever seeing an error scenario like that.
) Here’s the log excerpt from the point of the reboot. I didn’t use Insteon Terminal to link the switches (2477s) with the PLM. Instead I used my previous home automation software (QW Home Automation) to do the linking. I linked several other switches/dimmers this way, but the last two I installed are giving me grief.