Insteonplm and large modem databases

I am starting to see issues with insteonplm binding now that my modem database is growing. I am running into errors like:

2015-12-21 13:41:26 WARN  o.o.b.i.i.message.MsgFactory[:121]- got unknown command code 0x00
2015-12-21 13:41:26 WARN  o.o.b.i.internal.driver.Port[:266]- bad data received: got unknown command code 0x00
2015-12-21 13:43:24 WARN  o.o.b.i.i.d.ModemDBBuilder[:74]- modem database download unsuccessful, restarting!
2015-12-21 13:43:31 WARN  o.o.b.i.i.message.MsgFactory[:121]- got unknown command code 0x01
2015-12-21 13:43:31 WARN  o.o.b.i.internal.driver.Port[:266]- bad data received: got unknown command code 0x01
2015-12-21 13:45:24 WARN  o.o.b.i.i.d.ModemDBBuilder[:74]- modem database download unsuccessful, restarting!
2015-12-21 13:45:28 WARN  o.o.b.i.i.message.MsgFactory[:121]- incoming message does not start with 0x02
2015-12-21 13:45:28 WARN  o.o.b.i.internal.driver.Port[:266]- bad data received: incoming message does not start with 0x02
2015-12-21 13:45:28 WARN  o.o.b.i.internal.driver.Port[:269]- got bad data back, must assume message was acked.
2015-12-21 13:47:24 WARN  o.o.b.i.i.d.ModemDBBuilder[:74]- modem database download unsuccessful, restarting!
2015-12-21 13:47:25 WARN  o.o.b.i.i.message.MsgFactory[:121]- got unknown command code 0x02
2015-12-21 13:47:25 WARN  o.o.b.i.internal.driver.Port[:266]- bad data received: got unknown command code 0x02
2015-12-21 13:47:25 WARN  o.o.b.i.internal.driver.Port[:269]- got bad data back, must assume message was acked.
2015-12-21 13:47:32 WARN  o.o.b.i.i.message.MsgFactory[:121]- got unknown command code 0x44
2015-12-21 13:47:32 WARN  o.o.b.i.internal.driver.Port[:266]- bad data received: got unknown command code 0x44
2015-12-21 13:47:32 WARN  o.o.b.i.internal.driver.Port[:269]- got bad data back, must assume message was acked.
2015-12-21 13:48:13 WARN  o.o.b.i.i.message.MsgFactory[:121]- incoming message does not start with 0x02
2015-12-21 13:48:13 WARN  o.o.b.i.internal.driver.Port[:266]- bad data received: incoming message does not start with 0x02
2015-12-21 13:48:13 WARN  o.o.b.i.internal.driver.Port[:269]- got bad data back, must assume message was acked.
2015-12-21 13:49:41 WARN  o.o.b.i.i.message.MsgFactory[:121]- got unknown command code 0xC5
2015-12-21 13:49:41 WARN  o.o.b.i.internal.driver.Port[:266]- bad data received: got unknown command code 0xC5

Full debug logs can be found here.

“My modem never does that”.

Just checked my modem, and I really don’t have a single error like that. I have about 105 or so devices.

  1. serial transfer errors, could be bad cable. Is this a usb or serial modem? If usb, then that’s highly unlikely to be it.
  2. I would say “noise on the insteon network” but I don’t think so because you get that at startup, during modem db download, and that is strictly local
  3. modem is going bad. Mine is 2.5years old now, and just crapped out last week. First the green LED light looked a little dim, then the modem would go offline. Unplugging would resurrect it. Now it’s dead as a door knob. That is a very common problem. Supposedly poorly dimensioned and low quality capacitors. I ordered a new modem and replacement capacitors for the old one. Hope to get the old modem back up so I don’t have to relink all the devices (or rather, hack the link databases via glorious InsteonTerminal).

Bernd

I too am having this problem, only when trying to use a 2245-222 (2014HUB).
Things seem to work if I point it to my insteon USB (2413u) PLM but when connected to 2014HUB I get:

2015-12-23 07:42:52.660 [WARN ] [.o.b.i.i.device.ModemDBBuilder] - modem database download unsuccessful, restarting!
2015-12-23 07:42:57.170 [INFO ] [ome.event.ThingStatusInfoEvent] - 'yahooweather:weather:barrington' updated: ONLINE
2015-12-23 07:42:57.357 [INFO ] [smarthome.event.ItemStateEvent] - CurrentDate updated to 2015-12-23T07:42:57
2015-12-23 07:42:57.369 [INFO ] [s.event.ItemStateChangedEvent ] - CurrentDate changed from 2015-12-23T07:41:57 to 2015-12-23T07:42:57
2015-12-23 07:43:21.312 [INFO ] [smarthome.event.ItemStateEvent] - Sun_Elevation updated to 6.66
2015-12-23 07:43:21.321 [INFO ] [s.event.ItemStateChangedEvent ] - Sun_Elevation changed from 6.74 to 6.66
2015-12-23 07:43:30.539 [WARN ] [.i.internal.message.MsgFactory] - incoming message does not start with 0x02
2015-12-23 07:43:30.541 [WARN ] [o.o.b.i.internal.driver.Port  ] - bad data received: incoming message does not start with 0x02
2015-12-23 07:43:57.121 [INFO ] [ome.event.ThingStatusInfoEvent] - 'yahooweather:weather:barrington' updated: ONLINE
2015-12-23 07:43:57.356 [INFO ] [smarthome.event.ItemStateEvent] - CurrentDate updated to 2015-12-23T07:43:57
2015-12-23 07:43:57.366 [INFO ] [s.event.ItemStateChangedEvent ] - CurrentDate changed from 2015-12-23T07:42:57 to 2015-12-23T07:43:57
2015-12-23 07:44:21.313 [INFO ] [smarthome.event.ItemStateEvent] - Sun_Elevation updated to 6.57
2015-12-23 07:44:21.322 [INFO ] [s.event.ItemStateChangedEvent ] - Sun_Elevation changed from 6.66 to 6.57
2015-12-23 07:44:52.662 [WARN ] [.o.b.i.i.device.ModemDBBuilder] - modem database download unsuccessful, restarting!

@sipvoip are you using a 2245-222 (2014HUB) too?

I turned on debug and it seems that the database is in the process of getting updated but either never finishes or isn’t allowed time to finish - not sure which.

Could it be that I have a device the needs a custom (XML) definition?
Or could it be that I have too many devices * too many links?

2015-12-23 08:11:50 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x38|LinkAddr:1F.6D.C1|LinkData1:0x03|LinkData2:0x20|LinkData3:0x41|
2015-12-23 08:11:50 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:11:51 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x39|LinkAddr:1F.6D.C1|LinkData1:0x03|LinkData2:0x20|LinkData3:0x41|
2015-12-23 08:11:51 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:11:52 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xEA|ALLLinkGroup:0x3A|LinkAddr:22.15.47|LinkData1:0x03|LinkData2:0x1B|LinkData3:0x41|
2015-12-23 08:11:52 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:11:53 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xEA|ALLLinkGroup:0x3A|LinkAddr:15.64.D3|LinkData1:0x03|LinkData2:0x0F|LinkData3:0x36|
2015-12-23 08:11:53 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:11:54 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x3A|LinkAddr:1A.F6.AF|LinkData1:0x03|LinkData2:0x0E|LinkData3:0x41|
2015-12-23 08:11:55 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:11:56 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x3A|LinkAddr:15.64.97|LinkData1:0x03|LinkData2:0x0F|LinkData3:0x36|
2015-12-23 08:11:56 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:11:57 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xEA|ALLLinkGroup:0x3A|LinkAddr:15.61.AC|LinkData1:0x03|LinkData2:0x0F|LinkData3:0x36|
2015-12-23 08:11:57 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:11:58 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x3A|LinkAddr:1F.6D.C1|LinkData1:0x03|LinkData2:0x20|LinkData3:0x41|
2015-12-23 08:11:58 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:11:59 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x3A|LinkAddr:1F.73.3E|LinkData1:0x03|LinkData2:0x20|LinkData3:0x41|
2015-12-23 08:11:59 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:00 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xEA|ALLLinkGroup:0x3A|LinkAddr:20.33.90|LinkData1:0x03|LinkData2:0x3A|LinkData3:0x42|
2015-12-23 08:12:00 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:01 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x3A|LinkAddr:1F.7F.83|LinkData1:0x03|LinkData2:0x20|LinkData3:0x41|
2015-12-23 08:12:01 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:01 [WARN ] [.o.b.i.i.device.ModemDBBuilder:74   ] - modem database download unsuccessful, restarting!
2015-12-23 08:12:01 [DEBUG] [o.o.b.i.internal.driver.Port  :122  ] - clearing modem db!
2015-12-23 08:12:02 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xEA|ALLLinkGroup:0x3A|LinkAddr:16.4B.8D|LinkData1:0x03|LinkData2:0x19|LinkData3:0x38|
2015-12-23 08:12:02 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x69|
2015-12-23 08:12:03 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:03 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:20.33.90|LinkData1:0x03|LinkData2:0x3A|LinkData3:0x42|
2015-12-23 08:12:04 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:06.21.97|LinkData1:0x03|LinkData2:0x0C|LinkData3:0x28|
2015-12-23 08:12:04 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:05 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:06.21.C1|LinkData1:0x03|LinkData2:0x0C|LinkData3:0x28|
2015-12-23 08:12:05 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:06 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:09.55.7A|LinkData1:0x03|LinkData2:0x01|LinkData3:0x27|
2015-12-23 08:12:06 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:07 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xA2|ALLLinkGroup:0x01|LinkAddr:09.55.7A|LinkData1:0x00|LinkData2:0x00|LinkData3:0x00|
2015-12-23 08:12:07 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:08 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:20.1F.C1|LinkData1:0x03|LinkData2:0x3A|LinkData3:0x42|
2015-12-23 08:12:08 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:09 [DEBUG] [o.o.b.i.internal.driver.Port  :382  ] - writing (0): OUT:Cmd:0x6A|
2015-12-23 08:12:09 [DEBUG] [.o.b.i.InsteonPLMActiveBinding:538  ] - got msg: IN:Cmd:0x57|RecordFlags:0xE2|ALLLinkGroup:0x00|LinkAddr:20.34.1F|LinkData1:0x03|LinkData2:0x3A|LinkData3:0x42|

