Pushover exception & return value

juelicher · February 10, 2021, 12:47pm

Hi,

I am using the Pushover binding for some time and quite extensively.

Since migrating to openHAB 3 I noticed two problems, that I have not seen in openHAB2:

Once in a while exceptions are logged

PushoverCommunicationException: org.openhab.binding.pushover.internal.connection.PushoverCommunicationException: org.eclipse.jetty.io.EofException

I am invoking the action as following:

result = actions.get("pushover", "pushover:pushover-account:my-account").sendPriorityMessage(messageText, messageTitle, messagePriority)

According to the docs, the Pushover actions, e.g. sendMessage() should return a boolean value. This too worked with openHAB 2, I could evaluate the return value and send a mail if Pushover failed.

In openHAB 3 there seems to be no such return value, only the receipt when sending high priority messages with sendPriorityMessage().

Is there anything I am doing wrong?

ralle · March 5, 2021, 7:19am

Hi @juelicher

I see the same messages in my log. At first I thought that it only happens when using the .sendPriorityMessage method, but after looking deeper into this I found out that it is logged for teh sendMessage method as well.

You are not alone

EDIT: I do get a boolean result when the message is sent out, but not when the exception occurs. I worked around this by using the following code:

try:
    result=actions.get('pushover','pushover:pushover-account:Ralph').sendMessage("abc123",'')
except:
    result=False

juelicher · March 5, 2021, 11:00am

Thanks, good to know, that I am not alone

I tried this with the version from mid January and I am pretty sure, that I got no return value. But I will try it again with the current milestone build.

ralle · March 5, 2021, 12:28pm

I’m currently on 3.1M1. I checked with

log.error(str(type(result)) + ' - ' + str(result))

and it reports True when the message is sent over pushover and nothing when the exception is spit out to the logs.

Have you investigated further into this issue by inceasing the log level for the binding? It seems to me that once a pushover is sent out successfully, subsequent pushovers are also successful.

juelicher · March 6, 2021, 1:20pm

I checked this again with 3.1 M2 and now I too get a boolean as result whenever no exception is raised. But only when using “sendMessage()”. This is probably a bug in the documentation, where it is stated " All actions return a Boolean value to indicate if the message was sent successfully or not."

Now I have set the log level to TRACE, I will report back if this gives any interesting information. But, as always when testing, currently everything works as expected

ralle · March 6, 2021, 1:53pm

I have build a workaround for this in the meantime that retries sending the Pushover notification.

I created a file action.py in the python library directory next to the core directory of the openhab-scripters library with the following contents:

from core.jsr223.scope import actions
from core.log import logging, LOG_PREFIX
log = logging.getLogger(LOG_PREFIX + ".action")
import time

def sendPushoverMessage(message,account='Ralph',prio=0):
    result=False   
    count=0
    log.error("sendMessage")
    while result == False:
        try:
            result=actions.get('pushover','pushover:pushover-account:'+account).sendPriorityMessage(message,'',prio)
            count+=1
        except:
            log.error("Pushover failed - "+ account + " - " + str(count))
        time.sleep(5)

in my rule files I added

from action import sendPushoverMessage

and replaced the actions.get call with

sendPushoverMessage('Message','account',<priority>)

only the first two arguments are mandatory, the latter ones are pre-defaulted.

So far this served me well.

juelicher · March 6, 2021, 2:43pm

Thanks for sharing this, good idea! I will adopt this, luckily I have already encapsulated sending Pushover message in my own library function.

In the meantime I found the following information in my log file:

2021-03-06 15:00:30.348 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request: POST - URL = 'https://api.pushover.net/1/messages.json'
2021-03-06 15:00:30.350 [TRACE] [nal.connection.PushoverAPIConnection] - Pushover request body: 'org.eclipse.jetty.client.util.MultiPartContentProvider@6753ce04'
2021-03-06 15:00:30.364 [DEBUG] [nal.connection.PushoverAPIConnection] - Exception occurred during execution: java.io.EOFException: HttpConnectionOverHTTP@58b1280c::DecryptedEndPoint@65152ed5{api.pushover.net/104.20.124.71:443<->/192.168.10.50:51982,CLOSED,fill=-,flush=W,to=627073/0}
java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@58b1280c::DecryptedEndPoint@65152ed5{api.pushover.net/104.20.124.71:443<->/192.168.10.50:51982,CLOSED,fill=-,flush=W,to=627073/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.sendPriorityMessage(PushoverAPIConnection.java:83) [bundleFile:?]
	at org.openhab.binding.pushover.internal.handler.PushoverAccountHandler.sendPriorityMessage(PushoverAccountHandler.java:145) [bundleFile:?]
	at org.openhab.binding.pushover.internal.actions.PushoverActions.sendPriorityMessage(PushoverActions.java:146) [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.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:190) [bundleFile:?]
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:208) [bundleFile:?]
	at org.python.core.PyObject.__call__(PyObject.java:512) [bundleFile:?]
	at org.python.core.PyObject.__call__(PyObject.java:517) [bundleFile:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:171) [bundleFile:?]
	at personal.mylib$py.push_pushover$22(/etc/openhab/automation/lib/python/personal/mylib.py:217) [bundleFile:?]
	at personal.mylib$py.call_function(/etc/openhab/automation/lib/python/personal/mylib.py) [bundleFile:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:173) [bundleFile:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:168) [bundleFile:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:437) [bundleFile:?]
	at personal.mylib$py.notifyMe$23(/etc/openhab/automation/lib/python/personal/mylib.py:238) [bundleFile:?]
	at personal.mylib$py.call_function(/etc/openhab/automation/lib/python/personal/mylib.py) [bundleFile:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:173) [bundleFile:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:306) [bundleFile:?]
	at org.python.core.PyFunction.function___call__(PyFunction.java:474) [bundleFile:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:469) [bundleFile:?]
	at org.python.pycode._pyx101.notifyHunidityLow$1(<script>:55) [bundleFile:?]
	at org.python.pycode._pyx101.call_function(<script>) [bundleFile:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:173) [bundleFile:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:134) [bundleFile:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:416) [bundleFile:?]
	at core.rules$py.execute$6(/etc/openhab/automation/lib/python/core/rules.py:108) [bundleFile:?]
	at core.rules$py.call_function(/etc/openhab/automation/lib/python/core/rules.py) [bundleFile:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:173) [bundleFile:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:306) [bundleFile:?]
	at org.python.core.PyFunction.function___call__(PyFunction.java:474) [bundleFile:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:469) [bundleFile:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:464) [bundleFile:?]
	at org.python.core.PyObject._callextra(PyObject.java:589) [bundleFile:?]
	at core.log$py.wrapper$7(/etc/openhab/automation/lib/python/core/log.py:114) [bundleFile:?]
	at core.log$py.call_function(/etc/openhab/automation/lib/python/core/log.py) [bundleFile:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:173) [bundleFile:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:306) [bundleFile:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:197) [bundleFile:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:485) [bundleFile:?]
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237) [bundleFile:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:228) [bundleFile:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:218) [bundleFile:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:213) [bundleFile:?]
	at org.python.core.PyObject._jcallexc(PyObject.java:3565) [bundleFile:?]
	at org.python.core.PyObject._jcall(PyObject.java:3598) [bundleFile:?]
	at org.python.proxies.core.rules$_FunctionRule$213.execute(Unknown Source) [bundleFile:?]
	at org.openhab.core.automation.module.script.rulesupport.shared.simple.SimpleRuleActionHandlerDelegate.execute(SimpleRuleActionHandlerDelegate.java:34) [bundleFile:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.delegates.SimpleActionHandlerDelegate.execute(SimpleActionHandlerDelegate.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@58b1280c::DecryptedEndPoint@65152ed5{api.pushover.net/104.20.124.71:443<->/192.168.10.50:51982,CLOSED,fill=-,flush=W,to=627073/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-06 15:00:30.404 [WARN ] [org.openhab.core.automation.mylib.py] - Pushover failed with exception:

The last line is from my own function.

ralle · March 7, 2021, 10:12am

Are you running openHAB natively on the system or in a container?

I use the alpine variant of the docker container.

juelicher · March 7, 2021, 3:30pm

My main system is a native Debian 10 installation, in addition I have a VMWare Debian 10 test system.

ralle · March 7, 2021, 3:35pm

So it’s not docker-related. Maybe it’s time to open a github issue for this?

juelicher · March 7, 2021, 5:39pm

It is a bit strange, that we seem to be the only ones with this problem.

cypresss · March 14, 2021, 1:33pm

+1

Hello everyone,
I do have the same errors from time to time.
It appears very randomly and no message is sent in the event of an error.

I hope this will be solved in a future release!

cypresss · March 18, 2021, 2:26pm

Any Updates on this?
Did someone open an issue on github already?

To be precise:
Very randomly 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 rule works like a charm for multiple times.
Very strange!

ralle · March 19, 2021, 12:09pm

No I didn’t open an issue yet. Feel free to do so. Unfortunately I don’t have time at the moment to do it myself.

cypresss · April 2, 2021, 9:57am

Just to let you know:

system · May 14, 2021, 1:57am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.