Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[pushover] Sending messages randomly fails with java.io.EOFException #10376

Open
olflo opened this issue Mar 22, 2021 · 59 comments · Fixed by #10437 · May be fixed by #17348
Open

[pushover] Sending messages randomly fails with java.io.EOFException #10376

olflo opened this issue Mar 22, 2021 · 59 comments · Fixed by #10437 · May be fixed by #17348
Labels
bug An unexpected problem or unintended behavior of an add-on

Comments

@olflo
Copy link

olflo commented Mar 22, 2021

Expected Behavior

Pushover messages should be reliable. Every attempt of sending a message from a rule should bring the same result.

Current Behavior

Very randomly and for no good reason the following error message appears in the logs and no pushover message is sent:

Script execution of rule with UID 'hm-sonstige-5' failed: java.io.EOFException: HttpConnectionOverHTTP@d761b68::DecryptedEndPoint@3b78ddb9{api.pushover.net/104.20.125.71:443<->/192.168.178.2:47218,OPEN,fill=-,flush=F,to=82112373/0} in hm-sonstige

Seconds later the exact same rule works like a charm for multiple times.

Steps to Reproduce (for Bugs)

Send a pushover message from the same rule multiple times.

Your Environment

  • Version used: openHAB 3.1.0.M2
  • Operating System and version: Synology Docker Container
@olflo olflo added the bug An unexpected problem or unintended behavior of an add-on label Mar 22, 2021
@cweitkamp
Copy link
Contributor

Can you add some DEBUG or TRACE logs?

@olflo
Copy link
Author

olflo commented Mar 31, 2021

I am trying to reproduce the issue, but it seems to happen very randomly.
Do you need the TRACE of the binding org.openhab.binding.pushover or the TRACE of internal.handler.ScriptActionHandler ?
The latter throws the Exception.

@cweitkamp
Copy link
Contributor

If so, best would be both.

@olflo
Copy link
Author

olflo commented Apr 1, 2021

This is all I could find in the logs. Hope it helps...

2021-03-31 22:02:51.914 [TRACE] [ver.internal.actions.PushoverActions] - ThingAction 'sendMessage' called with value(s): message='Die Waschmaschine ist fertig!', title='Waschmaschine'
2021-03-31 22:02:51.914 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json'
2021-03-31 22:02:51.915 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@47a98bca'
2021-03-31 22:02:51.921 [DEBUG] [nal.connection.PushoverAPIConnection] - Exception occurred during execution: java.io.EOFException: HttpConnectionOverHTTP@33c06a9d::DecryptedEndPoint@3f5fdb78{api.pushover.net/104.20.124.71:443<->/192.168.178.2:35676,OPEN,fill=-,flush=-,to=932788/0}
java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@33c06a9d::DecryptedEndPoint@3f5fdb78{api.pushover.net/104.20.124.71:443<->/192.168.178.2:35676,OPEN,fill=-,flush=-,to=932788/0}
	at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:685) ~[bundleFile:9.4.20.v20190813]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.executeRequest(PushoverAPIConnection.java:150) [bundleFile:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.post(PushoverAPIConnection.java:134) [bundleFile:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.sendMessage(PushoverAPIConnection.java:78) [bundleFile:?]
	at org.openhab.binding.pushover.internal.handler.PushoverAccountHandler.sendMessage(PushoverAccountHandler.java:137) [bundleFile:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.send(PushoverActions.java:208) [bundleFile:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendMessage(PushoverActions.java:51) [bundleFile:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendMessage(PushoverActions.java:55) [bundleFile:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1176) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1151) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1137) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1082) [bundleFile:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:862) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:232) [bundleFile:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:459) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:240) [bundleFile:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:202) [bundleFile:?]
	at org.openhab.core.model.script.runtime.internal.engine.ScriptImpl.execute(ScriptImpl.java:80) [bundleFile:?]
	at org.openhab.core.model.script.runtime.internal.engine.DSLScriptEngine.eval(DSLScriptEngine.java:131) [bundleFile:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:62) [bundleFile:?]
	at java.util.Optional.ifPresent(Optional.java:183) [?:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:59) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1179) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.runRule(RuleEngineImpl.java:987) [bundleFile:?]
	at org.openhab.core.automation.internal.TriggerHandlerCallbackImpl$TriggerData.run(TriggerHandlerCallbackImpl.java:89) [bundleFile:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	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) [?:?]
Caused by: java.io.EOFException: HttpConnectionOverHTTP@33c06a9d::DecryptedEndPoint@3f5fdb78{api.pushover.net/104.20.124.71:443<->/192.168.178.2:35676,OPEN,fill=-,flush=-,to=932788/0}
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:335) ~[?:?]
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1526) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:209) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:147) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?]
	at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?]
	... 1 more
2021-03-31 22:02:51.931 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'waschmaschine-1' failed: java.io.EOFException: HttpConnectionOverHTTP@33c06a9d::DecryptedEndPoint@3f5fdb78{api.pushover.net/104.20.124.71:443<->/192.168.178.2:35676,OPEN,fill=-,flush=-,to=932788/0} in waschmaschine

@cweitkamp
Copy link
Contributor

Thanks. It might help.

Currently I have two possible solutions in my mind and I prepared a first test version for you: org.openhab.binding.pushover-3.1.0-SNAPSHOT.zip

Are you able to test it?

@cweitkamp cweitkamp self-assigned this Apr 2, 2021
@openhab-bot
Copy link
Collaborator

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/pushover-exception-return-value/116669/15

@olflo
Copy link
Author

olflo commented Apr 2, 2021

Thanks. It might help.

Currently I have two possible solutions in my mind and I prepared a first test version for you: org.openhab.binding.pushover-3.1.0-SNAPSHOT.zip

Are you able to test it?

