You should stop testing, I am already working on a fix!
Haha, I have stopped, but I was hoping I might see a log message that might give a clue to the problem.
Cheers,
Mike
Ok, let me tell you the most important thing to do when debugging problems in ESH: Type this in the console:
log:set DEBUG org.eclipse.smarthome
The logs will be so much more helpful afterwards 
Ok, I will save that for next time 
Ok, build 407 should finally fix this issue - please test and report back!
1 Like
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!!!
1 Like
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
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:
@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
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
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]
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.
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?
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.
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.
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 ?
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.
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?
I always set the status either to ONLINE or OFFLINE in initialize of my things.
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) ?