Error at Systemstart: "An error occurred while calling method 'ThingHandler.initialize()"

fibu-freak · August 25, 2019, 9:31am

SetUp: Raspberry Pi 3 Model B Rev 1.2, OH 2.5.0.M2,Raspbian GNU/Linux 9 (stretch), Java (Zulu8.40.0.178-CA-linux_aarch32hf) (build 1.8.0_222-b178)

When starting or restarting openHAB I find the below eror-messages in my Log (frontail)

------------------------------------------------- AVM - Fritz - Error-Doc---------------------------------------------------------------------------------------------------------------------------------------------------------
2019-08-13 23:04:49.960 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.avmfritz.internal.handler.BoxHandler@18debca': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-08-13 23:04:49.972 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'avmfritz:fritzbox:Fritz-Box-7490': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 29888  2019-08-21 00:08:38.391 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.avmfritz.internal.handler.BoxHandler@6e97bc': null
 29889  java.lang.NullPointerException: null
 29890          at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
 29891          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
 29892          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
 29893          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
 29894          at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
 29895          at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
 29896          at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
 29897          at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
 29898          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
 29899          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
 29900          at java.lang.Thread.run(Thread.java:748) [?:?]
 29901  2019-08-21 00:08:38.418 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'avmfritz:fritzbox:Fritz-Box-7490': null
 29902  java.lang.NullPointerException: null
 29903          at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
 29904          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
 29905          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
 29906          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
 29907          at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
 29908          at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
 29909          at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
 29910          at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
 29911          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
 29912          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
 29913          at java.lang.Thread.run(Thread.java:748) [?:?]
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2019-08-24 23:22:18.111 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing2
2019-08-24 23:22:18.241 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing3
2019-08-24 23:22:26.157 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.avmfritz.internal.handler.BoxHandler@a1c4b': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-08-24 23:22:26.192 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'avmfritz:fritzbox:Fritz-Box-7490': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-08-24 23:22:42.661 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'sonos:PLAY1:RINCON_949F3E157B8401400' to inbox.
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2019-08-25 01:33:53.081 [INFO ] [smarthome.model.script.startup-rules] - Timer wird initialisiert 
2019-08-25 01:34:10.388 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.avmfritz.internal.handler.BoxHandler@1f05b9a': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-08-25 01:34:10.427 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'avmfritz:fritzbox:Fritz-Box-7490': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-08-25 01:34:11.163 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local

When restarting the bundle in the Karaf-Console everthing’s ok then.

But I never had such an error up to OH 2.5.0.M1. Does anyone know, how to solve ?

Cheer,
Peter

cweitkamp · August 29, 2019, 3:47pm

Hi Peter,

I performed a restart today - my first one after update to OH 2.5.M2 - I can see some similar issues in my live environment. I will investigate on it:

2019-08-29 17:44:16.582 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.avmfritz.internal.handler.BoxHandler@8a20e6': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

But I assume it is not related to the avmfritz binding because I have similar errors for other bindings too:

2019-08-29 17:44:36.092 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.chromecast.internal.handler.ChromecastHandler@97aa01': null
java.lang.NullPointerException: null
	at org.openhab.binding.chromecast.internal.handler.ChromecastHandler.initialize(ChromecastHandler.java:103) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor83.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

fibu-freak · August 29, 2019, 7:57pm

Hi Christoph,
thx for reply. At the moment I only can repeat what I said above. I don’t using Chromecast.

But I will try to investigate in older Log-Files, if I can figure out other parallel, came up with the AVM-Problem. I’ll keep you informed. Hope you can find the reason.

Cheers,
Peter

fibu-freak · October 1, 2019, 10:24pm

Hi Christoph,
meanwhile I’m on OH 2.5 M3 but the Error still occurs

019-10-01 23:37:11.823 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.avmfritz.internal.handler.BoxHandler@ae7895': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M3]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-10-01 23:37:11.867 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'avmfritz:fritzbox:Fritz-Box-7490': null
java.lang.NullPointerException: null
	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.initialize(AVMFritzBaseBridgeHandler.java:140) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M3]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

In this case a Bundle-Restart helps as a first workaround.

But even more, after a while (some hours, a day or two) the binding loses connection now. In this case no Bundle-Restart helps, but only a restart of openHAB.

cweitkamp · October 3, 2019, 9:11am

Hi Peter,

I am sorry. Did not find the time to investigate init yet. Currently I have the slight feeling that it is not a binding issue but more or less a timing issue when initializing bundles. The line number referenced in your logs leads to a method the to access the configuration of a thing - in both cases avmfritz and chromecast. This method should never return null.

fibu-freak · October 3, 2019, 11:35am

Hi Christoph,
first of all, thx for reply. Is there a way for me to change anything in my setup, or is something wrong with my setup ?
As written, if the error occurs on startup I can restart the bundle and then the binding seems to be loaded and runs. So this is OK for me at the moment as temporary workaround.
But now after a while the binding stops working, and no restart of the bundle helps, only restart of OH.
So if I don’t see this immediately, I’ m sitting in cold rooms
Do you have any idea what cause this problem ?

fuslwusl · February 9, 2020, 7:07am

I had simmilar issues and increased the Threadpool sizes - this fixes my problems:

HolgerL · February 9, 2020, 8:09am

Well I see similar issue on OH start with the AVM-Fritz binding. On 30…50% of the starts, the binding does not get up propperly and creates errors. After a restart normally everything works again.
I run Openhabian 2.5 pn a Raspi3, but this behavior was already there with the older version.

cweitkamp · May 18, 2020, 7:49am

I have some news on this topic. The latest release OH 2.5.5 contains some refactoring of the avmfritz binding. Few test users reported that the exception during start process might be solved because they did not see it anymore. I invited you to update and do some additional testing.

WeRo · January 20, 2023, 5:50pm

Hi Christoph,

I am facing a similar problem after the upgrade from 2.5 to 3.4.
May you could take a look at my topic:

WeRo · February 3, 2023, 9:18pm

Problem is solved: I deleted all things and afterwards new things have shown up automatically in the inbox.