Do I have to uninstall the 3.1.0.M2 Version before copying your version to the addons folder? (I didn't)

I do get errors now that I haven't seen before:

2021-04-02 13:14:08.143 [ERROR] [com.sun.xml.messaging.saaj.soap ] - SAAJ0511: Unable to create envelope from given source

In the console:

ERROR: 'The element type "HR" must be terminated by the matching end-tag "</HR>".'

Still got the error once so far:

2021-04-02 13:01:00.219 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'TEST-1' failed: java.io.EOFException: HttpConnectionOverHTTP@1a429163::DecryptedEndPoint@42d92773{api.pushover.net/104.20.124.71:443<->/192.168.178.2:40540,OPEN,fill=-,flush=-,to=2194674/0} in TEST

@cweitkamp
Copy link
Contributor

Do I have to uninstall the 3.1.0.M2 Version before copying your version to the addons folder?

Yes. Please uninstall any other Pushover binding versions before. Download the “.zip” file, extract the “.jar” and put it into your addons/ folder.

@olflo
Copy link
Author

olflo commented Apr 2, 2021

Looks good so far.
I created a test rule that sends a pushover message every 5 minutes.
It's working flawlessly since a couple of hours. Not a single error in the logs.

@cweitkamp
Copy link
Contributor

Sounds good. I will prepare a PR for it and submit my changes.

Some more information in them: I added additional exception handling which should result in correct return of false if an error occurs. The binding itself will not try to try to resend a message on failure. A user has to take care of that if it is important.

@olflo
Copy link
Author

olflo commented Apr 3, 2021

I just had a missing pushover notification.
Email worked, pushover didn't.

As soon as I'm home, I'll have a look into the log files...

@olflo
Copy link
Author

olflo commented Apr 3, 2021

Here we go...

2021-04-03 10:59:28.064 [DEBUG] [nal.connection.PushoverAPIConnection] - Exception occurred during execution: java.io.EOFException: HttpConnectionOverHTTP@4c662b99::DecryptedEndPoint@1b60745c{api.pushover.net/104.20.125.71:443<->/192.168.178.2:59162,CLOSED,fill=-,flush=F,to=52460497/0}
java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@4c662b99::DecryptedEndPoint@1b60745c{api.pushover.net/104.20.125.71:443<->/192.168.178.2:59162,CLOSED,fill=-,flush=F,to=52460497/0}
	at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:685) ~[bundleFile:9.4.20.v20190813]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.executeRequest(PushoverAPIConnection.java:146) [bundleFile:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.post(PushoverAPIConnection.java:130) [bundleFile:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.sendMessage(PushoverAPIConnection.java:76) [bundleFile:?]
	at org.openhab.binding.pushover.internal.handler.PushoverAccountHandler.sendMessage(PushoverAccountHandler.java:138) [bundleFile:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.send(PushoverActions.java:255) [bundleFile:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendAttachmentMessage(PushoverActions.java:172) [bundleFile:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendAttachmentMessage(PushoverActions.java:177) [bundleFile:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1176) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1151) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1137) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1082) [bundleFile:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:862) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:232) [bundleFile:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:459) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:240) [bundleFile:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) [bundleFile:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:202) [bundleFile:?]
	at org.openhab.core.model.script.runtime.internal.engine.ScriptImpl.execute(ScriptImpl.java:80) [bundleFile:?]
	at org.openhab.core.model.script.runtime.internal.engine.DSLScriptEngine.eval(DSLScriptEngine.java:131) [bundleFile:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:62) [bundleFile:?]
	at java.util.Optional.ifPresent(Optional.java:183) [?:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:59) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1179) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.runRule(RuleEngineImpl.java:987) [bundleFile:?]
	at org.openhab.core.automation.internal.TriggerHandlerCallbackImpl$TriggerData.run(TriggerHandlerCallbackImpl.java:89) [bundleFile:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	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) [?:?]
Caused by: java.io.EOFException: HttpConnectionOverHTTP@4c662b99::DecryptedEndPoint@1b60745c{api.pushover.net/104.20.125.71:443<->/192.168.178.2:59162,CLOSED,fill=-,flush=F,to=52460497/0}
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:335) ~[?:?]
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1526) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:209) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:147) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?]
	at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?]
	... 1 more

@cweitkamp
Copy link
Contributor

In DEBUG mode I expected the message shown above. The important thing is, that we do not see the error in ScriptActionHandler anymore. It will not be possible to prevent communication failures towards the Pushover API. Only to handle them correctly.

Did you still see an error message like this one?

2021-04-02 13:01:00.219 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'TEST-1' failed: java.io.EOFException: HttpConnectionOverHTTP@1a429163::DecryptedEndPoint@42d92773{api.pushover.net/104.20.124.71:443<->/192.168.178.2:40540,OPEN,fill=-,flush=-,to=2194674/0} in TEST

@olflo
Copy link
Author

olflo commented Apr 3, 2021

I have to check the logs when I'm back home. Busy day ;-)

But I had not a single error on openHAB 2.5. This issue started with the openHAB 3 Update.

@olflo olflo closed this as completed Apr 3, 2021
@olflo
Copy link
Author

olflo commented Apr 3, 2021

Did you still see an error message like this one?

That error didn't show up anymore.
But like I said before, the pushover messages worked without any exception in version 2.5.
Since version 3 I experience these random issues.

@olflo olflo reopened this Apr 3, 2021
@olflo
Copy link
Author

olflo commented Apr 4, 2021

Is this issue really closed?

I'm still experiencing some missing pushover messages, which I haven't seen in version 2.5 at all.

@fwolter
Copy link
Member

fwolter commented Apr 4, 2021

Did you try the change in #10437?

@olflo
Copy link
Author

olflo commented Apr 4, 2021

Isn't that the same change, that @cweitkamp included in the test version above?
I'm using this right now and still had a couple of missing messages.

@cweitkamp
Copy link
Contributor

Please reopen this issue if it is still a problem for you,

The changes in #10437 are included in the test version I provided to you. They were necessary anyways. As I told you above we cannot prevent communication failures for sure. Just handle them correctly.

But I have a second idea how we can improve the situation. I will prepare another test version for you. Currently the binding uses a shared HTTP client which may interfere with other bindings. We can test to create an own instance of the client.

@olflo
Copy link
Author

olflo commented Apr 5, 2021

Sounds promising...
I'll give it a try, as soon as it's ready.
Thanks for your work, much appreciated!

