Insteon Binding stops responding

Add-ons Bindings
,
1

I recently upgraded my OpenHAB version to the latest stable release and while doing so I decided to switch from the InsteonPLM binding from OH1 to the new Insteon binding for OH2. I had been testing it and it seemed to do ok but I’m starting to run into an issue. I’m not sure if this is an issue only I’m facing or if it’s a more common issue.

The following is my things file:

Bridge insteon:network:InsteonHub [port="/dev/ttyUSB0"] {

    Thing   device  BasementCeilingLightSwitch          "Basement Ceiling Light Switch"     @"Basement"         [address="48.83.3C", productKey="F00.00.02"]

    Thing   device  BathroomCeilingLightSwitch          "Bathroom Ceiling Light Switch"     @"Bathroom"         [address="4E.CE.A5", productKey="F00.00.01"]

    Thing   device  DiningRoomCeilingFan                "Dining Room Ceiling Fan"           @"Dining Room"      [address="3F.B6.AB", productKey="F00.00.1C"]

    Thing   device  DiningRoomKeypad                    "Dining Room Keypad"                @"Dining Room"      [address="43.5D.5E", productKey="F00.00.16"]

    {

        Channels:

            Type switch: keypadButtonB "Keypad Button B" [group="0x30"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x31"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x32"]

            Type switch: keypadButtonE "Keypad Button E" [group="0x33"]

            Type switch: keypadButtonF "Keypad Button F" [group="0x34"]

            Type switch: keypadButtonG "Keypad Button G" [group="0x35"]

            Type switch: keypadButtonH "Keypad Button H" [group="0x36"]

    }

    Thing   device  EntryKeypad                         "Entry Keypad"                      @"Entry"            [address="3D.88.42", productKey="F00.00.15"]

    {

        Channels:

            Type switch: keypadButtonA "Keypad Button A" [group="0x10"]

            Type switch: keypadButtonB "Keypad Button B" [group="0x11"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x12"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x13"]

    }

    Thing   device  GuestKeypad                         "Guest Keypad"                      @"Guest Bedroom"    [address="45.76.91", productKey="F00.00.16"]

    {

        Channels:

            Type switch: keypadButtonB "Keypad Button B" [group="0x80"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x81"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x82"]

            Type switch: keypadButtonE "Keypad Button E" [group="0x83"]

            Type switch: keypadButtonF "Keypad Button F" [group="0x84"]

            Type switch: keypadButtonG "Keypad Button G" [group="0x85"]

            Type switch: keypadButtonH "Keypad Button H" [group="0x86"]

    }

    Thing   device  HallwayKeypad                       "Hallway Keypad"                    @"Hallway"          [address="3D.80.E7", productKey="F00.00.16"]

    {

        Channels:

            Type switch: keypadButtonB "Keypad Button B" [group="0x70"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x71"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x72"]

            Type switch: keypadButtonE "Keypad Button E" [group="0x73"]

            Type switch: keypadButtonF "Keypad Button F" [group="0x74"]

            Type switch: keypadButtonG "Keypad Button G" [group="0x75"]

            Type switch: keypadButtonH "Keypad Button H" [group="0x76"]

    }

    Thing   device  HallwayStairwayDimmer               "Hallway Stairway Dimmer"           @"Hallway"          [address="41.A9.4E", productKey="F00.00.01"]

    Thing   device  KitchenKeypad                       "Kitchen Keypad"                    @"Kitchen"          [address="43.97.A4", productKey="F00.00.14"]

    {

        Channels:

            Type switch: keypadButtonA "Keypad Button A" [group="0x50"]

            Type switch: keypadButtonB "Keypad Button B" [group="0x51"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x52"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x53"]

    }

    Thing   device  KitchenBackDoorKeypad               "Kitchen Back Door Keypad"          @"Kitchen"          [address="43.68.C0", productKey="F00.00.15"]

    {

        Channels:

            Type switch: keypadButtonA "Keypad Button A" [group="0x58"]

            Type switch: keypadButtonB "Keypad Button B" [group="0x59"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x5A"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x5B"]

    }

    Thing   device  KitchenPendantLights                "Kitchen Pendant Lights"            @"Kitchen"          [address="43.63.96", productKey="F00.00.15"]

    {

        Channels:

            Type switch: keypadButtonA "Keypad Button A" [group="0x60"]

            Type switch: keypadButtonB "Keypad Button B" [group="0x61"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x62"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x63"]

    }

    Thing   device  LaundryRoomKeypad                   "Laundry Room Keypad"               @"Laundry Room"     [address="43.6A.A9", productKey="F00.00.15"]

    {

        Channels:

            Type switch: keypadButtonA "Keypad Button A" [group="0x40"]

            Type switch: keypadButtonB "Keypad Button B" [group="0x41"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x42"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x43"]

    }

    Thing   device  LivingRoomEntryKeypad               "Living Room Entry Keypad"          @"Living Room"      [address="3D.91.6E", productKey="F00.00.15"]

    {

        Channels:

            Type switch: keypadButtonA "Keypad Button A" [group="0x18"]

            Type switch: keypadButtonB "Keypad Button B" [group="0x19"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x1A"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x1B"]

    }

    Thing   device  LivingRoomKeypad                    "Living Room Keypad"                @"Living Room"      [address="3D.C4.F4", productKey="F00.00.16"]

    {

        Channels:

            Type switch: keypadButtonB "Keypad Button B" [group="0x20"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x21"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x22"]

            Type switch: keypadButtonE "Keypad Button E" [group="0x23"]

            Type switch: keypadButtonF "Keypad Button F" [group="0x24"]

            Type switch: keypadButtonG "Keypad Button G" [group="0x25"]

            Type switch: keypadButtonH "Keypad Button H" [group="0x26"]

    }

    Thing   device  LivingRoomFrontCeilingFan           "Living Room Front Ceiling Fan"     @"Living Room"      [address="49.23.90", productKey="F00.00.1C"]

    Thing   device  LivingRoomRearCeilingFan            "Living Room Rear Ceiling Fan"      @"Living Room"      [address="40.16.FB", productKey="F00.00.1C"]

    Thing   device  MasterBathroomCeilingLightsKeypad   "Master Bathroom Ceiling Lights"    @"Master Bathroom"  [address="43.A3.5F", productKey="F00.00.15"]

    {

        Channels:

            Type switch: keypadButtonA "Keypad Button A" [group="0x98"]

            Type switch: keypadButtonB "Keypad Button B" [group="0x99"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x9A"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x9B"]

    }

    Thing   device  MasterBathroomVanityKeypad          "Master Bathroom Vanity Lights"     @"Master Bathroom"  [address="43.A2.AE", productKey="F00.00.15"]

    {

        Channels:

            Type switch: keypadButtonA "Keypad Button A" [group="0x90"]

            Type switch: keypadButtonB "Keypad Button B" [group="0x91"]

            Type switch: keypadButtonC "Keypad Button C" [group="0x92"]

            Type switch: keypadButtonD "Keypad Button D" [group="0x93"]

    }

    Thing   device  MasterBedroomKeypad                 "Master Bedroom Keypad"             @"Master Bedroom"   [address="40.CB.1D", productKey="F00.00.16"]

    {

        Channels:

            Type switch: keypadButtonB "Keypad Button B" [group="0xB0"]

            Type switch: keypadButtonC "Keypad Button C" [group="0xB1"]

            Type switch: keypadButtonD "Keypad Button D" [group="0xB2"]

            Type switch: keypadButtonE "Keypad Button E" [group="0xB3"]

            Type switch: keypadButtonF "Keypad Button F" [group="0xB4"]

            Type switch: keypadButtonG "Keypad Button G" [group="0xB5"]

            Type switch: keypadButtonH "Keypad Button H" [group="0xB6"]

    }

    Thing   device  MasterBedroomCeilingFan             "Master Bedroom Ceiling Fan"        @"Master Bedroom"   [address="3F.B6.B5", productKey="F00.00.1C"]

    Thing   device  MasterBedroomClosetLight            "Master Bedroom Closet Light"       @"Master Bedroom"   [address="4E.D2.2A", productKey="F00.00.01"]

    Thing   device  PorchLightSwitch                    "Porch Light Switch"                @"Porch"            [address="3D.44.19", productKey="F00.00.02"]

    Thing   device  PorchOutlet                         "Porch Outlet"                      @"Porch"            [address="3B.A7.60", productKey="F00.00.1A"]

}

