ok, unavailble state occured again,
below full log, you also see at the same time that my vacuum cleaner is also unavaible, not sure its related 
Excellent, thank you.
So based on the log files a disconnect was received for the web socket. At that time went for reconnecting. It initiated the connection at 21:50:23 and then nothing. Thus it seems to just be āhangingā there then.
Looks like at 21:50:33 your automation kicks in for running sync. It notices that another connection is already in progress (Waiting for other connect). However, that check seems to then have ākick-startedā the other connect as 1 second later the listener is started (and thus the connection was successful).
I do not fully understand why as there is nothing in my code that would do that ākickstartā based on my understanding on how aiohttp works.
I did make some changes for the reconnection and pushed out as version 0.1.10.
Change mainly is that weāre now going to absolutely sure that both web socket and connection pool are closed and gone when getting disconnection before trying to reconnect. That will then ensure everything is setup again.
If you can update in remote.py the version to 0.1.10, keep debug logs on.
Looks like weāve at least got the connection a lot more stable now compared to before. Hoping that with this latest change if a disconnect happens, the reconnect works. Idea is that if connection is lost, reconnect happens and done. No unavailable state or so as the reconnect can happen in a second or 2, well before entity would go to unavailable state.
Feel like weāre getting closed to fix this, the XMPP might just take a bit longer due to the issue between the library and Home Assistant.
ok!
0.1.10 running and debug on
1 Like
btw, can i see in the debug the disconnects? normally i had them like 4-5 times a day
maybe its usefull for you , if a reconnect is logged before my automation kicks in?
You would be able to see the disconnects.
Following 2 lines are indicative that a disconnect occurred:
2019-03-20 21:50:23 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Listener stopped.
2019-03-20 21:50:23 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connection closed, reconnecting
ok, next time i need to restart my config, i will lookout for those lines
had a new disconnect, log here
2019-03-23 17:11:54 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Response payload: None
2019-03-23 17:11:54 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Web socket closed
2019-03-23 17:11:54 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Listener stopped.
2019-03-23 17:11:54 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connection closed, reconnecting
2019-03-23 17:11:54 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Closing sessions
2019-03-23 17:11:54 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Starting connect.
2019-03-23 17:11:54 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connecting for hub 10271701
2019-03-23 17:12:04 DEBUG (MainThread) [aioharmony.responsehandler] Registering handler sync with UUID 9b2d2b2d-5719-44eb-9820-cce523318d67 that will expire on 2019-03-23 17:13:04.328301+01:00
2019-03-23 17:12:04 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Waiting for other connect
2019-03-23 17:12:25 ERROR (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connection timed out for hub 10271701
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Starting connect.
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connecting for hub 10271701
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Sending payload: {'hubId': 10271701, 'timeout': 30, 'hbus': {'cmd': 'setup.sync?None', 'id': 'ff45db52-0b33-45d7-8984-0265296c4ac9', 'params': {'verb': 'get', 'format': 'json'}}}
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Listener started
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.hubconnector] 192.168.0.21: Response payload: {"type":"connect.stateDigest?notify","data":{"sleepTimerId":-1,"runningZoneList":[],"sequence":false,"activityId":"25425467","errorCode":"200","syncStatus":1,"discoveryServer":"https:\/\/svcs.myharmony.com\/Discovery\/Discovery.svc","stateVersion":587,"tzOffset":"3600","mode":3,"hubSwVersion":"4.15.250","deviceSetupState":[],"tzoffset":"3600","isSetupComplete":true,"configVersion":217,"time":1553341476,"activitySetupState":false,"wifiStatus":1,"activityStatus":2,"runningActivityList":"25425467","tz":"CET-1CEST,M3.5.0,M10.4.0\/3","updates":{"100":"4.14.112","97":"4.14.112"},"contentVersion":144,"hubUpdate":false,"discoveryServerCF":"https:\/\/cf-svcs.myharmony.com\/Discovery\/Discovery.svc","accountId":"6630584"}}
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.responsehandler] Message received: {'type': 'connect.stateDigest?notify', 'data': {'sleepTimerId': -1, 'runningZoneList': [], 'sequence': False, 'activityId': '25425467', 'errorCode': '200', 'syncStatus': 1, 'discoveryServer': 'https://svcs.myharmony.com/Discovery/Discovery.svc', 'stateVersion': 587, 'tzOffset': '3600', 'mode': 3, 'hubSwVersion': '4.15.250', 'deviceSetupState': [], 'tzoffset': '3600', 'isSetupComplete': True, 'configVersion': 217, 'time': 1553341476, 'activitySetupState': False, 'wifiStatus': 1, 'activityStatus': 2, 'runningActivityList': '25425467', 'tz': 'CET-1CEST,M3.5.0,M10.4.0/3', 'updates': {'100': '4.14.112', '97': '4.14.112'}, 'contentVersion': 144, 'hubUpdate': False, 'discoveryServerCF': 'https://cf-svcs.myharmony.com/Discovery/Discovery.svc', 'accountId': '6630584'}}
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.responsehandler] No match for handler Activity_Changed
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.responsehandler] Match for Notification_Received
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.responsehandler] No match on msgid for sync
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.responsehandler] Checking for expired handlers
2019-03-23 17:12:25 DEBUG (MainThread) [aioharmony.harmonyclient] 192.168.0.21: Notification was receivedThis one is already much better. You can see at 17:12:25 (pretty much 30 seconds after connection started) we get a timeout.
Just pushed 0.1.11 that does:
- Sleep for 1 second before trying reconnects.
- Changed timeout to 5 seconds for network activity from 30 seconds.
Letās see how this does.
ok .11 up and running
edig: 2019-03-24 09:19:45 ERROR (SyncWorker_2) [homeassistant.util.package] Unable to install package aioharmony==0.1.11: Could not find a version that satisfies the requirement aioharmony==0.1.11 (from versions: 0.1.0, 0.1.1, 0.1.2, 0.1.3, 0.1.4, 0.1.5, 0.1.6, 0.1.7, 0.1.8, 0.1.9, 0.1.10)
No matching distribution found for aioharmony==0.1.11
sems it doesnt run?
Sorry,
Forgot to upload it to pypi. Just uploaded it so is available now.
np
up and running now
1 Like
still want debug enabled on my side? i had no issues anymore with latest lib
my automation didnt run anymore
Nope, thank you. Iāll be updating version on pypi for aioharmony then with these changes, and then get the PR update for HA. At least web sockets is working better then while I get the fixes for XMPP in
cool, thnx
had some timeouts today 
and debug was off
2019-04-04 07:54:40 ERROR (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connection timed out for hub 10271701
2019-04-04 07:54:53 ERROR (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connection timed out for hub 10271701
2019-04-04 08:15:40 ERROR (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connection timed out for hub 10271701
2019-04-04 08:15:52 ERROR (MainThread) [aioharmony.hubconnector] 192.168.0.21: Connection timed out for hub 10271701
Did it reconnect? Based on the log entries it seems to me that it would have since we only report the connection timeout once with ERROR (all other times it is only reported on DEBUG).
It times out if unable to connect after 5 seconds, then it will wait for 1 seconds and try again. The time it will wait in between retries is doubled with a maximum of 30 seconds.
Well, thatās something I donāt know, itās my automation that does the reconnectionā¦ In my automation i do a sync, then it reconnects
I can change my automation, so I receive the notification when hub is disconnected, but without the reconnect service
If you could do that and re-enable debug.
it is not the sync in itself that does it. For every call done there is a check done if weāre connected and if not connected it will connect. Thus when you call sync it finds it is not connected and then tries a connect.
Now only 1 task can connect at a time, and the reconnect is already doing that. But when the reconnect times out and goes for a wait, the call for sync can try to do a connect.
This is why I changed like timeout and wait times to initially be more aggressive when trying to reconnect.