I am using 2012 hub with 123 devices

How many devices do you have?

I have 2014 HUB with about 62 devices.

So we are not looking at the direct PLM modems here, but hubs.

I’m not surprised about the 2014 hub timing out. With 1sec poll interval, it will time out before the last device has been polled. You can bump the timeout by modifying this variable in openhab.cfg:

insteonplm:modem_db_retry_timeout=120000

About the 2012 hub: yes, that one produces a surprisingly large number of read errors, the source of which we could not figure out. IIRC the corrupted data comes over the tcp stream, so it’s not an issue with the binding. In fact I remember having to rework the binding just to make it more robust to such data corruption. That’s when we introduced the retries for the modem database.

Bernd

Thanks Bernd.
I tried your suggestion of 120000 and still got the timeout.
I then set the poll rate to 100 ms instead of 1000 ms and this, combined with the 120000 seems to have solved it.
Thanks!

The 120000 is the default value. You would need to bump it to maybe 4mins.
I’m morally opposed to dropping the poll interval to 100ms because of the overhead involved and the additional load. I hope you don’t run into other issues related to reading the buffer while the PLM writes it. It was never quite clear to me how the synchronization works on the hub’s side between data coming in from the insteon network into the modem buffer, and the http server fetching from that buffer at the same time. You’ll find out :smile:

Your concerns were justified - 100ms poll rate was too much for my Raspberry Pi and resulted in terrible performance.
I went back to 1000 ms poll rate ime combined with
modem_db_retry_timeout=300000

seems to be working

Should I get myself a 2014 hub? I thought I read somewhere that the 2012 was better so that is what I have been using.

From a technology perspective the 2012 hub is better because it exposes the
raw PLM stream. Except that it mixes in some corrupt data.
The 2014 hub doesn’t expose the PLM stream, requiring the binding to poll,
with all the disadvantages of polling. Don’t know whether it actually
produces less corrupt data than the 2012 hub. The http polls definitely
return bad data occasionally.

So would http poll cause a delay between when I flip a switch and openhab sees is over the 2012 hub? I noticed that people are saying the 2014 hub has better insteon signal, I wonder if it would work better. Just hate the idea of reconfiguring 127 devices just to test it out…

Yes, there would be an additional delay of 1s max, but sometimes I see these bizarre delays actually on the insteon network where it takes seconds for a device to respond after the binding logs a “msg sent” line. In other words: that 1s extra may not be that big a deal. Still, with so many devices I’d stick with the 2012 hub unless you have good reason to switch.

My favorite thing about the 2014 hub is the Amazon Echo integration. Without the Amazon Echo it would be just another insteon hub.

1 Like