OT: How do I reopen the issue? (Maybe I'm blind :-D)

EDIT: I think I'm not allowed to reopen the issue, because @fwolter closed it.

@olflo
Copy link
Author

olflo commented Apr 6, 2021

In DEBUG mode I expected the message shown above. The important thing is, that we do not see the error in ScriptActionHandler anymore.

This error showed up a couple of minutes ago (no pushover message was sent):

[internal.handler.ScriptActionHandler] - Script execution of rule with UID 'hm-sonstige-5' failed: null in hm-sonstige

@fwolter fwolter reopened this Apr 6, 2021
@olflo
Copy link
Author

olflo commented Apr 6, 2021

It's very strange and I don't know whether this helps, but it seems like the longer the interval in my test rule, the more errors I get.

Generating pushover messages every one or two minutes creates no errors.
Setting the interval to ten minutes resulted in two errors within 30 minutes.

EDIT: Almost every second message seems to fail. The reason differs:

2021-04-06 20:00:02.013 [DEBUG] [nal.connection.PushoverAPIConnection] - Exception occurred during execution: java.io.EOFException: HttpConnectionOverHTTP@23ca7f7c::DecryptedEndPoint@2416ac01{api.pushover.net/104.20.125.71:443<->/192.168.178.2:34694,CLOSED,fill=-,flush=W,to=593481/0}
2021-04-06 20:10:11.691 [DEBUG] [nal.connection.PushoverAPIConnection] - Exception occurred during execution: Total timeout 10000 ms elapsed
java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed
2021-04-06 21:30:01.698 [DEBUG] [nal.connection.PushoverAPIConnection] - Exception occurred during execution: org.eclipse.jetty.io.EofException
java.util.concurrent.ExecutionException: org.eclipse.jetty.io.EofException

@olflo
Copy link
Author

olflo commented Apr 12, 2021

Any Updates on this?

As a workaround I'm sending an email to my pushover mail address ([email protected]). This works without any problems, but it's a bit delayed.

@sihui62
Copy link
Contributor

sihui62 commented Aug 23, 2024

Push.
Issue still exists on 4.2.1

@lsiepel
Copy link
Contributor

lsiepel commented Aug 24, 2024

Push. Issue still exists on 4.2.1

There is not much we can do here for whenever the connection is closed either by the server or some router in between. Only think we can do is to create a retry mechanism. I'm a bit surprised it happens that often.

Edit: According to the API-documentation, a keep-alive header can be set. The binding does not do this, but the header might be set somewhere else as default. I'm not able to test this at the moment.

@stale stale bot removed the stale As soon as a PR is marked stale, it can be removed 6 months later. label Aug 24, 2024
@sihui62
Copy link
Contributor

sihui62 commented Aug 25, 2024

Thank you very much for looking into this.

I'm a bit surprised it happens that often.

Unfortunately it happens EVERY time there is a pause of around 5 minutes from the last message sent.

IIRC the problems started around the time the new TTL was introduced:

#15289
https://community.openhab.org/t/openhab-4-1-release-discussion/152252/20?u=sihui

I'm not able to test this at the moment.

If there is anything I can do (as a not coder), please shout.
I am using the pushover binding since 2016 and never have seen a problem before.

@lsiepel
Copy link
Contributor

lsiepel commented Aug 27, 2024

Unfortunately it happens EVERY time there is a pause of around 5 minutes from the last message sent.

IIRC the problems started around the time the new TTL was introduced:

#15289 https://community.openhab.org/t/openhab-4-1-release-discussion/152252/20?u=sihui

Double checked the related PR regarding TTL and afaict it does not touch anything related.

You might want to try this pushover binding version where i replaced the commonhttpclient with a custom one.

To test:

  • make sure you use openHAB 4.2.1
  • uninstall the currernt binding version
  • drop the jar file in your addon folder

@sihui62
Copy link
Contributor

sihui62 commented Aug 27, 2024

You might want to try this

Thanks for investing time into this.

Unfortunately the binding does not start, even after manually starting through the console:

openhab> bundle:list | grep Push
336 │ Waiting │  80 │ 4.3.0.202408271155    │ openHAB Add-ons :: Bundles :: Pushover Binding
openhab> bundle:start 336
openhab> bundle:list | grep Push
336 │ Waiting │  80 │ 4.3.0.202408271155    │ openHAB Add-ons :: Bundles :: Pushover Binding

System details:

runtimeInfo:
  version: 4.2.1
  buildString: Release Build
locale: de-DE
systemInfo:
  configFolder: /opt/openhab/conf
  userdataFolder: /opt/openhab/userdata
  logFolder: /opt/openhab/userdata/logs
  javaVersion: 17.0.12
  javaVendor: Debian
  osName: Linux
  osVersion: 6.1.0-23-amd64
  osArchitecture: amd64
  availableProcessors: 2
  freeMemory: 258455768
  totalMemory: 708837376
  uptime: 717
  startLevel: 70
debug.log
2024-08-27 14:34:26.286 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-08-27 14:34:26.339 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Querying state disabled
2024-08-27 14:34:26.383 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Querying state disabled
2024-08-27 14:34:26.412 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Component can not be activated since it is in state disabled
2024-08-27 14:34:26.437 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Querying state disabled
2024-08-27 14:34:26.462 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Updating target filters
2024-08-27 14:34:26.482 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-08-27 14:34:26.504 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-08-27 14:34:26.523 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-08-27 14:34:26.543 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-08-27 14:34:26.563 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-08-27 14:34:26.590 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-08-27 14:34:26.609 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : dm osgi.ds.satisfying.condition tracker opened
2024-08-27 14:34:26.635 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-08-27 14:34:26.661 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Changed state from disabled to unsatisfiedReference
2024-08-27 14:34:26.683 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Component enabled
2024-08-27 14:34:26.716 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : ActivateInternal
2024-08-27 14:34:26.740 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Querying state unsatisfiedReference
2024-08-27 14:34:26.765 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Querying state unsatisfiedReference
2024-08-27 14:34:26.790 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Activating component from state unsatisfiedReference
2024-08-27 14:34:26.810 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Querying state unsatisfiedReference
2024-08-27 14:34:26.834 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Querying state unsatisfiedReference
2024-08-27 14:34:26.859 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : Changed state from unsatisfiedReference to satisfied
2024-08-27 14:34:26.886 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.actions.PushoverActions(454)] : registration change queue [registered]
2024-08-27 14:34:26.912 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2024-08-27 14:34:26.935 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Component created: DS=DS13, implementation=org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider]
2024-08-27 14:34:26.954 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Component Services: scope=prototype, services=[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider, org.openhab.core.config.core.ConfigOptionProvider]
2024-08-27 14:34:26.978 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-08-27 14:34:27.004 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Querying state disabled
2024-08-27 14:34:27.027 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Querying state disabled
2024-08-27 14:34:27.076 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Component can not be activated since it is in state disabled
2024-08-27 14:34:27.102 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Querying state disabled
2024-08-27 14:34:27.122 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Updating target filters
2024-08-27 14:34:27.144 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-08-27 14:34:27.163 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-08-27 14:34:27.183 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-08-27 14:34:27.211 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-08-27 14:34:27.252 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-08-27 14:34:27.296 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-08-27 14:34:27.315 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : dm osgi.ds.satisfying.condition tracker opened
2024-08-27 14:34:27.336 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-08-27 14:34:27.360 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Changed state from disabled to unsatisfiedReference
2024-08-27 14:34:27.383 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Component enabled
2024-08-27 14:34:27.413 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : ActivateInternal
2024-08-27 14:34:27.436 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Querying state unsatisfiedReference
2024-08-27 14:34:27.458 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Querying state unsatisfiedReference
2024-08-27 14:34:27.485 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Activating component from state unsatisfiedReference
2024-08-27 14:34:27.509 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Querying state unsatisfiedReference
2024-08-27 14:34:27.529 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Querying state unsatisfiedReference
2024-08-27 14:34:27.550 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Changed state from unsatisfiedReference to satisfied
2024-08-27 14:34:27.572 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : registration change queue [registered]
2024-08-27 14:34:27.595 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : ServiceFactory.getService()
2024-08-27 14:34:27.623 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Checking constructor public org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider()
2024-08-27 14:34:27.660 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Found constructor with 0 arguments : public org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider()
2024-08-27 14:34:27.688 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : This thread collected dependencies
2024-08-27 14:34:27.715 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : getService (ServiceFactory) dependencies collected.
2024-08-27 14:34:27.741 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Querying state satisfied
2024-08-27 14:34:27.764 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-08-27 14:34:27.818 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : getting activate: activate
2024-08-27 14:34:27.860 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Locating method activate in class org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider
2024-08-27 14:34:27.887 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Declared Method org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-08-27 14:34:27.914 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Locating method activate in class java.lang.Object
2024-08-27 14:34:27.942 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-08-27 14:34:27.971 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : activate method [activate] not found, ignoring
2024-08-27 14:34:27.997 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(455)] : Changed state from satisfied to active
2024-08-27 14:34:28.025 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Dependency Manager created $000interface=org.openhab.core.io.net.http.HttpClientFactory, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=service, parameter=0
2024-08-27 14:34:28.058 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2024-08-27 14:34:28.082 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Component created: DS=DS14, implementation=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[binding.pushover]
2024-08-27 14:34:28.112 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2024-08-27 14:34:28.134 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-08-27 14:34:28.156 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Querying state disabled
2024-08-27 14:34:28.183 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Querying state disabled
2024-08-27 14:34:28.231 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Component can not be activated since it is in state disabled
2024-08-27 14:34:28.257 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Querying state disabled
2024-08-27 14:34:28.283 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Updating target filters
2024-08-27 14:34:28.309 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : No change in target property for dependency $000: currently registered: false
2024-08-27 14:34:28.336 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] :  No existing service listener to unregister for dependency $000
2024-08-27 14:34:28.362 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Setting target property for dependency $000 to null
2024-08-27 14:34:28.387 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.io.net.http.HttpClientFactory), initialReferenceFilter (objectClass=org.openhab.core.io.net.http.HttpClientFactory)
2024-08-27 14:34:28.422 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm $000 tracker reset (closed)
2024-08-27 14:34:28.442 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=311, service.bundleid=182, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=170} (enter)
2024-08-27 14:34:28.469 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2024-08-27 14:34:28.496 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=311, service.bundleid=182, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=170} (exit)
2024-08-27 14:34:28.550 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm $000 tracker opened
2024-08-27 14:34:28.571 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : registering service listener for dependency $000
2024-08-27 14:34:28.593 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-08-27 14:34:28.613 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-08-27 14:34:28.635 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-08-27 14:34:28.661 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-08-27 14:34:28.689 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm osgi.ds.satisfying.condition tracking 2 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-08-27 14:34:28.714 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm osgi.ds.satisfying.condition tracking 2 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-08-27 14:34:28.740 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : dm osgi.ds.satisfying.condition tracker opened
2024-08-27 14:34:28.752 [WARN ] [ault.internal.handler.RenaultHandler] - Disabling unsupported lock status update.
2024-08-27 14:34:28.767 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-08-27 14:34:28.818 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Changed state from disabled to unsatisfiedReference
2024-08-27 14:34:28.843 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Component enabled
2024-08-27 14:34:28.876 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : ActivateInternal
2024-08-27 14:34:28.901 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state unsatisfiedReference
2024-08-27 14:34:28.922 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state unsatisfiedReference
2024-08-27 14:34:28.949 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Activating component from state unsatisfiedReference
2024-08-27 14:34:28.977 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state unsatisfiedReference
2024-08-27 14:34:29.005 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state unsatisfiedReference
2024-08-27 14:34:29.032 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Changed state from unsatisfiedReference to satisfied
2024-08-27 14:34:29.053 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : registration change queue [registered]
2024-08-27 14:34:29.078 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Checking constructor public org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(org.openhab.core.io.net.http.HttpClientFactory)
2024-08-27 14:34:29.099 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.io.net.http.HttpClientFactory through loader of org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory
2024-08-27 14:34:29.120 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : getClassFromComponentClassLoader: Found class org.openhab.core.io.net.http.HttpClientFactory
2024-08-27 14:34:29.142 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Found constructor with 1 arguments : public org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(org.openhab.core.io.net.http.HttpClientFactory)
2024-08-27 14:34:29.165 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : This thread collected dependencies
2024-08-27 14:34:29.186 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : getService (single component manager) dependencies collected.
2024-08-27 14:34:29.210 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.231 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.250 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=311, service.bundleid=182, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=170}] service: [null]]]
2024-08-27 14:34:29.269 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-08-27 14:34:29.294 [ERROR] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Error during instantiation of the implementation object
java.lang.reflect.InvocationTargetException: null
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:481) ~[?:?]
	at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.newInstance(ComponentConstructorImpl.java:326) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:286) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:115) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:1002) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:975) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:920) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:220) ~[org.eclipse.osgi-3.18.0.jar:?]
	at java.security.AccessController.doPrivileged(AccessController.java:318) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:217) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:118) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:48) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:547) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:534) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:660) [org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:88) [bundleFile:?]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:675) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2612) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:2078) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:2061) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:443) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:336) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:304) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1232) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1152) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:959) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:895) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1184) [bundleFile:?]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:116) [bundleFile:?]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:123) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:961) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:937) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:874) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:141) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:262) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:500) [org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:929) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:915) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:133) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:984) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:752) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:674) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:437) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:671) [bundleFile:?]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:310) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:593) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:74) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:460) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [bundleFile:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:488) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:420) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:450) [osgi.core-8.0.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:949) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:229) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:138) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:130) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:217) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:499) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.start(Module.java:486) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]
