search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.56k forks source link

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

Open olflo opened 3 years ago

olflo commented 3 years ago

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

cweitkamp commented 3 years ago

Can you add some DEBUG or TRACE logs?

olflo commented 3 years ago

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 commented 3 years ago

If so, best would be both.

olflo commented 3 years ago

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 commented 3 years ago

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?

openhab-bot commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

Did you try the change in #10437?

olflo commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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

olflo commented 3 years ago

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 commented 3 years ago

Any Updates on this?

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

DUSAG0211 commented 3 years ago

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.

Hi Christoph, is the second test version already available? I am running with 4 "things" and regularly messages are not being sent out due to EofException. I am running 3.0.2 as of now.

cweitkamp commented 3 years ago

I am sorry. Did not find time to dig deeper yet. There is an ongoing PR introducing a configurable timeout which might help you too: https://github.com/openhab/openhab-addons/pull/10817.

paxb1984 commented 2 years ago

Hi! I ran into the same Problem! Some messages went out and some not. What i saw is that after a fresh reboot every message went out. But after some time when no message was sent the next message generates an EOF Exception. I observed this after i got a new Cable Modem from my Internet Provider. So i started to dig deeper. What i found out:

  1. After a fresh reboot the Binding opens a TLS Connection to api.pushover.net
  2. Trigering some Pushover Rules in OpenHAB -> Messages are all sent!
  3. Then I waited some Time and observed the Network Traffic via TCP Dump
  4. I saw that the HTTPS Connection is not closed by the Binding and there is no Traffic on this connection (Keepalives)
  5. My Cable Modem at some point Kills the Session the hard way and unfortunately not telling this to the Client (openHAB Server) via the TCP Stack
  6. The next Message which a rule want to sent will fail
  7. The Binding opens a new TLS Connection to api.pushover.net

Workaround: Triggering a "Sent Message" with Empty Content every couple of Minutes will generate some "Keepalive" Traffic on the established Connection and my Cable Modem is not Dropping the Connection!

Is it possible to implement some sort of Keepalive in the Binding or a check if an established TCP Session is "healthy"?

underdog commented 10 months ago

Still seeing this bug in openhab 4.0.2. I'm going to implement a cronjob to just hit api.pusover.net ever 2 minutes and see if this fixes the issue with messages not being sent.

I have a script (bash) that is called upon an event that is grabbing some images from cameras and sending them to pushover via curl and this script seems to always be able to connect with the API. curl is definitely more proven than the built-in pushover binding. it does appear that maybe the pushover agent fails to quickly and therefore fails to send messages.

underdog commented 10 months ago

I "fixed" the issue but basically, i'm not using the pushover addon. I wrote a generic bash script that allows me to pass parameters to it when an event occurs in openhab. I've had 100% success with pushover messages being generated. So, until this connectivity bug is fixed, i'll just roll my own solution. This is definitely a connectivity issue. I would send messages and then test my actions and they worked fine with the built-in addon. I then just let things run as usual, and no pushover messages were generated, but as soon as one pushover message is sent (via my script) all the pushover add-on messages worked.

lsiepel commented 6 months ago

Looking at the code: https://github.com/openhab/openhab-addons/blob/105ce627e7100a0c7408e4dd2769a8aacdb53bff/bundles/org.openhab.binding.pushover/src/main/java/org/openhab/binding/pushover/internal/connection/PushoverAPIConnection.java#L144

It looks like any other binding using the httpclient, nothing specific. Very similar to how Telegram and other bindings use it.

@paxb1984 i don't have detailed knowledge about the http client, but i think it is strange that the connection is not closed after the request is done and killed by the router without the httpclient knowing. I don;t think this can be fixed from the openHAB binding.

@underdog are you able to provide a debug log for this binding when this issue happens with openHAB 4.1 ?

stale[bot] commented 4 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

sihui62 commented 1 month ago