I created items simply linking to the load for each device, and the keypad buttons if it’s a keypad device. I then go to test the setup by setting dimmers to different values and making sure it comes through. It works for about 5-10 minutes of me changing the dimmer about once every 5 seconds. Then everything stops responding. I checked the logs and this is what I get with Insteon set to DEBUG:

2020-05-12 12:10:42.143 [DEBUG] [nternal.handler.InsteonDeviceHandler] - channel insteon:device:InsteonHub:HallwayKeypad:loadDimmer was triggered with the command 43
2020-05-12 12:10:42.143 [DEBUG] [nsteon.internal.device.InsteonDevice] - processing command 43 features: 35
2020-05-12 12:10:42.144 [DEBUG] [steon.internal.device.CommandHandler] - changing level of 3D.80.E7 to 43
2020-05-12 12:10:42.144 [DEBUG] [steon.internal.device.CommandHandler] - PercentHandler: sent msg to set 3D.80.E7 to 110
2020-05-12 12:10:42.144 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 3D.80.E7 for another 4426 usec
2020-05-12 12:10:42.145 [DEBUG] [ding.insteon.internal.InsteonBinding] - found binding config for channel insteon:device:InsteonHub:HallwayKeypad:loadDimmer
2020-05-12 12:10:44.144 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 3D.80.E7 for another 2426 usec
2020-05-12 12:10:44.406 [DEBUG] [nternal.handler.InsteonDeviceHandler] - channel insteon:device:InsteonHub:HallwayKeypad:loadDimmer was triggered with the command 0
2020-05-12 12:10:44.406 [DEBUG] [nsteon.internal.device.InsteonDevice] - processing command 0 features: 35
2020-05-12 12:10:44.407 [DEBUG] [steon.internal.device.CommandHandler] - changing level of 3D.80.E7 to 0
2020-05-12 12:10:44.407 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 3D.80.E7 for another 2163 usec
2020-05-12 12:10:44.407 [DEBUG] [steon.internal.device.CommandHandler] - PercentHandler: sent msg to set 3D.80.E7 to zero by switching off
2020-05-12 12:10:44.408 [DEBUG] [ding.insteon.internal.InsteonBinding] - found binding config for channel insteon:device:InsteonHub:HallwayKeypad:loadDimmer
2020-05-12 12:10:46.407 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 3D.80.E7 for another 163 usec
2020-05-12 12:10:47.990 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: KeyPadButtonGroup(0:0:0) OUT:Cmd:0x62|toAddress:40.CB.1D|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2020-05-12 12:10:47.991 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 1499 msec, quiettime = 500
2020-05-12 12:10:48.407 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 3D.80.E7