Caused by: java.lang.IllegalArgumentException: consumerName binding.pushover contains illegal character, allowed only [a-zA-Z0-9_-]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.checkConsumerName(WebClientFactoryImpl.java:360) ~[?:?]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.createHttpClient(WebClientFactoryImpl.java:150) ~[?:?]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.createHttpClient(WebClientFactoryImpl.java:144) ~[?:?]
	at org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory.<init>(PushoverHandlerFactory.java:48) ~[?:?]
	... 79 more
2024-08-27 14:34:29.345 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Failed creating the component instance; see log for reason
2024-08-27 14:34:29.369 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.390 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Changed state from satisfied to satisfied
2024-08-27 14:34:29.410 [WARN ] [g.discovery.internal.PersistentInbox] - bundle org.openhab.core.config.discovery:4.2.1 (169)[org.openhab.core.config.discovery.internal.PersistentInbox(141)] : Could not get service from ref {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=1068, service.bundleid=336, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, component.id=456}
2024-08-27 14:34:29.431 [WARN ] [g.discovery.internal.PersistentInbox] - bundle org.openhab.core.config.discovery:4.2.1 (169)[org.openhab.core.config.discovery.internal.PersistentInbox(141)] : DependencyManager : invokeBindMethod : Service not available from service registry for ServiceReference {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=1068, service.bundleid=336, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, component.id=456} for reference ThingHandlerFactory
2024-08-27 14:34:29.454 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : This thread collected dependencies
2024-08-27 14:34:29.478 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : getService (single component manager) dependencies collected.
2024-08-27 14:34:29.499 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.520 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.543 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=311, service.bundleid=182, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=170}] service: [org.openhab.core.io.net.http.internal.WebClientFactoryImpl@6b889308]]]
2024-08-27 14:34:29.562 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-08-27 14:34:29.583 [ERROR] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Error during instantiation of the implementation object
java.lang.reflect.InvocationTargetException: null
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:481) ~[?:?]
	at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.newInstance(ComponentConstructorImpl.java:326) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:286) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:115) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:1002) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:975) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:920) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:220) ~[org.eclipse.osgi-3.18.0.jar:?]
	at java.security.AccessController.doPrivileged(AccessController.java:318) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:217) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:118) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:48) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:547) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:534) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:660) [org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:88) [bundleFile:?]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:675) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2612) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:2078) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:2061) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:443) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:336) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:304) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1232) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1152) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:959) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:895) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1184) [bundleFile:?]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:116) [bundleFile:?]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:123) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:961) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:937) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:874) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:141) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:262) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:500) [org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:929) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:915) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:133) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:984) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:752) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:674) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:437) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:671) [bundleFile:?]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:310) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:593) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:74) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:460) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [bundleFile:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:488) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:420) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:450) [osgi.core-8.0.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:949) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:229) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:138) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:130) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:217) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:499) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.start(Module.java:486) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]
Caused by: java.lang.IllegalArgumentException: consumerName binding.pushover contains illegal character, allowed only [a-zA-Z0-9_-]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.checkConsumerName(WebClientFactoryImpl.java:360) ~[?:?]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.createHttpClient(WebClientFactoryImpl.java:150) ~[?:?]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.createHttpClient(WebClientFactoryImpl.java:144) ~[?:?]
	at org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory.<init>(PushoverHandlerFactory.java:48) ~[?:?]
	... 79 more
2024-08-27 14:34:29.639 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Failed creating the component instance; see log for reason
2024-08-27 14:34:29.659 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.680 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Changed state from satisfied to satisfied
2024-08-27 14:34:29.701 [WARN ] [.thing.internal.GenericThingProvider] - bundle org.openhab.core.model.thing:4.2.1 (214)[org.openhab.core.model.thing.internal.GenericThingProvider(249)] : Could not get service from ref {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=1068, service.bundleid=336, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, component.id=456}
2024-08-27 14:34:29.721 [WARN ] [.thing.internal.GenericThingProvider] - bundle org.openhab.core.model.thing:4.2.1 (214)[org.openhab.core.model.thing.internal.GenericThingProvider(249)] : DependencyManager : invokeBindMethod : Service not available from service registry for ServiceReference {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=1068, service.bundleid=336, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, component.id=456} for reference ThingHandlerFactory
2024-08-27 14:34:29.741 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : This thread collected dependencies
2024-08-27 14:34:29.759 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : getService (single component manager) dependencies collected.
2024-08-27 14:34:29.777 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.797 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.824 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=311, service.bundleid=182, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=170}] service: [org.openhab.core.io.net.http.internal.WebClientFactoryImpl@6b889308]]]
2024-08-27 14:34:29.841 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-08-27 14:34:29.859 [ERROR] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Error during instantiation of the implementation object
java.lang.reflect.InvocationTargetException: null
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:481) ~[?:?]
	at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.newInstance(ComponentConstructorImpl.java:326) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:286) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:115) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:1002) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:975) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:920) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:220) ~[org.eclipse.osgi-3.18.0.jar:?]
	at java.security.AccessController.doPrivileged(AccessController.java:318) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:217) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:118) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:48) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:547) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:534) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:660) [org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:88) [bundleFile:?]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:675) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2612) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:2078) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:2061) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:443) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:336) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:304) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1232) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1152) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:959) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:895) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1184) [bundleFile:?]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:116) [bundleFile:?]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:123) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:961) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:937) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:874) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:141) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:262) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:500) [org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:929) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:915) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:133) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:984) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:752) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:674) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:437) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:671) [bundleFile:?]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:310) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:593) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:74) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:460) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [bundleFile:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:488) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:420) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:450) [osgi.core-8.0.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:949) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:229) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:138) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:130) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:217) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:499) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.start(Module.java:486) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]
Caused by: java.lang.IllegalArgumentException: consumerName binding.pushover contains illegal character, allowed only [a-zA-Z0-9_-]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.checkConsumerName(WebClientFactoryImpl.java:360) ~[?:?]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.createHttpClient(WebClientFactoryImpl.java:150) ~[?:?]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.createHttpClient(WebClientFactoryImpl.java:144) ~[?:?]
	at org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory.<init>(PushoverHandlerFactory.java:48) ~[?:?]
	... 79 more
2024-08-27 14:34:29.905 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Failed creating the component instance; see log for reason
2024-08-27 14:34:29.925 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:29.947 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Changed state from satisfied to satisfied
2024-08-27 14:34:29.967 [WARN ] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:4.2.1 (221)[org.openhab.core.thing.internal.ThingManagerImpl(279)] : Could not get service from ref {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=1068, service.bundleid=336, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, component.id=456}
2024-08-27 14:34:29.989 [WARN ] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:4.2.1 (221)[org.openhab.core.thing.internal.ThingManagerImpl(279)] : DependencyManager : invokeBindMethod : Service not available from service registry for ServiceReference {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=1068, service.bundleid=336, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, component.id=456} for reference ThingHandlerFactory
2024-08-27 14:34:30.012 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : This thread collected dependencies
2024-08-27 14:34:30.035 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : getService (single component manager) dependencies collected.
2024-08-27 14:34:30.056 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:30.078 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:30.101 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=311, service.bundleid=182, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=170}] service: [org.openhab.core.io.net.http.internal.WebClientFactoryImpl@6b889308]]]
2024-08-27 14:34:30.122 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-08-27 14:34:30.144 [ERROR] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Error during instantiation of the implementation object
java.lang.reflect.InvocationTargetException: null
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:481) ~[?:?]
	at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.newInstance(ComponentConstructorImpl.java:326) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:286) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:115) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:1002) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:975) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:920) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:220) ~[org.eclipse.osgi-3.18.0.jar:?]
	at java.security.AccessController.doPrivileged(AccessController.java:318) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:217) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:118) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:48) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:547) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:534) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:660) [org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:88) [bundleFile:?]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:675) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2612) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:2078) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:2061) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:443) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:336) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:304) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1232) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1152) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:959) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:895) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1184) [bundleFile:?]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:116) [bundleFile:?]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:123) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:961) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:937) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:874) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:141) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:262) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:500) [org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:929) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:915) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:133) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:984) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:752) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:674) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:437) [bundleFile:?]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:671) [bundleFile:?]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:310) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:593) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:74) [bundleFile:?]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:460) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [bundleFile:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [bundleFile:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:488) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:420) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [osgi.core-8.0.0.jar:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:450) [osgi.core-8.0.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:949) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:229) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:138) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:130) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:217) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:499) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.start(Module.java:486) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]
Caused by: java.lang.IllegalArgumentException: consumerName binding.pushover contains illegal character, allowed only [a-zA-Z0-9_-]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.checkConsumerName(WebClientFactoryImpl.java:360) ~[?:?]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.createHttpClient(WebClientFactoryImpl.java:150) ~[?:?]
	at org.openhab.core.io.net.http.internal.WebClientFactoryImpl.createHttpClient(WebClientFactoryImpl.java:144) ~[?:?]
	at org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory.<init>(PushoverHandlerFactory.java:48) ~[?:?]
	... 79 more
2024-08-27 14:34:30.189 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Failed creating the component instance; see log for reason
2024-08-27 14:34:30.210 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:34:30.233 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Changed state from satisfied to satisfied
2024-08-27 14:34:30.258 [WARN ] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:4.2.1 (221)[org.openhab.core.thing.internal.ThingRegistryImpl(280)] : Could not get service from ref {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=1068, service.bundleid=336, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, component.id=456}
2024-08-27 14:34:30.282 [WARN ] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:4.2.1 (221)[org.openhab.core.thing.internal.ThingRegistryImpl(280)] : DependencyManager : invokeBindMethod : Service not available from service registry for ServiceReference {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=1068, service.bundleid=336, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory, component.id=456} for reference ThingHandlerFactory
2024-08-27 14:36:00.560 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'testing-9' failed: 'sendMessage' is not a member of 'org.openhab.core.thing.binding.ThingActions'; line 115, column 5, length 227 in testing
2024-08-27 14:36:00.595 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'testing-9' failed: 'sendMessage' is not a member of 'org.openhab.core.thing.binding.ThingActions'; line 115, column 5, length 227 in testing
2024-08-27 14:36:00.622 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'testing-9' failed: 'sendMessage' is not a member of 'org.openhab.core.thing.binding.ThingActions'; line 115, column 5, length 227 in testing
2024-08-27 14:36:00.651 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'testing-9' failed: 'sendMessage' is not a member of 'org.openhab.core.thing.binding.ThingActions'; line 115, column 5, length 227 in testing
2024-08-27 14:36:02.877 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:36:06.182 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied
2024-08-27 14:36:25.915 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.3.0.202408271155 (336)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(456)] : Querying state satisfied

@lsiepel
Copy link
Contributor

lsiepel commented Aug 27, 2024

Ah, mistake in the consumer name, please try-again i updated the jar.

@sihui62
Copy link
Contributor

sihui62 commented Aug 27, 2024

please try-again

Test binding is working now, but issue remains.

First attempt after longer pause at 17:29 with error:

trace.log with error 17:29
2024-08-27 17:29:36.556 [TRACE] [ver.internal.actions.PushoverActions] - ThingAction 'sendMessage' called with value(s): message='Pushover Test', title='openHAB', sound='siren', url='null', urlTitle='null', attachment='null', contentType='null', priority='0', device='null', ttl='null'
2024-08-27 17:29:36.582 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json'
2024-08-27 17:29:36.609 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@4b2e2caf'
2024-08-27 17:29:36.644 [DEBUG] [nal.connection.PushoverAPIConnection] - ExecutionException occurred during execution: java.io.EOFException: @77a927b4::DecryptedEndPoint@7396bd99{l=/192.168.2.212:53682,r=api.pushover.net/104.20.42.236:443,OPEN,fill=-,flush=-,to=3882051/0}
java.util.concurrent.ExecutionException: java.io.EOFException: @77a927b4::DecryptedEndPoint@7396bd99{l=/192.168.2.212:53682,r=api.pushover.net/104.20.42.236:443,OPEN,fill=-,flush=-,to=3882051/0}
	at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
	at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:732) ~[?:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.executeRequest(PushoverAPIConnection.java:158) ~[?:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.post(PushoverAPIConnection.java:141) ~[?:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.sendMessage(PushoverAPIConnection.java:84) ~[?:?]
	at org.openhab.binding.pushover.internal.handler.PushoverAccountHandler.sendMessage(PushoverAccountHandler.java:172) ~[?:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.send(PushoverActions.java:438) ~[?:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendMessage(PushoverActions.java:115) ~[?:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendMessage(PushoverActions.java:63) ~[?:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendMessage(PushoverActions.java:69) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:569) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1192) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1167) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1153) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1098) ~[?:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:878) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:243) ~[?:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:227) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:475) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:251) ~[?:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:227) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:213) ~[?:?]
	at org.openhab.core.model.script.runtime.internal.engine.ScriptImpl.execute(ScriptImpl.java:80) ~[?:?]
	at org.openhab.core.model.script.runtime.internal.engine.DSLScriptEngine.eval(DSLScriptEngine.java:137) ~[?:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:75) ~[?:?]
	at java.util.Optional.ifPresent(Optional.java:178) [?:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:72) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1188) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.runRule(RuleEngineImpl.java:997) [bundleFile:?]
	at org.openhab.core.automation.internal.TriggerHandlerCallbackImpl$TriggerData.run(TriggerHandlerCallbackImpl.java:86) [bundleFile:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
	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:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.io.EOFException: @77a927b4::DecryptedEndPoint@7396bd99{l=/192.168.2.212:53682,r=api.pushover.net/104.20.42.236:443,OPEN,fill=-,flush=-,to=3882051/0}
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:385) ~[?:?]
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1621) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:269) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:185) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) ~[?:?]
	at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
	... 1 more

Second attempt, successfull, at 17:31:

trace.log success 17:31

2024-08-27 17:31:08.761 [TRACE] [ver.internal.actions.PushoverActions] - ThingAction 'sendMessage' called with value(s): message='Pushover Test', title='openHAB', sound='siren', url='null', urlTitle='null', attachment='null', contentType='null', priority='0', device='null', ttl='null'
2024-08-27 17:31:08.789 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json'
2024-08-27 17:31:08.815 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@2e908342'
2024-08-27 17:31:09.168 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover response: status = 200, content = '{"status":1,"request":"3a96af14-2711-40b3-907e-7c9aeb766594"}'

Third attempt, error, at 17:37:

trace.log error 17:37
2024-08-27 17:37:25.925 [TRACE] [ver.internal.actions.PushoverActions] - ThingAction 'sendMessage' called with value(s): message='Pushover Test', title='openHAB', sound='siren', url='null', urlTitle='null', attachment='null', contentType='null', priority='0', device='null', ttl='null'
2024-08-27 17:37:25.953 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json'
2024-08-27 17:37:25.984 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@67177b9a'
2024-08-27 17:37:26.020 [DEBUG] [nal.connection.PushoverAPIConnection] - ExecutionException occurred during execution: java.io.EOFException: @6e11575d::DecryptedEndPoint@7a4fb716{l=/192.168.2.212:53052,r=api.pushover.net/104.20.42.236:443,OPEN,fill=-,flush=-,to=376851/0}
java.util.concurrent.ExecutionException: java.io.EOFException: @6e11575d::DecryptedEndPoint@7a4fb716{l=/192.168.2.212:53052,r=api.pushover.net/104.20.42.236:443,OPEN,fill=-,flush=-,to=376851/0}
	at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
	at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:732) ~[?:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.executeRequest(PushoverAPIConnection.java:158) ~[?:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.post(PushoverAPIConnection.java:141) ~[?:?]
	at org.openhab.binding.pushover.internal.connection.PushoverAPIConnection.sendMessage(PushoverAPIConnection.java:84) ~[?:?]
	at org.openhab.binding.pushover.internal.handler.PushoverAccountHandler.sendMessage(PushoverAccountHandler.java:172) ~[?:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.send(PushoverActions.java:438) ~[?:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendMessage(PushoverActions.java:115) ~[?:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendMessage(PushoverActions.java:63) ~[?:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendMessage(PushoverActions.java:69) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:569) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1192) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1167) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1153) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1098) ~[?:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:878) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:243) ~[?:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:227) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:475) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:251) ~[?:?]
	at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:227) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:213) ~[?:?]
	at org.openhab.core.model.script.runtime.internal.engine.ScriptImpl.execute(ScriptImpl.java:80) ~[?:?]
	at org.openhab.core.model.script.runtime.internal.engine.DSLScriptEngine.eval(DSLScriptEngine.java:137) ~[?:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:75) ~[?:?]
	at java.util.Optional.ifPresent(Optional.java:178) [?:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:72) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1188) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.runRule(RuleEngineImpl.java:997) [bundleFile:?]
	at org.openhab.core.automation.internal.TriggerHandlerCallbackImpl$TriggerData.run(TriggerHandlerCallbackImpl.java:86) [bundleFile:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
	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:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.io.EOFException: @6e11575d::DecryptedEndPoint@7a4fb716{l=/192.168.2.212:53052,r=api.pushover.net/104.20.42.236:443,OPEN,fill=-,flush=-,to=376851/0}
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:385) ~[?:?]
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1621) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:269) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:185) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) ~[?:?]
	at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
	... 1 more

Fourth attempt, successfull, at 17:40:

trace.log success 17:40
2024-08-27 17:40:08.911 [TRACE] [ver.internal.actions.PushoverActions] - ThingAction 'sendMessage' called with value(s): message='Pushover Test', title='openHAB', sound='siren', url='null', urlTitle='null', attachment='null', contentType='null', priority='0', device='null', ttl='null'
2024-08-27 17:40:08.939 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json'
2024-08-27 17:40:08.967 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@6b10d000'
2024-08-27 17:40:09.822 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover response: status = 200, content = '{"status":1,"request":"70af12c3-1eb5-4ba8-ba31-8f23e8ea8a83"}'

@lsiepel
Copy link
Contributor

lsiepel commented Aug 27, 2024

Could it be a router or something that actively closes the connection when it is idle for some time? There is not much to configure client side (binding)

@sihui62
Copy link
Contributor

sihui62 commented Aug 27, 2024

Could it be ...

I will further test with your test binding and also with the original binding and post here if I find something.
Thank you very much, so far.

@lsiepel
Copy link
Contributor

lsiepel commented Aug 27, 2024

Could it be ...

I will further test with your test binding and also with the original binding and post here if I find something. Thank you very much, so far.

Both bindings have sort of the same configuration. It’s just that the test version has an isolated client. Not affected by other bindings.

@lsiepel
Copy link
Contributor

lsiepel commented Aug 28, 2024

Updated the JAR, now it includes some more timeout restrictions. Curious if that makes a difference. most of them are set around 2 minute mark.

@sihui62
Copy link
Contributor

sihui62 commented Aug 28, 2024

Curious if that makes a difference.

It looks like it does:

16:17 -> success
16:19 -> success
16:26 -> success
16:36 -> success
16:56 -> success

So even after 20 min of inactivity, the next first consecutive attempt was successful.

I will do some more tests the next hours and report back. Great job 👍

@sihui62
Copy link
Contributor

sihui62 commented Aug 28, 2024

18:00 -> success

@sihui62
Copy link
Contributor

sihui62 commented Aug 29, 2024

After a couple of hours of operation, the pushover test binding

336 │ Active │ 80 │ 4.3.0.202408281406 │ openHAB Add-ons :: Bundles :: Pushover Binding

is still working fine, no issues anymore.

Jabadabado 🥇

@lsiepel
Copy link
Contributor

lsiepel commented Aug 29, 2024

Nice! I have updated the jar again. Would be nice if you can test once more.
I did some cleanup and had a closer look at the documentation so it should still work, but with less code change.

@sihui62
Copy link
Contributor

sihui62 commented Aug 29, 2024

Would be nice if you can test once more.

After around 5 hours of operation and several test messages I can confirm that version

336 │ Active │ 80 │ 4.3.0.202408290848 │ openHAB Add-ons :: Bundles :: Pushover Binding

also works without any issues.

Big THANKS again for solving this issue and all your work on openHAB!

@jlaur
Copy link
Contributor

jlaur commented Aug 31, 2024

@lsiepel - can you help me with an explanation why/how your fix works? 🙂 I had a very quick look the other day, and found only this usage of HttpClient:

final Request request = httpClient.newRequest(url).method(httpMethod).timeout(config.timeout,
TimeUnit.SECONDS);

So it seems we are doing blocking HTTP calls ad-hoc with 10 s timeout (default value at least) and not keeping any persistent connection. What causes the EOF exception, and how did you come up with 18 s as idle value? It seems like the default value for the shared client is 300 s, unless configured to something else or unless a binding messes with this value for the shared client:

https://github.com/openhab/openhab-core/blob/72753be8cc9af029c3e656a89b29064f4624c73f/bundles/org.openhab.core.io.net/src/main/java/org/openhab/core/io/net/http/internal/WebClientFactoryImpl.java#L183

https://github.com/openhab/openhab-core/blob/72753be8cc9af029c3e656a89b29064f4624c73f/bundles/org.openhab.core.io.net/src/main/java/org/openhab/core/io/net/http/internal/WebClientFactoryImpl.java#L113

I probably don't have all the information, so hence asking, since I don't understand what causes the issue, why no one else seems to have it and why/how your fix works.

@sihui62 - do you have anything in $OPENHAB_CONF/services/runtime.cfg starting with org.openhab.webclient or containing keepAliveTimeoutShared? Do you have a timeout set in the Thing configuration other than the default 10 s? Which bindings do you have installed?

@sihui62
Copy link
Contributor

sihui62 commented Aug 31, 2024

do you have anything in $OPENHAB_CONF/services/runtime.cfg

No, everything is commented out.

other than the default 10 s?

No, has always been 10s.

Which bindings do you have installed?

  - binding-astro
  - binding-bsblan
  - binding-enigma2
  - binding-ephemeris
  - binding-fineoffsetweatherstation
  - binding-fronius
  - binding-http
  - binding-hue
  - binding-icalendar
  - binding-ipcamera
  - binding-logreader
  - binding-mail
  - binding-mihome
  - binding-miio
  - binding-mqtt
  - binding-network
  - binding-renault
  - binding-roku
  - binding-speedtest
  - binding-tankerkoenig
  - binding-telegram
  - binding-tr064
  - binding-zwave
  - binding-worxlandroid
  - binding-pushover
  - binding- smarthome/j amazon echo control

@lsiepel
Copy link
Contributor

lsiepel commented Aug 31, 2024

o it seems we are doing blocking HTTP calls ad-hoc with 10 s timeout (default value at least) and not keeping any persistent connection. What causes the EOF exception, and how did you come up with 18 s as idle value? It seems like the default value for the shared client

It took me a while to get it fixed.

The EOF is caused by the httpclient while sending the request. The underlying connection seems no longer to be available, but the httpclient is not aware. The connection might be killed by anything in between the httpclient and the remote server (including the remote server self, firewall, routers, anything)

As of HTTP 1.1 the connection is kept alive by default. The Jetty client can be manipulated to control the idle time by setting httpClient.setIdleTimeout(); As it failed reproducable after 5 minutes, i set the idletimeout to a shorter time, i just choose 18 seconds, but it might also work with 3 minutes or any other value < 5 minutes.
Pushover binding does not use a periodic call, so i could not choose this interval + some offeset. The binding sends messagtes ad-hoc, so i assumed most messages are send close together or with some longer time in between.
I do not care that much about the exact value as there is little to no advantage to stretch this value to the max.

The thought behind this is that the httpclient does know when the idle timeout occurs and it handles it transparantly. As long as this timeout triggers before the 'remote connection kill' event is happening, it all works.

BTW: i ruled out the other bindings by first trying to use httpClientFactory.createHttpClient("binding.pushover"); but that did not help at all. You can see that in the commit history.

Hope this explains it enough to merge the request.

@jlaur
Copy link
Contributor

jlaur commented Sep 2, 2024

@lsiepel - thanks for your detailed explanation! I'm still a bit confused about what exactly happens in the specific case, and if using 18 s idle timeout will effectively resolve it or just somehow reduce it.

I'm currently trying to reproduce it in a simple manner:

var timeoutId = 0;
var seconds = 10;

function sendNotification() {
    notification.send("Test", "Test");
    timeoutId = setTimeout(() => {
        console.log("Sending test notification");
        sendNotification()
    }, seconds*1000);
    seconds = seconds * 2;
}

rules.when()
    .item("Test").changed().toOn()
    .then(event => {
        sendNotification()
    })
    .build("Pushover start test");

