Losing Insteon connectivity on reboot

Setup, Configuration and Use Beginners
1

I’m running OpenHAB 3.0.1 on Windows 7 Pro. Following a reboot (which the machine does nightly at 5 a.m.), often the Insteon binding is NULL and none of the Insteon commands reach their devices.

Here’s the log:

openhab> log:display
05:02:11.784 [WARN ] [org.openhab.core.net.NetUtil         ] - Found multiple local interfaces - ignoring 192.168.1.198
05:02:35.806 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
05:02:40.672 [INFO ] [org.openhab.ui.internal.UIService    ] - Started UI on port 8080
05:02:43.947 [INFO ] [hab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
05:02:45.222 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.222 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.354 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.356 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.358 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.362 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.242 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.416 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.222 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:02:45.484 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
05:02:45.783 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from UNINITIALIZED to INITIALIZING
05:02:45.787 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from INITIALIZING to ONLINE
05:02:52.416 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:network:330aacac71' changed from UNKNOWN to ONLINE
05:34:00.027 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:astroDawn#event triggered START
05:34:00.037 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:morningNight#event triggered END
05:34:00.037 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'FrontPorchIconDimmer_Switch' received command OFF
05:34:00.057 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'FrontPorchIconDimmer_Switch' predicted to become ON
06:06:00.050 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:astroDawn#event triggered END
06:06:00.050 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:nauticDawn#event triggered START
06:06:00.050 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'FrontPorchIconDimmer_Switch' received command OFF
06:06:00.060 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'FrontPorchIconDimmer_Switch' predicted to become ON
06:37:00.073 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:civilDawn#event triggered START
06:37:00.073 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:nauticDawn#event triggered END
07:03:00.095 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:civilDawn#event triggered END
07:03:00.095 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:rise#event triggered START
07:05:00.095 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:rise#event triggered END
07:05:00.095 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:daylight#event triggered START
08:30:01.050 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'PetersOfficePrinterSwitch_Switch' received command ON
08:30:01.060 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'PetersOfficePrinterSwitch_Switch' predicted to become OFF

As you can see at the end of the log, it’s merrily going along “predicting” that it turned things on or off . . . but it didn’t. Here’s what the Things status looks like:

image
image747×669 41.6 KB

If I manually Pause and Un-Pause the Insteon Network Thing, it restores operation (turning all devices to ONLINE) until the next reboot.

If it helps, here’s how the Insteon binding responds when its in this state:

openhab> insteon display_channels
openhab> insteon display_monitored
Not mointoring any devices.
openhab> insteon display_devices
openhab> insteon display_local_database
local database contains 10 entries
07.DA.EB: plm controls groups (2,3,4,5,6,7,8) and responds to groups (1,2,3,4,5,6,7,8)
0D.04.03: plm controls groups () and responds to groups (1)
17.5B.0B: plm controls groups () and responds to groups (1)
17.5E.E7: plm controls groups () and responds to groups (1)
22.CC.B4: plm controls groups (1) and responds to groups ()
27.CC.B4: plm controls groups (1) and responds to groups (1)
39.54.C7: plm (COM3)
3D.25.2A: plm controls groups (1) and responds to groups (1)
3D.EB.B8: plm controls groups (1) and responds to groups (1)
58.06.08: plm controls groups (1) and responds to groups (1,2,3,4,5,6,7,8)

Any suggestions?

2

Looks like you get OH in some sort of weird state by forcing a reboot on Windows. The code that is failing is:

    private InsteonNetworkHandler getInsteonNetworkHandler() {
        Bridge bridge = getBridge();
        if (bridge == null) {
            throw new IllegalArgumentException("insteon network bridge is null");
        }
        InsteonNetworkHandler handler = (InsteonNetworkHandler) bridge.getHandler();
        if (handler == null) {
            throw new IllegalArgumentException("insteon network handler is null");
        }
        return handler;
    }

bridge.getHandler() is returning null, which shouldn’t be possible, according to the documentation:

    /**
     * Gets the bridge handler.
     *
     * @return the handler which can be null for a Thing that is not initialized. Note that a Bridge is
     *         guaranteed to be initialized before its children. It is therefore safe to call getBridge().getHandler()
     *         for a subordinate Thing
     */
    @Override
    @Nullable
    BridgeHandler getHandler();

How do you have your Insteon things defined? Maybe they are not a child of the bridge?

3

Here’s how my PLM is configured:

UID: insteon:network:home
label: Insteon Network
thingTypeUID: insteon:network
configuration:
  port: /dev/ttyUSB0

And one of the devices

UID: insteon:device:home:23A073
label: Family Room
thingTypeUID: insteon:device
configuration:
  productKey: F00.00.11
  address: 23.A0.73
bridgeUID: insteon:network:home
4

Rob:

How do I get the listing your showing the UIDs and configuration? Is there a console command that grabs that? Sorry for being a noob.

The problem is continuing. After about a week, it reboots the Insteon connection successfully roughly half the time. The other half the time, it looks like my example.

Thanks!

5

It’s the code tab for the thing:

image
image1902×390 51.6 KB

6

LOL! It was right there in the user interface. Who knew?

Here’s the Insteon config (after it was re-initialized):

UID: insteon:network:330aacac71
label: Insteon Network 2413U PLM
thingTypeUID: insteon:network
configuration:
  port: COM3
  devicePollIntervalSeconds: 300
location: Downstairs

and here is one of the dimmers:

UID: insteon:device:330aacac71:175EE7
label: Front Porch Icon Dimmer
thingTypeUID: insteon:device
configuration:
  productKey: F00.00.04
  address: 17.5E.E7
bridgeUID: insteon:network:330aacac71

The next time it doesn’t initialize (which might be tomorrow morning), I’ll grab the same two again and we can compare . . . if that would help.

7

Can you try and run 3.1.0.M3 and see if the issue goes away?

8

I’d be happy to, but apparently the script for updating to a new version isn’t working under Windows 7 Pro. Following the directions at Windows | openHAB, I couldn’t get the upgrade to work.

After I convinced Windows to attempt to execute the script (by using set-executionpolicy to allow unsigned scripts), PowerShell said that the script requires version 5.0 of PowerShell, and Windows 7 has version 2.0 of PowerShell.

I can’t seem to find directions for manually upgrading to a new version. Would it be something like . . . backup up the conf and userdata folders, wipe out the OpenHAB folder, do a full installation, restart the service, and then restore the conf and userdata folders? Or is there an easier way (like replacing one file with another and rebooting)?

Thanks.

9

It looks like you can upgrade powershell: Download and install Windows PowerShell 5.1 - Skype for Business Online | Microsoft Docs

10

At last, I think I’ve managed to upgrade. Appreciate the suggestion to update PowerShell.

[It took a couple of hours. The Windows PowerShell 5.1 installation relies on .NET framework 4.5, which requires a Microsoft update. But Microsoft removed the files for 4.5 from their server so their own installer craps out. I finally found a version of .NET 4.5.1 that was meant for “offline installation” and got it upgraded. After all that, I had to set execution policy in the new PowerShell to allow the OpenHAB update scripts to run properly, since they are not signed. If I wasn’t a programmer, the likelihood of any of this happening would be close to zero. I’d suggest someone figure out a more user-friendly upgrade path for the future.]

I’m now running OpenHAB 3.1.0.M3. I will let you know if the Insteon binding still has issues after a morning reboot. Thanks!

11

Windows 7 is a dead platform, Microsoft dropped support Jan 14, 2020.

12

Yeah, that too.

13

After two days of restarts, I can report the symptoms with 3.1.0.M3 are almost the same, but slightly different. What’s the same is that some devices still come up as “Initializing”. What’s different is that a few devices show “Online” now, and it seems to vary which devices it is (at least it was different on the last two days). The first day, “Peter’s Office Printer Switch” worked properly. The second day, it didn’t.

Here’s the screenshot from Day 2:

image
image742×701 41.9 KB

And here is the console data (which looks more interesting):

openhab> insteon display_channels
insteon:device:330aacac71:0D0403:fastOnOff feature = fastonoff parameters = {}
insteon:device:330aacac71:175B0B:switch feature = switch parameters = {}
insteon:device:330aacac71:22CCB4:dimmer feature = dimmer parameters = {}
insteon:device:330aacac71:22CCB4:fastOnOff feature = fastonoff parameters = {}
insteon:device:330aacac71:3954C7:dimmer feature = dimmer parameters = {}
insteon:device:330aacac71:3954C7:fastOnOff feature = fastonoff parameters = {}
insteon:device:330aacac71:580608:fastOnOffButtonD feature = fastonoffbuttond parameters = {}
insteon:device:330aacac71:580608:keypadButtonD feature = keypadbuttond parameters = {}
insteon:device:330aacac71:580608:loadDimmer feature = loaddimmer parameters = {}
insteon:device:330aacac71:580608:manualChangeButtonD feature = manualchangebuttond parameters = {}
openhab> insteon display_monitored
Not mointoring any devices.
openhab> insteon display_devices
insteon:device:330aacac71:0D0403 address = 0D.04.03 productKey = 0x000037 channels = dimmer, fastOnOff, lastHeardFrom, manualChange
insteon:device:330aacac71:175B0B address = 17.5B.0B productKey = F00.00.04 channels = lastHeardFrom, switch
insteon:device:330aacac71:22CCB4 address = 22.CC.B4 productKey = F00.00.01 channels = beep, dimmer, fastOnOff, lastHeardFrom, ledBrightness, ledOnOff, manualChange, onLevel, rampRate
insteon:device:330aacac71:3954C7 address = 39.54.C7 productKey = F00.00.01 channels = beep, dimmer, fastOnOff, lastHeardFrom, ledBrightness, ledOnOff, manualChange, onLevel, rampRate
insteon:device:330aacac71:580608 address = 58.06.08 productKey = F00.00.16 channels = beep, fastOnOff, fastOnOffButtonB, fastOnOffButtonC, fastOnOffButtonD, fastOnOffButtonE, fastOnOffButtonF, fastOnOffButtonG, fastOnOffButtonH, keypadButtonB, keypadButtonC, keypadButtonD, keypadButtonE, keypadButtonF, keypadButtonG, keypadButtonH, lastHeardFrom, ledBrightness, ledOnOff, loadDimmer, manualChange, manualChangeButtonB, manualChangeButtonC, manualChangeButtonD, manualChangeButtonE, manualChangeButtonF, manualChangeButtonG, manualChangeButtonH, onLevel, rampDimmer, rampRate
openhab> insteon display_local_database
local database contains 10 entries
07.DA.EB: plm controls groups (2,3,4,5,6,7,8) and responds to groups (1,2,3,4,5,6,7,8)
0D.04.03: plm controls groups () and responds to groups (1)
17.5B.0B: plm controls groups () and responds to groups (1)
17.5E.E7: plm controls groups () and responds to groups (1)
22.CC.B4: plm controls groups (1) and responds to groups ()
27.CC.B4: plm controls groups (1) and responds to groups (1)
39.54.C7: plm (COM3)
3D.25.2A: plm controls groups (1) and responds to groups (1)
3D.EB.B8: plm controls groups (1) and responds to groups (1)
58.06.08: plm controls groups (1) and responds to groups (1,2,3,4,5,6,7,8)
openhab>

I can now install new versions. Let me know if you’d like me to do anything…

14

Are you shutting down openHAB before rebooting Windows 7?

@Kai, any ideas on what might cause things to start initializing before the bridge?

15

I’m just using running the standard shutdown through a scheduled task. I’m guessing it stops all the services.

Also, here is the logfile which I failed to include in the last message. It looks like there may be some clues in here:


openhab> log:display
05:02:35.116 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Time zone set to 'America/New_York'.
05:02:35.276 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Location set to '34.0492288,-84.1580544'.
05:02:35.278 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
05:02:35.279 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'US'.
05:02:51.402 [WARN ] [org.openhab.core.net.NetUtil         ] - Found multiple local interfaces - ignoring 192.168.1.198
05:03:18.479 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
05:03:26.116 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
05:03:26.810 [INFO ] [org.openhab.ui.internal.UIService    ] - Started UI on port 8080
05:03:27.538 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from UNINITIALIZED to INITIALIZING
05:03:27.578 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from INITIALIZING to ONLINE
05:03:28.302 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:580608' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
05:03:28.312 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:network:330aacac71' changed from UNINITIALIZED to INITIALIZING
05:03:28.312 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:network:330aacac71' changed from INITIALIZING to UNKNOWN
05:03:28.332 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:07DAEB' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_CONFIGURATION_PENDING)
05:03:28.332 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:27CCB4' changed from UNINITIALIZED to INITIALIZING
05:03:28.372 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:175EE7' changed from UNINITIALIZED to INITIALIZING
05:03:28.382 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:3DEBB8' changed from UNINITIALIZED to INITIALIZING
05:03:28.382 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:3D252A' changed from UNINITIALIZED to INITIALIZING
05:03:28.392 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:22CCB4' changed from UNINITIALIZED to INITIALIZING
05:03:28.402 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:175B0B' changed from UNINITIALIZED to INITIALIZING
05:03:28.412 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:0D0403' changed from UNINITIALIZED to INITIALIZING
05:03:28.422 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:3954C7' changed from UNINITIALIZED to INITIALIZING
05:03:28.476 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:580608' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
05:03:28.726 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:03:28.726 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:03:28.726 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:03:28.726 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.IllegalArgumentException: insteon binding is null
        at org.openhab.binding.insteon.internal.handler.InsteonNetworkHandler.getInsteonBinding(InsteonNetworkHandler.java:201) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.getInsteonBinding(InsteonDeviceHandler.java:524) ~[?:?]
        at org.openhab.binding.insteon.internal.handler.InsteonDeviceHandler.lambda$0(InsteonDeviceHandler.java:194) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
05:03:29.286 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:175B0B' changed from INITIALIZING to ONLINE
05:03:29.375 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:0D0403' changed from INITIALIZING to ONLINE
05:03:29.388 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:3954C7' changed from INITIALIZING to ONLINE
05:03:29.388 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:580608' changed from INITIALIZING to ONLINE
05:03:29.388 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:device:330aacac71:22CCB4' changed from INITIALIZING to ONLINE
05:03:29.748 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'FrontPorchIconDimmer_Switch' changed from NULL to ON
05:03:29.898 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MainHallIcon_Switch' changed from NULL to OFF
05:03:29.988 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'DownstairsTVRoomLights_FastOnOff' changed from NULL to OFF
05:03:30.138 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'KitchenKeypadLinc2334222_ManualChangeButtonD' changed from NULL to 1.0
05:03:30.298 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'KitchenKeypadLinc2334222_KeypadButtonD' changed from NULL to OFF
05:03:30.408 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'InsteonDevice3954C7unk_FastOnOff' changed from NULL to ON
05:03:30.488 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PetersOfficePrinterSwitch_Switch' changed from NULL to OFF
05:03:30.588 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'KitchenKeypadLinc2334222_LoadDimmer' changed from NULL to 0
05:03:30.708 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'InsteonDevice22CCB4unk_FastOnOff' changed from NULL to OFF
05:03:30.898 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'KitchenKeypadLinc2334222_FastOnOffButtonD' changed from NULL to OFF
05:03:32.539 [INFO ] [hab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
05:03:36.769 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'insteon:network:330aacac71' changed from UNKNOWN to ONLINE
05:20:00.020 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:morningNight#event triggered END
05:20:00.020 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:astroDawn#event triggered START
05:20:00.030 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'FrontPorchIconDimmer_Switch' received command OFF
05:20:00.050 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'FrontPorchIconDimmer_Switch' predicted to become ON
05:53:00.031 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:nauticDawn#event triggered START
05:53:00.051 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:astroDawn#event triggered END
05:53:00.061 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'FrontPorchIconDimmer_Switch' received command OFF
05:53:00.061 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'FrontPorchIconDimmer_Switch' predicted to become ON
06:25:00.046 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:civilDawn#event triggered START
06:25:00.046 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:nauticDawn#event triggered END
06:51:00.054 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:civilDawn#event triggered END
06:51:00.054 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:rise#event triggered START
06:54:00.054 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:daylight#event triggered START
06:54:00.054 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - astro:sun:local:rise#event triggered END
08:30:00.598 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'PetersOfficePrinterSwitch_Switch' received command ON
08:30:00.608 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'PetersOfficePrinterSwitch_Switch' predicted to become OFF
16

Here are the events associated with the binding initialization:

05:03:28.302 - Thing 'insteon:device:330aacac71:580608' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
05:03:28.312 - Thing 'insteon:network:330aacac71' changed from UNINITIALIZED to INITIALIZING
05:03:28.312 - Thing 'insteon:network:330aacac71' changed from INITIALIZING to UNKNOWN
05:03:28.332 - Thing 'insteon:device:330aacac71:07DAEB' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_CONFIGURATION_PENDING)
05:03:28.332 - Thing 'insteon:device:330aacac71:27CCB4' changed from UNINITIALIZED to INITIALIZING
05:03:28.372 - Thing 'insteon:device:330aacac71:175EE7' changed from UNINITIALIZED to INITIALIZING
05:03:28.382 - Thing 'insteon:device:330aacac71:3DEBB8' changed from UNINITIALIZED to INITIALIZING
05:03:28.382 - Thing 'insteon:device:330aacac71:3D252A' changed from UNINITIALIZED to INITIALIZING
05:03:28.392 - Thing 'insteon:device:330aacac71:22CCB4' changed from UNINITIALIZED to INITIALIZING
05:03:28.402 - Thing 'insteon:device:330aacac71:175B0B' changed from UNINITIALIZED to INITIALIZING
05:03:28.412 - Thing 'insteon:device:330aacac71:0D0403' changed from UNINITIALIZED to INITIALIZING
05:03:28.422 - Thing 'insteon:device:330aacac71:3954C7' changed from UNINITIALIZED to INITIALIZING
05:03:28.476 - Thing 'insteon:device:330aacac71:580608' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
05:03:29.286 - Thing 'insteon:device:330aacac71:175B0B' changed from INITIALIZING to ONLINE
05:03:29.375 - Thing 'insteon:device:330aacac71:0D0403' changed from INITIALIZING to ONLINE
05:03:29.388 - Thing 'insteon:device:330aacac71:3954C7' changed from INITIALIZING to ONLINE
05:03:29.388 - Thing 'insteon:device:330aacac71:580608' changed from INITIALIZING to ONLINE
05:03:29.388 - Thing 'insteon:device:330aacac71:22CCB4' changed from INITIALIZING to ONLINE
05:03:36.769 - Thing 'insteon:network:330aacac71' changed from UNKNOWN to ONLINE

@Kai , it appears that some of the things are trying to initialize when the status of the bridge is UNKNOWN. Here’s the start of the initialize() for the bridge:

    @Override
    public void initialize() {
        logger.debug("Starting Insteon bridge");
        config = getConfigAs(InsteonNetworkConfiguration.class);
        updateStatus(ThingStatus.UNKNOWN);

        scheduler.execute(() -> {
17

This is fully correct behavior. As soon as the initialize() method returns, the Thing is considered initialized, so the child handlers get initialized as well.

See also Things | openHAB

UNKNOWN: The handler is fully initialized

21

@ranielsen Let me know when you have an update for me install to try addressing the issue. Happy to test.

22

@contra, this should be fixed in the latest 3.1.0-SNAPSHOT build. You can upgrade to the snapshot build by using 3.1.0-SNAPSHOT as the version with the update script.

If you want to wait, it will also be in the next M release

23

I installed 3.1.0-SNAPSHOT this morning and it seems to be working on reboot. (Yay!) I’ll update after more time has passed. Thank you.

1 Like