It looks like the binding is still getting the commands and trying to process them but the device never responds and the binding isn’t processing a response to the request for a status of the device.

So I switched back to the InsteonPLM binding for OH1 and I don’t have any issues. Is this an issue in the binding? An issue with my setup? I’m not sure what to look for to resolve the issue. I really like the new binding! So I’d really like to get it ironed out.

2

I have the 2.0 version running on 2.5.4 with no issues. I am on a hub vs plm.

Did you clear cache after switching to the 2.0 version? Only thing I could think of. We can see if other comment on issues, I have not seen any though.

These are the tough ones if we are the only one having an issue.

3

I actually even went to the step of going to an entirely different PC, installing OpenHAB and it still has the same issues there too. I can temporarily resolve the issue by commenting out my “things” definitions and then adding them back in. When I add them back in everything works for a while again, then it stops. Again this happens on both PCs I’m trying to nail down exactly what causes it but so far I only have insteon and hue bindings installed with things and items linked. That’s it.

4

Do you see any more details if you turn on trace debugging? Can you make sure that InsteonPLM isn’t also running by running the command:

bundle:list | grep steon

You should see something like this:

228 x Active x 80 x 2.5.5.202005110355 x openHAB Add-ons :: Bundles :: Insteon Binding

BTW, I’ve been using a PLM for a few months with no issues.

5

This is probably more than you need but this is what I have:

2020-05-12 11:09:00.296 [DEBUG] [nternal.handler.InsteonDeviceHandler] - channel insteon:device:InsteonHub:HallwayKeypad:loadDimmer was triggered with the command 0
2020-05-12 11:09:00.297 [DEBUG] [nsteon.internal.device.InsteonDevice] - processing command 0 features: 35
2020-05-12 11:09:00.297 [TRACE] [nsteon.internal.device.DeviceFeature] - LoadDimmerButton uses PercentHandler to handle command PercentType for 3D.80.E7
2020-05-12 11:09:00.297 [DEBUG] [steon.internal.device.CommandHandler] - changing level of 3D.80.E7 to 0
2020-05-12 11:09:00.297 [TRACE] [nsteon.internal.device.InsteonDevice] - enqueing direct message with delay 0
2020-05-12 11:09:00.298 [TRACE] [.internal.device.RequestQueueManager] - scheduling request for device 3D.80.E7 in 0 msec
2020-05-12 11:09:00.298 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 3D.80.E7 for another 1107 usec
2020-05-12 11:09:00.299 [TRACE] [.internal.device.RequestQueueManager] - device queue for 3D.80.E7 rescheduled in 2000 msec
2020-05-12 11:09:00.299 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 43.A3.5F must wait for 734 msec
2020-05-12 11:09:00.299 [DEBUG] [steon.internal.device.CommandHandler] - PercentHandler: sent msg to set 3D.80.E7 to zero by switching off
2020-05-12 11:09:00.300 [DEBUG] [ding.insteon.internal.InsteonBinding] - found binding config for channel insteon:device:InsteonHub:HallwayKeypad:loadDimmer
2020-05-12 11:09:00.662 [DEBUG] [nternal.handler.InsteonDeviceHandler] - channel insteon:device:InsteonHub:HallwayKeypad:loadDimmer was triggered with the command 0
2020-05-12 11:09:00.663 [DEBUG] [nsteon.internal.device.InsteonDevice] - processing command 0 features: 35
2020-05-12 11:09:00.663 [TRACE] [nsteon.internal.device.DeviceFeature] - LoadDimmerButton uses PercentHandler to handle command PercentType for 3D.80.E7
2020-05-12 11:09:00.663 [DEBUG] [steon.internal.device.CommandHandler] - changing level of 3D.80.E7 to 0
2020-05-12 11:09:00.663 [TRACE] [nsteon.internal.device.InsteonDevice] - enqueing direct message with delay 0
2020-05-12 11:09:00.664 [TRACE] [.internal.device.RequestQueueManager] - queue for dev 3D.80.E7 is already scheduled in 1634 msec
2020-05-12 11:09:00.664 [DEBUG] [steon.internal.device.CommandHandler] - PercentHandler: sent msg to set 3D.80.E7 to zero by switching off
2020-05-12 11:09:00.664 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 3D.80.E7 for another 741 usec
2020-05-12 11:09:00.665 [TRACE] [.internal.device.RequestQueueManager] - device queue for 3D.80.E7 rescheduled in 2000 msec
2020-05-12 11:09:00.664 [DEBUG] [ding.insteon.internal.InsteonBinding] - found binding config for channel insteon:device:InsteonHub:HallwayKeypad:loadDimmer
2020-05-12 11:09:00.665 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 43.A3.5F must wait for 368 msec
2020-05-12 11:09:01.036 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 43.A3.5F
2020-05-12 11:09:01.037 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: ExtStatusGroup(0:0:0) OUT:Cmd:0x62|toAddress:43.A3.5F|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x01|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x9A|userData14:0x88|
2020-05-12 11:09:01.037 [TRACE] [nsteon.internal.device.DeviceFeature] - ExtStatusGroup set query status to: QUERY_PENDING
2020-05-12 11:09:01.037 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:43.A3.5F|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x01|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x9A|userData14:0x88|
2020-05-12 11:09:01.038 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 500 msec, quiettime = 500
2020-05-12 11:09:01.038 [TRACE] [.internal.device.RequestQueueManager] - device queue for 43.A3.5F rescheduled in 500 msec
2020-05-12 11:09:01.038 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 43.A3.5F must wait for 498 msec
2020-05-12 11:09:01.536 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 43.A3.5F is empty!
2020-05-12 11:09:01.537 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 3D.80.E7 must wait for 1127 msec
2020-05-12 11:09:02.665 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 3D.80.E7
2020-05-12 11:09:02.666 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: LoadDimmerButton(1:2:8) OUT:Cmd:0x62|toAddress:3D.80.E7|messageFlags:0x0F=DIRECT:3:3|command1:0x13|command2:0x00|
2020-05-12 11:09:02.666 [TRACE] [nsteon.internal.device.DeviceFeature] - LoadDimmerButton set query status to: QUERY_PENDING
2020-05-12 11:09:02.667 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:3D.80.E7|messageFlags:0x0F=DIRECT:3:3|command1:0x13|command2:0x00|
2020-05-12 11:09:02.667 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 2000 msec, quiettime = 2000
2020-05-12 11:09:02.667 [TRACE] [.internal.device.RequestQueueManager] - device queue for 3D.80.E7 rescheduled in 2000 msec
2020-05-12 11:09:02.667 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 3D.80.E7 must wait for 1998 msec
2020-05-12 11:09:03.534 [TRACE] [nding.insteon.internal.driver.Poller] - entry 40.CB.1D/Tue May 12 11:09:03 PDT 2020 expired at time 1589306943533
2020-05-12 11:09:03.534 [TRACE] [nsteon.internal.device.DeviceFeature] - OnLevel making poll msg for 40.CB.1D using handler NoPollHandler
2020-05-12 11:09:03.534 [TRACE] [nsteon.internal.device.DeviceFeature] - KeyPadButtonGroup making poll msg for 40.CB.1D using handler FlexPollHandler
2020-05-12 11:09:03.535 [TRACE] [nsteon.internal.device.DeviceFeature] - ExtStatusGroup making poll msg for 40.CB.1D using handler FlexPollHandler
2020-05-12 11:09:03.535 [TRACE] [.internal.device.RequestQueueManager] - scheduling request for device 40.CB.1D in -1 msec
2020-05-12 11:09:03.535 [TRACE] [nding.insteon.internal.driver.Poller] - added entry 40.CB.1D/Tue May 12 11:14:03 PDT 2020 originally aimed at time Tue May 12 11:14:03 PDT 2020
2020-05-12 11:09:03.535 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 40.CB.1D
2020-05-12 11:09:03.535 [TRACE] [nding.insteon.internal.driver.Poller] - waiting for 9997 msec until 3D.44.19/Tue May 12 11:09:13 PDT 2020 comes due
2020-05-12 11:09:03.536 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: KeyPadButtonGroup(0:0:0) OUT:Cmd:0x62|toAddress:40.CB.1D|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2020-05-12 11:09:03.536 [TRACE] [nsteon.internal.device.DeviceFeature] - KeyPadButtonGroup set query status to: QUERY_PENDING
2020-05-12 11:09:03.536 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:40.CB.1D|messageFlags:0x0F=DIRECT:3:3|command1:0x19|command2:0x01|
2020-05-12 11:09:03.537 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 1499 msec, quiettime = 500
2020-05-12 11:09:03.537 [TRACE] [.internal.device.RequestQueueManager] - device queue for 40.CB.1D rescheduled in 1499 msec
2020-05-12 11:09:03.537 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 3D.80.E7 must wait for 1128 msec
2020-05-12 11:09:04.666 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 3D.80.E7 for another 3999 usec
2020-05-12 11:09:04.666 [TRACE] [.internal.device.RequestQueueManager] - device queue for 3D.80.E7 rescheduled in 2000 msec
2020-05-12 11:09:04.667 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 40.CB.1D must wait for 367 msec
2020-05-12 11:09:05.035 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 40.CB.1D for another 4500 usec
2020-05-12 11:09:05.035 [TRACE] [.internal.device.RequestQueueManager] - device queue for 40.CB.1D rescheduled in 2000 msec
2020-05-12 11:09:05.036 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 3D.80.E7 must wait for 1630 msec
2020-05-12 11:09:06.666 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 3D.80.E7 for another 1999 usec
2020-05-12 11:09:06.667 [TRACE] [.internal.device.RequestQueueManager] - device queue for 3D.80.E7 rescheduled in 2000 msec
2020-05-12 11:09:06.667 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 40.CB.1D must wait for 368 msec
2020-05-12 11:09:07.036 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 40.CB.1D for another 2499 usec
2020-05-12 11:09:07.037 [TRACE] [.internal.device.RequestQueueManager] - device queue for 40.CB.1D rescheduled in 2000 msec
2020-05-12 11:09:07.037 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 3D.80.E7 must wait for 1629 msec
2020-05-12 11:09:08.667 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 3D.80.E7
2020-05-12 11:09:08.668 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: LoadDimmerButton(1:2:8) OUT:Cmd:0x62|toAddress:3D.80.E7|messageFlags:0x0F=DIRECT:3:3|command1:0x13|command2:0x00|
2020-05-12 11:09:08.668 [TRACE] [nsteon.internal.device.DeviceFeature] - LoadDimmerButton set query status to: QUERY_PENDING
2020-05-12 11:09:08.668 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:3D.80.E7|messageFlags:0x0F=DIRECT:3:3|command1:0x13|command2:0x00|
2020-05-12 11:09:08.669 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 2000 msec, quiettime = 2000
2020-05-12 11:09:08.669 [TRACE] [.internal.device.RequestQueueManager] - device queue for 3D.80.E7 rescheduled in 2000 msec
2020-05-12 11:09:08.669 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 40.CB.1D must wait for 367 msec
2020-05-12 11:09:09.037 [DEBUG] [nsteon.internal.device.InsteonDevice] - still waiting for query reply from 40.CB.1D for another 498 usec
2020-05-12 11:09:09.038 [TRACE] [.internal.device.RequestQueueManager] - device queue for 40.CB.1D rescheduled in 2000 msec
2020-05-12 11:09:09.038 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 3D.80.E7 must wait for 1629 msec
2020-05-12 11:09:10.668 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 3D.80.E7 is empty!
2020-05-12 11:09:10.668 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 40.CB.1D must wait for 369 msec
2020-05-12 11:09:11.039 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 40.CB.1D
2020-05-12 11:09:11.039 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: ExtStatusGroup(0:0:0) OUT:Cmd:0x62|toAddress:40.CB.1D|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x01|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x9A|userData14:0x88|
2020-05-12 11:09:11.040 [TRACE] [nsteon.internal.device.DeviceFeature] - ExtStatusGroup set query status to: QUERY_PENDING
2020-05-12 11:09:11.040 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:40.CB.1D|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x01|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x9A|userData14:0x88|
2020-05-12 11:09:11.040 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 500 msec, quiettime = 500
2020-05-12 11:09:11.041 [TRACE] [.internal.device.RequestQueueManager] - device queue for 40.CB.1D rescheduled in 500 msec
2020-05-12 11:09:11.041 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 40.CB.1D must wait for 498 msec
2020-05-12 11:09:11.540 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 40.CB.1D is empty!
2020-05-12 11:09:11.540 [TRACE] [.internal.device.RequestQueueManager] - waiting for request queues to fill
2020-05-12 11:09:13.533 [TRACE] [nding.insteon.internal.driver.Poller] - entry 3D.44.19/Tue May 12 11:09:13 PDT 2020 expired at time 1589306953533
2020-05-12 11:09:13.534 [TRACE] [nsteon.internal.device.DeviceFeature] - GenericSwitch making poll msg for 3D.44.19 using handler FlexPollHandler
2020-05-12 11:09:13.534 [TRACE] [.internal.device.RequestQueueManager] - scheduling request for device 3D.44.19 in 0 msec
2020-05-12 11:09:13.534 [TRACE] [nding.insteon.internal.driver.Poller] - added entry 3D.44.19/Tue May 12 11:14:13 PDT 2020 originally aimed at time Tue May 12 11:14:13 PDT 2020
2020-05-12 11:09:13.534 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 3D.44.19