rules.when()
    .item("Test").changed().toOff()
    .then(event => {
        if (timeoutId > 0) {
            clearTimeout(timeoutId);
        }
    })
    .build("Pushover stop test");

I never experienced the issue myself, and also never saw it reported by anyone else. I'm therefore wondering about a few options:

  • Perhaps this would resolve it as well, maybe even more consistently by not having an idle connection at all?
              final Request request = httpClient.newRequest(url).method(httpMethod).header(HttpHeader.CONNECTION, "close")
                      .timeout(config.timeout, TimeUnit.SECONDS);
    18 seconds seems very low anyway, and I doubt there is much benefit in keeping it since I assume you would then have to second another notification within the next 18 seconds to benefit, which is probably a rare (and undesired) scenario.
  • With your current approach, perhaps we could avoid creating a custom client:
              final Request request = httpClient.newRequest(url).method(httpMethod).idleTimeout(18, TimeUnit.SECONDS)
                      .timeout(config.timeout, TimeUnit.SECONDS);
  • In either case, perhaps it should be made configurable as an advanced parameter? We already have the timeout configurable. This would allow for not affected users to still be reusing idle connections per default. I think the most common case is that everything works, and it's rather an exception to experience the EOFException. If we would start seeing some pattern and gain experience about best values, we could then later drop the parameter and provide the "perfect default" setup.

There are multiple factors that could cause the issue (like connection pool usage), and I'm just not sure if we are fixing the symptom rather than root cause.

WDYT?

@sihui62
Copy link
Contributor

sihui62 commented Sep 2, 2024

I never experienced the issue myself ...

I am using the pushover binding since 2016 and also did never experience the issue ... until the end of December 2023.

I even installed a new, clean openHAB (around the beginning of this year) and only installed the pushover binding: same issue

... and also never saw it reported by anyone else.

For me it seems we have that issue since 2021, when this issue report was opened, or am I wrong?

Anyway, thanks for taking your time to look into this. I almost switched to the notifications of the cloud connector, but am now confident we have a solution.

@jlaur
Copy link
Contributor

jlaur commented Sep 2, 2024

I am using the pushover binding since 2016 and also did never experience the issue ... until the end of December 2023.

Did you start using the binding differently at that time, for example did you start using Expiring Messages? Jetty was also upgraded in 4.1: openhab/openhab-core#3814. In any case, the OP had the issue in 2021 already.

For me it seems we have that issue since 2021, when this issue report was opened, or am I wrong?

Sorry, I mixed you up with the OP, so at least two are having the issue. My main point is that it doesn't seem to be the majority of users having it, unless we are only us three using the binding, or everyone except me is having it and staying silent in the foum and in this issue. 😄 This is not to say nothing is wrong in the binding, but just to bring up some additional considerations, and also to avoid breaking something for unaffected systems.

I hope you will be able to help testing once again if we come up with a tweaked fix. Your test efforts are also appreciated.

@lsiepel
Copy link
Contributor

lsiepel commented Sep 2, 2024

  • Perhaps this would resolve it as well, maybe even more consistently by not having an idle connection at all?

              final Request request = httpClient.newRequest(url).method(httpMethod).header(HttpHeader.CONNECTION, "close")
                      .timeout(config.timeout, TimeUnit.SECONDS);

    18 seconds seems very low anyway, and I doubt there is much benefit in keeping it since I assume you would then have to second another notification within the next 18 seconds to benefit, which is probably a rare (and undesired) scenario.

  • With your current approach, perhaps we could avoid creating a custom client:

              final Request request = httpClient.newRequest(url).method(httpMethod).idleTimeout(18, TimeUnit.SECONDS)
                      .timeout(config.timeout, TimeUnit.SECONDS);
  • In either case, perhaps it should be made configurable as an advanced parameter? We already have the timeout configurable. This would allow for not affected users to still be reusing idle connections per default. I think the most common case is that everything works, and it's rather an exception to experience the EOFException. If we would start seeing some pattern and gain experience about best values, we could then later drop the parameter and provide the "perfect default" setup.

There are multiple factors that could cause the issue (like connection pool usage), and I'm just not sure if we are fixing the symptom rather than root cause.

WDYT?

There are many ways to Rome, i guess.

  1. Actively closing each connection; Did consider this, but as HTTP 1.1 defaults to keep alive and expect that there is a higer change that one or more notifications are send shortly after eachother, i choose to stick with the (more efficient) shorter keep alive.

  2. Per request idleTimeout; also considered this, the downside is that it is more error prone / could cause regressions as each PR author has to know that this idletimeout has to be added. Thought a more defensive design would be to set it on the client and yes that would need a custom client. Similar to what @lolodomo proposed.

  3. Per configuration; Didn't think of this option, nice one, could be feasable. Not entirely sure if it would be worth the effort. Would you expect that users who experience the issue would know how to fix this without support?

Tests by @sihui62 showed that the issue was reproducable with a 5 minuten interval. I certainly don't expect this to lead to regression and or hidden issues, as that should have been shown by the performed tests.
(same applies to your options though)

I'll sleep a night on option 3 ;-)

@sihui62
Copy link
Contributor

sihui62 commented Sep 3, 2024

Did you start using the binding differently at that time

No. Although I tested the new TTL feature, it did not make it into my system as I have no usecase for it.

All tests with the test version of the binding from @lsiepel where made with the simplest way possible:

rule "pushover testing" 
when   
    Item TestPushover changed to ON
then
    val actions = getActions("pushover", "pushover:pushover-account:pushover")
    actions.sendMessage("Pushover Test simple")
end

Usually pushover is used to send me an animated gif from my door camera:

actions.sendMessage("Doorbell", "openHAB", "pushover", null, null, "/opt/openhab/conf/html/dahua1/ipcamera.gif", "image/gif", 0,"motog54", null)

I hope you will be able to help testing once again if we come up with a tweaked fix.

Sure, just shout.

@jlaur
Copy link
Contributor

jlaur commented Sep 4, 2024

3. Per configuration; Didn't think of this option, nice one, could be feasable. Not entirely sure if it would be worth the effort. Would you expect that users who experience the issue would know how to fix this without support?

No, so perhaps we could default to the 18, and let 0 keep the default idle timeout. I can't say if it's worth it, but personally I would probably use idleTimeout=0 since I never had any issues, and don't see a reason not to reuse connections. Would you expect any issues if timeout is configured to be higher than idle timeout? Since timeout is configurable already, it would be strange to have idle timeout hardcoded if the two values have any relation.

If you don't think any of this is worth to do, we can also merge it in its current state.

@lsiepel
Copy link
Contributor

lsiepel commented Sep 4, 2024

  1. Per configuration; Didn't think of this option, nice one, could be feasable. Not entirely sure if it would be worth the effort. Would you expect that users who experience the issue would know how to fix this without support?

No, so perhaps we could default to the 18, and let 0 keep the default idle timeout. I can't say if it's worth it, but personally I would probably use idleTimeout=0 since I never had any issues, and don't see a reason not to reuse connections. Would you expect any issues if timeout is configured to be higher than idle timeout? Since timeout is configurable already, it would be strange to have idle timeout hardcoded if the two values have any relation.

There is no relation, idletimeout and timeout control different parts without overlap.

If you don't think any of this is worth to do, we can also merge it in its current state.

I'll come back to this. Bit busy these days.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
10 participants