action taking place only on the second time i ask to do it #671
Comments
|
What version are you running? |
|
sorry, im running 4.5.5 i just updated it thought maybe it will solve the problem. i had the same issue on 4.5 |
|
i have the same issur as #605 had. but i dont run anything else.. |
|
i put my com.bwssystems.HABridge.plugins.http.HTTPHandler on debug
all logs are from com.bwssystems.HABridge.plugins.http.HTTPHandler |
|
So, when you issue the call the second time, it works, is that correct? Also, you are using home assistant as the target? |
|
yes, the second time the my command work. It doesn't happen on every command and I can't tell you how often. |
|
Will test again on my setup |
|
thank you! |
|
have similar problem. it happens sometimes not always |
|
@yjon1 are you using home assistant over ssl? |
|
no, http on same pi server, defined as 127.0.0.1:8123 |
|
@pickeld Do you have this issue if you do not use https? |
|
I tried to debug it (remote app) but there is nothing more than: Anyway, I was able to fix it in very ugly way: retry request in HtppHandler when exception occurs... |
|
@yjon1 please share your solution. the fact i need to ask everything twice makes habridge pretty much useless for me right now.. i need a fix please |
|
sure, try attached jar |
|
@yjon1 seems like it fixed the issue, but as you said, its more a workaround then a fix... |
|
Adding the ClientProtocolException into the retry loop |
|
Adding it to the retry loop results a delay on every failed action. We must understand the cause. |
|
Please turn on debug and post the results. The one error dump does not give enough info |
|
sure, for what component? root only? or all of them? |
|
let's do huemulator, http, HomeAssistant |
|
` 06-20-2017 18:45:41.037 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:45:41.057 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:45:42.301 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:45:42.323 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:45:49.118 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:45:49.127 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:45:59.816 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:45:59.833 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:10.250 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:18.771 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:18.789 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:31.680 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:31.702 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:33.099 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:33.107 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:36.979 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 18:46:37.009 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
|
|
I see the very first call to Home Assistant gets the error. After that, it works as expected. Very interesting. |
|
here is another one: 06-20-2017 20:05:07.450 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:07.458 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:10.178 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:10.200 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:10.697 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:43.820 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:43.828 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:46.903 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:46.935 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:51.811 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:51.851 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:55.844 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:05:55.863 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:06:01.015 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:06:01.032 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:06:03.174 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:06:03.192 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:06:10.725 DEBUG isSSDPDiscovery found message to be valid under strict rules - strict: true com.bwssystems.HABridge.upnp.UpnpListener
06-20-2017 20:06:13.879 DEBUG Sending notify packet for upnp. com.bwssystems.HABridge.upnp.UpnpListener 06-20-2017 20:06:14.930 DEBUG httpMethod:get, uri: / spark.webserver.MatcherFilter 06-20-2017 20:06:16.040 DEBUG httpMethod:get, uri: /js/rzslider.min.js spark.webserver.MatcherFilter 06-20-2017 20:06:17.854 DEBUG httpMethod:get, uri: /js/bootstrap.min.js spark.webserver.MatcherFilter |
|
As I asked before, have you tried this when Home Assistant is just on port 8123 without https? Also, how is your setup to get Home Assistant with https? It seems the config for this could be causing this issue and that's why I need you to validate with http to port 8123. Thanks |
|
Hello All, I'm fairly new to ha-bridge but I;m having the same issue |
|
So I can fix this with: But that's a deprecated method in 4.4. Using the PoolingHttpClientConnectionManager didn't work in my testing, not even with setValidateAfterInactivity(1). |
|
I still see this issue in 4.5.6 and HA 0.48.0. |
|
I will try to set cronjob to wget the URL http:https://127.0.0.1/api/devices/hass/devices every minute and see whether this helps. |
|
Hi all, i tested the workaround below and it works perfectly. I got 100% success command without retry today . Below is the content in /etc/crontab, running with Ubuntu Xenial. I think it suits any linux based machine. The idea is perform a wget until receive HTTP 200 with retry interval of 5 seconds, periodically every minute.
|
|
Yea, that'd do it as well by keeping the Keep-Alive connection, well, alive. The diff I provided above while using a deprecated method works well without needing to constantly generate a HTTP request to HASS via ha-bridge. |
|
@bwssytems Could we get this issue re-opened? It seems to have a clear solution albeit using a deprecated method and a possible future method that /should/ work but doesn't (PoolingHttpClientConnectionManager) so it could use further investigation on that front also. |
|
Hmm, don't know why I closed this either... re-opening |
|
Same problem. The UI claims it got back a 500 from HASS, but I don't see it logged even with debug. |
|
tried to use the below: |
|
@jasoni81 , is your HA-Bridge running on port 80 ? I think either user is fine since it uses wget and without writing to any file. |
|
@kykean thanks for the reply, yes it is running on port 80. I believe I have now managed to resolve it. The cron was throwing the error: So I modified two things, one was the IP address of the HASS server, (same as where the HA bridge is running), and also removed the 'root' from the cron entry 👍
Now my mailog entry is showing the below so it looks good. Need to test futher: Where I wasnt understanding this, and for others, is that you when i manually was running the URL in the broswer, teh first time it would fail, and only on the subsequent refreshes, would it return the entities. I wasnt quite understanding this at first. |
|
Im experiencing the same issue here, where intermittently commands have to be repeated. I'll trial @jasoni81 workaround to see if it helps keeps the connection alive. |
|
I don't find the workaround helps |
|
I agree. The work around is not working for me. |
|
My jar file which works for me (with the fix/patch I described previously) is here: https://transfer.sh/HkjzD/ha-bridge-4.5.6-fix671.jar |
|
I will add the stale connection into the http handler. |
|
Hi there, |
|
Hi all Fwiw I have the same issue on 4.5.6 and ha 0.54 and as a workaround jasoni81's crontab entry worked for me. */1 * * * * while true; do sleep 5; wget --server-response -q http:https://192.168.2.17/api/devices/hass/devices 2>&1 | grep 200 && break; done; Thanks buddy. George EDIT: issue is back this morning :/ |
|
@bwssytems Any update on this issue? |
|
@felixbouleau, joining your question, |
|
The release candidate that is out there has this fix. Please try it and see if that helps #735 |
|
@bwssytems Thanks! I still have issues but after some log grepping I found this in my home-assistant logs: So Home Assistant is (for some reason) reacting to a I will keep looking into this when I get time and report on the Home Assistant community instead. I will also keep using the RC and let you know if I run into any other issues. |
hey guys. its pretty hard for me to explain whats wrong. but something is defiantly worng.
each time i want to control my device (using google home and home assistant) i have to ask it twice even-tho i get a positive feedback from google home.
how can i solve the problem?
seaching the log file i ran into this (/var/log/syslog):
Jun 14 17:39:28 habridge java[5326]: Caused by: org.apache.http.ProtocolException: The server failed to respond with a valid HTTP responseand
Jun 14 18:00:31 habridge java[5326]: 2017-06-14 18:00:31,062 [qtp19678540-59] WARN com.bwssystems.HABridge.plugins.http.HTTPHandler - Error calling out to HA gateway: IOException in log Jun 14 18:00:31 habridge java[5326]: org.apache.http.client.ClientProtocolException: null Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:186) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107) Jun 14 18:00:31 habridge java[5326]: at com.bwssystems.HABridge.plugins.http.HTTPHandler.doHttpRequest(HTTPHandler.java:87) Jun 14 18:00:31 habridge java[5326]: at com.bwssystems.HABridge.plugins.hass.HomeAssistant.callCommand(HomeAssistant.java:71) Jun 14 18:00:31 habridge java[5326]: at com.bwssystems.HABridge.plugins.hass.HassHome.deviceHandler(HassHome.java:144) Jun 14 18:00:31 habridge java[5326]: at com.bwssystems.HABridge.hue.HueMulator.changeState(HueMulator.java:997) Jun 14 18:00:31 habridge java[5326]: at com.bwssystems.HABridge.hue.HueMulator.lambda$37(HueMulator.java:420) Jun 14 18:00:31 habridge java[5326]: at spark.RouteImpl$1.handle(RouteImpl.java:58) Jun 14 18:00:31 habridge java[5326]: at spark.webserver.MatcherFilter.doFilter(MatcherFilter.java:162) Jun 14 18:00:31 habridge java[5326]: at spark.webserver.JettyHandler.doHandle(JettyHandler.java:61) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:189) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.server.Server.handle(Server.java:517) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:302) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:245) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654) Jun 14 18:00:31 habridge java[5326]: at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572) Jun 14 18:00:31 habridge java[5326]: at java.lang.Thread.run(Thread.java:748) Jun 14 18:00:31 habridge java[5326]: Caused by: org.apache.http.ProtocolException: The server failed to respond with a valid HTTP response Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:151) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:261) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:165) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:167) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:271) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) Jun 14 18:00:31 habridge java[5326]: at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184) Jun 14 18:00:31 habridge java[5326]: ... 25 common frames omittedThe text was updated successfully, but these errors were encountered: