Binding not starting consistently since 6/19 build

MikeD · July 12, 2016, 12:28pm

Ok, I will save that for next time

Kai · July 13, 2016, 8:50pm

Ok, build 407 should finally fix this issue - please test and report back!

mhilbush · July 13, 2016, 9:16pm

Build 407 looks really good on my test system. Twelve restarts in a row and not a single startup issue. Startup also seems quicker, which I think you said might be the case.

I’ll install on my two other systems tomorrow morning.

Nice work!!!

MikeD · July 14, 2016, 8:26am

@Kai

I confirm that build #408 is working well and no issues with starting the bindings.

Thank you very much for your efforts and support!!

Cheers,
Mike

MikeD · July 14, 2016, 9:52am

@Kai

Since updating to build #408 there are a couple of minor issues:

Astro binding - starts OK but seems to hang after that and not update values in the Basic UI. I get the initial values but no update to any values after 60 seconds as expected.

The obvious value that is missing is the Moon Phase which normally was only updated after the first 60 second period.

If I uninstall and then reinstall the binding from the Paper UI, I get refreshed values, but no further updates.

Restarting OH2 also gives refreshed values, but then no further updates.

I have also noticed issues with the System info binding where no values were posted after restarting OH2.

if I then uninstall and then reinstall the binding from the Paper UI, I get a value and this updates every 60 seconds (unlike the Astro values)

Both of the above behaviours are new today following the update to build #408.

Mike

p.s. the debug log from startup can be seen at the following link:

mhilbush · July 14, 2016, 12:02pm

@Kai I’m seeing the same behavior as @MikeD with the astro binding. From what I’m seeing in the logs, the daily job is starting but not the job to update the positional channels.

Changing the interval in the config shows the daily job restarting, but not the positional job.

2016-07-14 07:53:03.693 [INFO ] [ding.astro.handler.AstroThingHandler] - Deleting astro DailyJob for thing ‘astro:sun:local’
2016-07-14 07:53:03.802 [DEBUG] [ding.astro.handler.AstroThingHandler] - AstroThingConfig[thing=astro:sun:local,geolocation=XXXX,XXXX,interval=150,systemTimezone=America/New_York (EST -0400),daylightSavings=true]
2016-07-14 07:53:05.809 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:local
2016-07-14 07:53:05.819 [DEBUG] [g.astro.internal.job.AbstractBaseJob] - Starting astro DailyJob for thing astro:sun:local
2016-07-14 07:53:05.838 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:local
2016-07-14 07:56:27.471 [INFO ] [ding.astro.handler.AstroThingHandler] - Deleting astro DailyJob for thing ‘astro:sun:local’
2016-07-14 07:56:27.524 [DEBUG] [ding.astro.handler.AstroThingHandler] - AstroThingConfig[thing=astro:sun:local,geolocation=XXXX,XXXX,interval=300,systemTimezone=America/New_York (EST -0400),daylightSavings=true]
2016-07-14 07:56:29.532 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:local
2016-07-14 07:56:29.536 [DEBUG] [g.astro.internal.job.AbstractBaseJob] - Starting astro DailyJob for thing astro:sun:local
2016-07-14 07:56:29.556 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:local

mhilbush · July 14, 2016, 12:10pm

If this helps, I enabled debug for org.eclipse.smarthome. This was the result of changing the interval from 300 to 150.

2016-07-14 08:06:50.069 [DEBUG] [nfig.core.status.ConfigStatusService] - There is no config status provider for entity astro:sun:local available.
2016-07-14 08:06:58.589 [INFO ] [ding.astro.handler.AstroThingHandler] - Deleting astro DailyJob for thing ‘astro:sun:local’
2016-07-14 08:06:58.641 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element astro:sun:local in ManagedThingProvider.
2016-07-14 08:06:58.642 [DEBUG] [.smarthome.config.core.Configuration] - Setting value (String) 40.828594,-74.308945 to field ‘geolocation’ in configuration class org.openhab.binding.astro.internal.config.AstroThingConfig
2016-07-14 08:06:58.643 [DEBUG] [.smarthome.config.core.Configuration] - Setting value (Integer) 150 to field ‘interval’ in configuration class org.openhab.binding.astro.internal.config.AstroThingConfig
2016-07-14 08:06:58.650 [DEBUG] [ding.astro.handler.AstroThingHandler] - AstroThingConfig[thing=astro:sun:local,geolocation=XXXX,XXXX,interval=150,systemTimezone=America/New_York (EST -0400),daylightSavings=true]
2016-07-14 08:07:00.654 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:local
2016-07-14 08:07:00.658 [DEBUG] [g.astro.internal.job.AbstractBaseJob] - Starting astro DailyJob for thing astro:sun:local
2016-07-14 08:07:00.681 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:local

Lolodomo · July 14, 2016, 7:31pm

Ok, I tried offline distro 408 and after several restarts I can confirlm that I encounter several problems with things remaining in INITIALIZING state.

First, the Freebox binding is no more working, bridge and things remains in INITIALIZING state.
I got these strange errors:

21:24:03.430 [ERROR] [nding.freebox.handler.FreeboxHandler] -
'org.apache.felix.eventadmin.impl.adapter.LogEventAdapter$1@cc7455' is removed as a LogListener, since it threw an exception.
21:24:32.194 [ERROR] [nding.freebox.handler.FreeboxHandler] -
21:25:02.260 [ERROR] [nding.freebox.handler.FreeboxHandler] -
21:25:32.162 [ERROR] [nding.freebox.handler.FreeboxHandler] -
21:26:02.598 [ERROR] [nding.freebox.handler.FreeboxHandler] -
21:26:32.138 [ERROR] [nding.freebox.handler.FreeboxHandler] -

Often but not always, my hue lights remains in INITIAZING state, the bridge seems to be always OK. Nothing special in the logs.

Sometimes, not often, the astro thing remains in INITIALIZING state. Nothing special in the logs.

The RFXCOM correctly initialized but I systematically got these errors (probably one for each of my things)

21:23:17.774 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured during notification of thing 'rfxcom:temperaturehumidity:rfx:Chambre' about bridge initialization at 'org.openhab.binding.rfxcom.handler.RFXComHandler@18658a1': null
java.lang.NullPointerException
        at org.openhab.binding.rfxcom.handler.RFXComHandler.initializeBridge(RFXComHandler.java:125)[199:org.openhab.binding.rfxcom:2.0.0.201607140102]
        at org.openhab.binding.rfxcom.handler.RFXComHandler.bridgeHandlerInitialized(RFXComHandler.java:114)[199:org.openhab.binding.rfxcom:2.0.0.201607140102]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9.run(ThingManager.java:801)[102:org.eclipse.smarthome.core.thing:0.9.0.201607131940]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0]
        at java.lang.Thread.run(Thread.java:744)[:1.8.0]
21:23:17.777 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured during notification of thing 'rfxcom:temperaturehumidity:rfx:Veranda' about bridge initialization at 'org.openhab.binding.rfxcom.handler.RFXComHandler@1ac71a': null
java.lang.NullPointerException
        at org.openhab.binding.rfxcom.handler.RFXComHandler.initializeBridge(RFXComHandler.java:125)[199:org.openhab.binding.rfxcom:2.0.0.201607140102]
        at org.openhab.binding.rfxcom.handler.RFXComHandler.bridgeHandlerInitialized(RFXComHandler.java:114)[199:org.openhab.binding.rfxcom:2.0.0.201607140102]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9.run(ThingManager.java:801)[102:org.eclipse.smarthome.core.thing:0.9.0.201607131940]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0]
        at java.lang.Thread.run(Thread.java:744)[:1.8.0]
21:23:17.776 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured during notification of thing 'rfxcom:temperaturehumidity:rfx:Bureau' about bridge initialization at 'org.openhab.binding.rfxcom.handler.RFXComHandler@1083d86': null
java.lang.NullPointerException
        at org.openhab.binding.rfxcom.handler.RFXComHandler.initializeBridge(RFXComHandler.java:125)[199:org.openhab.binding.rfxcom:2.0.0.201607140102]
        at org.openhab.binding.rfxcom.handler.RFXComHandler.bridgeHandlerInitialized(RFXComHandler.java:114)[199:org.openhab.binding.rfxcom:2.0.0.201607140102]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9.run(ThingManager.java:801)[102:org.eclipse.smarthome.core.thing:0.9.0.201607131940]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0]
        at java.lang.Thread.run(Thread.java:744)[:1.8.0]

Kai · July 15, 2016, 5:51am

I doubt that this has anything to do with the system startup issues that I fixed.
I would rather assume that his is a regression introduced by this PR. Let’s track this here.

Clearly a bug in that binding that needs to be fixed there.

Sounds if it throws exceptions, this needs to be fixed in the binding as well.

Lolodomo · July 15, 2016, 9:17am

Of course I will analyze what’s wrong with the freebox binding but the binding is working very well in beta 3 ! So something has changed in the framework from beta 3 to now that broke the binding !
I will check what happens with discovered things too. My problem is with things declared in config files.

For the astro and hue bindings using config files, am I am alone to encounter the problem?

Lolodomo · July 15, 2016, 9:24am

In fact, I get a problem with almost all 2.0 bindings I am using. Only NTP was initiated well at every start I thing.

Lolodomo · July 15, 2016, 11:40am

Ok here is my analysis for the Freebox binding.

If I start OH with a new binding jar, the initialization process always succeeded.
In all other cases (normal startup), it always failed. Here are logs that could help, I hope:

2016-07-15 13:29:02.671 [DEBUG] [org.openhab.binding.freebox         ] - BundleEvent STARTING - org.openhab.binding.freebox
2016-07-15 13:29:02.778 [DEBUG] [org.openhab.binding.freebox         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=339, service.bundleid=211, service.scope=singleton} - org.openhab.binding.freebox
2016-07-15 13:29:02.797 [DEBUG] [org.openhab.binding.freebox         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=freebox:server, thing.id=freebox:server:fb, service.id=340, service.bundleid=211, service.scope=singleton} - org.openhab.binding.freebox
2016-07-15 13:29:02.825 [DEBUG] [org.openhab.binding.freebox         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=freebox:phone, thing.id=freebox:phone:fb:Phone, service.id=341, service.bundleid=211, service.scope=singleton} - org.openhab.binding.freebox
2016-07-15 13:29:02.837 [DEBUG] [org.openhab.binding.freebox         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=freebox:net_device, thing.id=freebox:net_device:fb:00_1B_D3_D2_65_02, service.id=342, service.bundleid=211, service.scope=singleton} - org.openhab.binding.freebox
2016-07-15 13:29:02.840 [DEBUG] [org.openhab.binding.freebox         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.freebox.internal.FreeboxHandlerFactory, component.id=192, service.id=338, service.bundleid=211, service.scope=bundle} - org.openhab.binding.freebox
2016-07-15 13:29:02.911 [DEBUG] [org.openhab.binding.freebox         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.transport.mdns.discovery.MDNSDiscoveryParticipant}={component.name=org.openhab.binding.freebox.discovery.freeboxServer, component.id=193, service.id=343, service.bundleid=211, service.scope=bundle} - org.openhab.binding.freebox
2016-07-15 13:29:02.927 [DEBUG] [org.openhab.binding.freebox         ] - BundleEvent STARTED - org.openhab.binding.freebox
2016-07-15 13:29:02.941 [DEBUG] [nding.freebox.handler.FreeboxHandler] - initializing Freebox Server handler.
2016-07-15 13:29:02.961 [DEBUG] [.freebox.handler.FreeboxThingHandler] - initialize
2016-07-15 13:29:02.967 [DEBUG] [.freebox.handler.FreeboxThingHandler] - initializeThing thingHandler is null false bridgeStatus INITIALIZING
2016-07-15 13:29:02.976 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 1
2016-07-15 13:29:02.978 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 11
2016-07-15 13:29:03.018 [DEBUG] [.freebox.handler.FreeboxThingHandler] - initialize
2016-07-15 13:29:03.019 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 12
2016-07-15 13:29:03.019 [DEBUG] [.freebox.handler.FreeboxThingHandler] - initializeThing thingHandler is null false bridgeStatus INITIALIZING
2016-07-15 13:29:03.023 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 1
2016-07-15 13:29:03.024 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 11
2016-07-15 13:29:03.026 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 12
2016-07-15 13:29:03.055 [ERROR] [org.openhab.binding.freebox         ] - FrameworkEvent ERROR - org.openhab.binding.freebox
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.freebox [212]
  Another singleton bundle selected: osgi.identity; osgi.identity="org.openhab.binding.freebox"; type="osgi.bundle"; version:Version="2.0.0.201607151122"; singleton:="true"

        at org.eclipse.osgi.container.Module.start(Module.java:434)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1582)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1562)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1533)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1476)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
2016-07-15 13:29:03.799 [DEBUG] [.freebox.handler.FreeboxThingHandler] - dispose
2016-07-15 13:29:03.801 [DEBUG] [.freebox.handler.FreeboxThingHandler] - initialize
2016-07-15 13:29:03.802 [DEBUG] [.freebox.handler.FreeboxThingHandler] - initializeThing thingHandler is null false bridgeStatus INITIALIZING
2016-07-15 13:29:03.803 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 1
2016-07-15 13:29:03.805 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 11
2016-07-15 13:29:03.809 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 12
2016-07-15 13:29:03.837 [DEBUG] [.freebox.handler.FreeboxThingHandler] - dispose
2016-07-15 13:29:03.839 [DEBUG] [.freebox.handler.FreeboxThingHandler] - initialize
2016-07-15 13:29:03.842 [DEBUG] [.freebox.handler.FreeboxThingHandler] - initializeThing thingHandler is null false bridgeStatus INITIALIZING
2016-07-15 13:29:03.844 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 1
2016-07-15 13:29:03.846 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 11
2016-07-15 13:29:03.850 [DEBUG] [.freebox.handler.FreeboxThingHandler] - trace 12
2016-07-15 13:29:06.449 [DEBUG] [nding.freebox.handler.FreeboxHandler] - polling_interval: 30
2016-07-15 13:29:07.451 [DEBUG] [nding.freebox.handler.FreeboxHandler] - Polling server state...
2016-07-15 13:29:09.126 [ERROR] [nding.freebox.handler.FreeboxHandler] - Error (Exception): null

First, there is this strange framework error. What does it mean ?
Then, regarding my 2 things, we can see that initialize is called when bridge status is still INITIALIZING. We can even see a strange cycle initialize => dispose => initialize. Normally it should lead to state OFFLINE, I don’t know why my updateStatus is not considered. Please note that bridgeStatusChanged is never called.
Finally, my polling job systematically throws an exception without any message.

Lolodomo · July 15, 2016, 11:47am

So to be clear, the problem is that bridgeStatusChanged is not called fro my things when the brige is finally ONLINE.
Plus even if the bridge is finally always ONLINE, the polling job throws an exception I cannot explain. When the initialization process is OK, the polling job is working fine.
Maybe all this is simply a consequence of the framework error I can see ?

Lolodomo · July 15, 2016, 12:01pm

The difference I can see with the same binding version in beta 3 is that bridgeStatusChanged is called (while not in current snapshot).

PS: I realize that we don’t have the event logs in the console with last snapshot.

chris · July 15, 2016, 12:09pm

Do you set the thing status to ONLINE or OFFLINE in the initialize method? If you don’t, then you won’t get the bridge status change called (if I remember correctly). The fact that it’s stuck in INITIALIZING kind of indicates that you might not?

Lolodomo · July 15, 2016, 12:17pm

I always set the status either to ONLINE or OFFLINE in initialize of my things.

Lolodomo · July 15, 2016, 12:26pm

For the RFXCOM binding, the config object is probably null when initializeBridge is called for the thing, leading to the NPE.
The variable is set in initialize, maybe too early ?
By the way, I will have done things in a different order in initializeBridge, that is first checking the bridge status. And config variable could be set directly in this method rather than in initialize ?
Or maybe we could just add a null check to avoid this NPE.
Is there a reason why the config could be null when initialize is called ?

Can someone have a look to RFXComHandler (initialize, bridgeHandlerInitialized, initializeBridge) ?

Lolodomo · July 15, 2016, 12:40pm

Note that RFXCOM binding does not implement method bridgeStatusChanged but implement bridgeHandlerInitialized.

Lolodomo · July 15, 2016, 12:42pm

For the hue binding, the initialization process is very different and very difficult to analyze. But my lights remain in INITIALIZING state.

Lolodomo · July 15, 2016, 1:00pm

@chris: in fact, I set the status to OFFLINE but it seems to not be considered. Maybe that is why later bridgeStatusChanged is not called ?
The only difference I can see is that I call updateStatus with OFFLINE and a detailed status. Should I remove the detailed status ?