I actually set up an entirely new instance of OpenHAB using the Zulu-8 version of java and the latest stable build of OpenHAB. Moved the PLM device over to the new PC, installed the binding, added the same things and items files I had before and it worked fine for a while, and then stopped responding again. So there is no chance the old InsteonPLM binding is running since I never installed it on this new system. When I run the list command I get what you have above, just with version 2.5.4 instead. And it is active.

It’s really strange, everyone else is running this just fine. I don’t know why I’m running into issues! Is anyone else running with Hue, or the Zulu-8 java distribution? There has to be something I’m running differently than everyone else. I would say it might be a bad modem except for the fact that I can delete my bridge definition, restart the system, add the bridge and it all works again.

6

I’m using zulu:

$ java -version
openjdk version "1.8.0_242"
OpenJDK Runtime Environment (Zulu8.44.0.213-CA-linux_aarch32hf) (build 1.8.0_242-b213)
OpenJDK Client VM (Zulu8.44.0.213-CA-linux_aarch32hf) (build 25.242-b213, mixed mode, Evaluation)

For some reason it looks like responses are getting dropped somehow. What happens if you press the button on the device? You should see messages coming in. Also, can you run the command display_local_database and see what the local database returns?

7

When I press the button I get nothing. It’s like the serial port just gives up. When I run that command it dumps the database which makes sense cause it does run successfully for a good while before it stops. I might try deleting all my items files and building from start again. I’m not sure what the hang up could be but something is conflicting. At this point the only binding I have is the Insteon binding. So there shouldn’t be anything conflicting there. I’ll start playing with my items files.

8

So I played around with this more yesterday and I have absolutely no idea what was causing the issue. I did manage to resolve it though.

I have a stable system that I’ve had running for a long time now and I’ve been pretty happy with it and decided I was going to do some upgrades to a test system before deploying. Well I decided that I would upgrade the Insteon Binding on the stable system and that was my downfall. When I upgraded OpenHAB and switched to the new binding that’s when things would work for a minute and then quit.

So I went to the new PC I set up, got OpenHAB up and running, installed the bindings, and just copied the .items and .things files over to the new system. It would still stop responding after a short time.

So I started with a clean slate, installed just the Insteon Binding, created totally new .things files, and then created new .items files and linked the channels. Now everything has been stable.

In short, I have no idea why copying my .items or .things files would cause a problem but apparently it did. I will look through to see if I configured something incorrectly but at the moment it’s stable so I’ll go from there.

Thanks to those who responded.

9

Wow that’s really weird.

10

Think we have all been there!!!