I am seeing this issue on openHAB 4.2.0.M3.

I am using the pushover binding for a couple of years now, since around 2016, but this error occurred for me the first time since these changes (adding ttl parameter) were made to the pushover binding: https://community.openhab.org/t/openhab-4-1-release-discussion/152252/20

After roundabout 5 minutes of not triggering any pushover messages the subsequent first message fails, then within the next period everything works fine, as long as some messages are triggered, but after another 5 minutes of not triggering any pushover messages the next pushover message fails again.

Inbetween I did a clean install of openHAB 4.2.0.M3 and only installed the pushover binding and a DSL rest rule, the same error occurred also on that test installation.

The following logs are from my production system.

trace.log during OH startup ``` 2024-06-04 09:41:35.854 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : BundleComponentActivator : ComponentHolder created. 2024-06-04 09:41:35.875 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : BundleComponentActivator : ComponentHolder created. 2024-06-04 09:41:35.893 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : BundleComponentActivator : ComponentHolder created. 2024-06-04 09:41:35.912 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : 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-06-04 09:41:35.932 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Component created: DS=DS13, implementation=org.openhab.binding.pushover.internal.actions.PushoverActions, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.pushover.internal.actions.PushoverActions] 2024-06-04 09:41:35.954 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Component Services: scope=prototype, services=[org.openhab.binding.pushover.internal.actions.PushoverActions] 2024-06-04 09:41:35.974 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)} 2024-06-04 09:41:35.994 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Querying state disabled 2024-06-04 09:41:36.013 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Querying state disabled 2024-06-04 09:41:36.283 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Component can not be activated since it is in state disabled 2024-06-04 09:41:36.300 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions] : Querying state disabled 2024-06-04 09:41:36.317 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Updating target filters 2024-06-04 09:41:36.335 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : No existing service listener to unregister for dependency osgi.ds.satisfying.condition 2024-06-04 09:41:36.355 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true) 2024-06-04 09:41:36.372 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : 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-06-04 09:41:36.391 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : dm osgi.ds.satisfying.condition tracker reset (closed) 2024-06-04 09:41:36.408 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : 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-06-04 09:41:36.425 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : 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-06-04 09:41:36.442 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : dm osgi.ds.satisfying.condition tracker opened 2024-06-04 09:41:36.461 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : registering service listener for dependency osgi.ds.satisfying.condition 2024-06-04 09:41:36.477 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Changed state from disabled to unsatisfiedReference 2024-06-04 09:41:36.493 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Component enabled 2024-06-04 09:41:36.513 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : ActivateInternal 2024-06-04 09:41:36.532 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Querying state unsatisfiedReference 2024-06-04 09:41:36.548 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Querying state unsatisfiedReference 2024-06-04 09:41:36.568 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Activating component from state unsatisfiedReference 2024-06-04 09:41:36.585 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Querying state unsatisfiedReference 2024-06-04 09:41:36.604 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Querying state unsatisfiedReference 2024-06-04 09:41:36.621 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Changed state from unsatisfiedReference to satisfied 2024-06-04 09:41:36.639 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : registration change queue [registered] 2024-06-04 09:41:36.657 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[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-06-04 09:41:36.674 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[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-06-04 09:41:36.691 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[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-06-04 09:41:36.710 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)} 2024-06-04 09:41:36.730 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Querying state disabled 2024-06-04 09:41:36.749 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Querying state disabled 2024-06-04 09:41:36.767 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Component can not be activated since it is in state disabled 2024-06-04 09:41:36.787 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider] : Querying state disabled 2024-06-04 09:41:36.804 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Updating target filters 2024-06-04 09:41:36.822 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : No existing service listener to unregister for dependency osgi.ds.satisfying.condition 2024-06-04 09:41:36.839 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true) 2024-06-04 09:41:36.858 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : 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-06-04 09:41:36.877 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : dm osgi.ds.satisfying.condition tracker reset (closed) 2024-06-04 09:41:36.897 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : 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-06-04 09:41:36.914 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : 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-06-04 09:41:36.933 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : dm osgi.ds.satisfying.condition tracker opened 2024-06-04 09:41:36.951 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : registering service listener for dependency osgi.ds.satisfying.condition 2024-06-04 09:41:36.973 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Changed state from disabled to unsatisfiedReference 2024-06-04 09:41:36.991 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Component enabled 2024-06-04 09:41:37.010 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : ActivateInternal 2024-06-04 09:41:37.028 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Querying state unsatisfiedReference 2024-06-04 09:41:37.049 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Querying state unsatisfiedReference 2024-06-04 09:41:37.065 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Activating component from state unsatisfiedReference 2024-06-04 09:41:37.083 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Querying state unsatisfiedReference 2024-06-04 09:41:37.102 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Querying state unsatisfiedReference 2024-06-04 09:41:37.122 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Changed state from unsatisfiedReference to satisfied 2024-06-04 09:41:37.140 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : registration change queue [registered] 2024-06-04 09:41:37.162 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : ServiceFactory.getService() 2024-06-04 09:41:37.182 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Checking constructor public org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider() 2024-06-04 09:41:37.204 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Found constructor with 0 arguments : public org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider() 2024-06-04 09:41:37.222 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : This thread collected dependencies 2024-06-04 09:41:37.240 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : getService (ServiceFactory) dependencies collected. 2024-06-04 09:41:37.260 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Querying state satisfied 2024-06-04 09:41:37.277 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : 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-06-04 09:41:37.295 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : getting activate: activate 2024-06-04 09:41:37.314 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Locating method activate in class org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider 2024-06-04 09:41:37.336 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Declared Method org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider.activate([interface org.osgi.service.component.ComponentContext]) not found 2024-06-04 09:41:37.354 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Locating method activate in class java.lang.Object 2024-06-04 09:41:37.374 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found 2024-06-04 09:41:37.393 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : activate method [activate] not found, ignoring 2024-06-04 09:41:37.414 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Changed state from satisfied to active 2024-06-04 09:41:37.433 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[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-06-04 09:41:37.452 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[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-06-04 09:41:37.469 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[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-06-04 09:41:37.488 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory] 2024-06-04 09:41:37.507 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)} 2024-06-04 09:41:37.525 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Querying state disabled 2024-06-04 09:41:37.546 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Querying state disabled 2024-06-04 09:41:37.563 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Component can not be activated since it is in state disabled 2024-06-04 09:41:37.581 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory] : Querying state disabled 2024-06-04 09:41:37.599 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Updating target filters 2024-06-04 09:41:37.619 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : No change in target property for dependency $000: currently registered: false 2024-06-04 09:41:37.635 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : No existing service listener to unregister for dependency $000 2024-06-04 09:41:37.651 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Setting target property for dependency $000 to null 2024-06-04 09:41:37.667 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : 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-06-04 09:41:37.686 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : dm $000 tracker reset (closed) 2024-06-04 09:41:37.702 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=306, service.bundleid=183, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=164} (enter) 2024-06-04 09:41:37.722 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false 2024-06-04 09:41:37.739 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=306, service.bundleid=183, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=164} (exit) 2024-06-04 09:41:37.756 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : dm $000 tracker opened 2024-06-04 09:41:37.773 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : registering service listener for dependency $000 2024-06-04 09:41:37.790 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : No existing service listener to unregister for dependency osgi.ds.satisfying.condition 2024-06-04 09:41:37.806 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true) 2024-06-04 09:41:37.822 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : 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-06-04 09:41:37.839 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : dm osgi.ds.satisfying.condition tracker reset (closed) 2024-06-04 09:41:37.857 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : 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-06-04 09:41:37.897 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : 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-06-04 09:41:37.917 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : dm osgi.ds.satisfying.condition tracker opened 2024-06-04 09:41:37.935 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : registering service listener for dependency osgi.ds.satisfying.condition 2024-06-04 09:41:37.953 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Changed state from disabled to unsatisfiedReference 2024-06-04 09:41:37.971 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Component enabled 2024-06-04 09:41:37.990 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : ActivateInternal 2024-06-04 09:41:38.006 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Querying state unsatisfiedReference 2024-06-04 09:41:38.024 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Querying state unsatisfiedReference 2024-06-04 09:41:38.042 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Activating component from state unsatisfiedReference 2024-06-04 09:41:38.061 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Querying state unsatisfiedReference 2024-06-04 09:41:38.080 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Querying state unsatisfiedReference 2024-06-04 09:41:38.098 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Changed state from unsatisfiedReference to satisfied 2024-06-04 09:41:38.116 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : registration change queue [registered] 2024-06-04 09:41:38.137 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Checking constructor public org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(org.openhab.core.io.net.http.HttpClientFactory) 2024-06-04 09:41:38.155 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.io.net.http.HttpClientFactory through loader of org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory 2024-06-04 09:41:38.174 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : getClassFromComponentClassLoader: Found class org.openhab.core.io.net.http.HttpClientFactory 2024-06-04 09:41:38.191 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Found constructor with 1 arguments : public org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(org.openhab.core.io.net.http.HttpClientFactory) 2024-06-04 09:41:38.209 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : This thread collected dependencies 2024-06-04 09:41:38.227 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : getService (single component manager) dependencies collected. 2024-06-04 09:41:38.245 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Querying state satisfied 2024-06-04 09:41:38.264 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Querying state satisfied 2024-06-04 09:41:38.282 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : 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=306, service.bundleid=183, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=164}] service: [null]]] 2024-06-04 09:41:38.300 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : 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-06-04 09:41:38.321 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : getting activate: activate 2024-06-04 09:41:38.338 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Locating method activate in class org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory 2024-06-04 09:41:38.356 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Declared Method org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found 2024-06-04 09:41:38.374 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory 2024-06-04 09:41:38.393 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext) 2024-06-04 09:41:38.411 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl] 2024-06-04 09:41:38.429 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : invoked activate: activate 2024-06-04 09:41:38.449 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Set implementation object for component 2024-06-04 09:41:38.466 [DEBUG] [ernal.factory.PushoverHandlerFactory] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.factory.PushoverHandlerFactory(301)] : Changed state from satisfied to active 2024-06-04 09:42:19.371 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : ServiceFactory.getService() 2024-06-04 09:42:19.388 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Checking constructor public org.openhab.binding.pushover.internal.actions.PushoverActions() 2024-06-04 09:42:19.406 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Found constructor with 0 arguments : public org.openhab.binding.pushover.internal.actions.PushoverActions() 2024-06-04 09:42:19.425 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : This thread collected dependencies 2024-06-04 09:42:19.441 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : getService (ServiceFactory) dependencies collected. 2024-06-04 09:42:19.457 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Querying state satisfied 2024-06-04 09:42:19.473 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : 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-06-04 09:42:19.492 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : getting activate: activate 2024-06-04 09:42:19.508 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Locating method activate in class org.openhab.binding.pushover.internal.actions.PushoverActions 2024-06-04 09:42:19.526 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Declared Method org.openhab.binding.pushover.internal.actions.PushoverActions.activate([interface org.osgi.service.component.ComponentContext]) not found 2024-06-04 09:42:19.543 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Locating method activate in class java.lang.Object 2024-06-04 09:42:19.568 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found 2024-06-04 09:42:19.585 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : activate method [activate] not found, ignoring 2024-06-04 09:42:19.606 [DEBUG] [ver.internal.actions.PushoverActions] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.actions.PushoverActions(299)] : Changed state from satisfied to active 2024-06-04 09:42:19.624 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : ServiceFactory.getService() 2024-06-04 09:42:19.641 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : This thread collected dependencies 2024-06-04 09:42:19.659 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : getService (ServiceFactory) dependencies collected. 2024-06-04 09:42:19.678 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Querying state active 2024-06-04 09:42:19.693 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : 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-06-04 09:42:19.712 [DEBUG] [.config.PushoverConfigOptionProvider] - bundle org.openhab.binding.pushover:4.2.0.M3 (302)[org.openhab.binding.pushover.internal.config.PushoverConfigOptionProvider(300)] : Changed state from active to active 2024-06-04 09:42:20.489 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/users/validate.json' 2024-06-04 09:42:20.526 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@533d17a4' 2024-06-04 09:42:21.293 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover response: status = 200, content = '{"status":1,"group":0,"devices":["motog54"],"licenses":["Android"],"request":"52636051-661b-4071-9ede-0e38b44de33d"}' 2024-06-04 09:42:48.334 [TRACE] [ver.internal.actions.PushoverActions] - ThingAction 'sendMessage' called with value(s): message='openHAB startup.rules wurde ausgeführt', title='openHAB', sound='none', url='null', urlTitle='null', attachment='null', contentType='null', priority='0', device='MotoG54', ttl='null' 2024-06-04 09:42:48.359 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json' 2024-06-04 09:42:48.393 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@213a7ace' 2024-06-04 09:42:48.690 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover response: status = 200, content = '{"status":1,"request":"91c4e100-3e54-4c6e-9b7c-8ce17ecec5b3"}' 2024-06-04 09:42:54.902 [TRACE] [ver.internal.actions.PushoverActions] - ThingAction 'sendMessage' called with value(s): message='openHAB startup.rules wurde ausgeführt', title='openHAB', sound='none', url='null', urlTitle='null', attachment='null', contentType='null', priority='0', device='MotoG54', ttl='null' 2024-06-04 09:42:54.938 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json' 2024-06-04 09:42:54.970 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@7bef8913' 2024-06-04 09:42:55.766 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover response: status = 200, content = '{"status":1,"request":"13c71a8e-8fea-48e3-bdde-c3311f206a73"}' ```
trace.log during error ``` 2024-06-04 11:22:15.968 [TRACE] [ver.internal.actions.PushoverActions] - ThingAction 'sendMessage' called with value(s): message='Regenwarnung beendet', title='openHAB', sound='none', url='null', urlTitle='null', attachment='null', contentType='null', priority='0', device='MotoG54', ttl='PT1H' 2024-06-04 11:22:16.011 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json' 2024-06-04 11:22:16.032 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@394a79c9' 2024-06-04 11:22:16.064 [DEBUG] [nal.connection.PushoverAPIConnection] - ExecutionException occurred during execution: java.io.EOFException: @7b2c6709::DecryptedEndPoint@6adf7b65{l=/192.168.2.212:53852,r=api.pushover.net/104.20.43.236:443,OPEN,fill=-,flush=-,to=5960297/0} java.util.concurrent.ExecutionException: java.io.EOFException: @7b2c6709::DecryptedEndPoint@6adf7b65{l=/192.168.2.212:53852,r=api.pushover.net/104.20.43.236:443,OPEN,fill=-,flush=-,to=5960297/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:152) ~[?:?] 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:121) ~[?:?] 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:568) ~[?:?] 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._doEvaluate(XbaseInterpreter.java:488) ~[?:?] at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:267) ~[?:?] 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._doEvaluate(XbaseInterpreter.java:492) ~[?:?] at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:267) ~[?:?] 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: @7b2c6709::DecryptedEndPoint@6adf7b65{l=/192.168.2.212:53852,r=api.pushover.net/104.20.43.236:443,OPEN,fill=-,flush=-,to=5960297/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.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?] 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 ```
sihui62 commented 3 weeks ago

I am seeing this issue on openHAB 4.2.0.M3.

@lsiepel, any ideas? Thx.