home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.66k stars 29.95k forks source link

Ambient Weather Station websocket error #28559

Closed collinsjoshw closed 4 years ago

collinsjoshw commented 4 years ago

Home Assistant release with the issue: 0.101.2

Last working Home Assistant release (if known):

Operating environment (Hass.io/Docker/Windows/etc.): Hass.io on RPi 3

Integration: Ambient Weather Station Sensor https://www.home-assistant.io/integrations/ambient_station/

Description of problem: home-assistant.log output:

2019-11-05 08:00:41 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
2019-11-05 08:00:41 ERROR (MainThread) [homeassistant.components.ambient_station] Error with the websocket connection: Connection error

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant): N/A - configured via integrations page

Traceback (if applicable):

2019-11-05 08:00:41 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiohttp/connector.py", line 830, in _resolve_host
    self._resolver.resolve(host, port, family=self._family)
  File "/usr/local/lib/python3.7/site-packages/aiohttp/resolver.py", line 30, in resolve
    host, port, type=socket.SOCK_STREAM, family=family)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 784, in getaddrinfo
    None, getaddr_func, host, port, family, type, proto, flags)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/socket.py", line 748, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -3] Try again
2019-11-05 08:00:41 ERROR (MainThread) [homeassistant.components.ambient_station] Error with the websocket connection: Connection error

Additional information: This has been happening occasionally for a few releases, but now the integration won't connect at all. It tries to connect upon home assistant starting and doesn't attempt again.

probot-home-assistant[bot] commented 4 years ago

Hey there @bachya, mind taking a look at this issue as its been labeled with a integration (ambient_station) you are listed as a codeowner for? Thanks!

bachya commented 4 years ago

Could you tell me what versions of python-socketio and python-engineio you have? Instructions for how to do this in Hass.io can be found starting here: https://github.com/home-assistant/home-assistant/issues/24509#issuecomment-517512537

collinsjoshw commented 4 years ago

Could you tell me what versions of python-socketio and python-engineio you have? Instructions for how to do this in Hass.io can be found starting here: #24509 (comment)

I am running Hassos 2.12. Unfamiliar with the commands, so fumbling through finding that information.

collinsjoshw commented 4 years ago

Could you tell me what versions of python-socketio and python-engineio you have? Instructions for how to do this in Hass.io can be found starting here: #24509 (comment)

I am running Hassos 2.12. Unfamiliar with the commands, so fumbling through finding that information.

According to the Hassos github...

PYTHON_ENGINEIO_VERSION = 3.3.0 PYTHON_SOCKETIO_VERSION = 1.4.1

bachya commented 4 years ago

If that's the case, they're way out of date. You should have a python-engineio of at least 3.9.3 and a python-socketio of at least 4.3.1.

harfordhawk commented 4 years ago

this is the same error I have had for the past few versions of homeassistant.

I have to manually reinstall ambient each time I reboot

I have PYTHON_ENGINEIO_VERSION = 3.10.0 PYTHON_SOCKETIO_VERSION = 4.3.1

I had reached out to you by email. Anyway I was hoping the latest version of HA might cure it but no luck. please help if you can

bachya commented 4 years ago

@harfordhawk I recall our email conversation; I had asked you to open up a bug. I don’t think I ever saw one come through, so we can use this one.

Are you also using HassOS?

harfordhawk commented 4 years ago

yes Hostname hassio System HassOS 2.12 Deployment production

supervisor Version | 192

Latest version | 192

collinsjoshw commented 4 years ago

this is the same error I have had for the past few versions of homeassistant.

I have to manually reinstall ambient each time I reboot

I have PYTHON_ENGINEIO_VERSION = 3.10.0 PYTHON_SOCKETIO_VERSION = 4.3.1

I had reached out to you by email. Anyway I was hoping the latest version of HA might cure it but no luck. please help if you can

Where did you find this information? We are running the same version and supervisor, so I'm assuming the information I took from the github is wrong/out of date.

I was able to remove and add the integration successfully and the data is back. No reboots since.

harfordhawk commented 4 years ago

this is the same error I have had for the past few versions of homeassistant. I have to manually reinstall ambient each time I reboot I have PYTHON_ENGINEIO_VERSION = 3.10.0 PYTHON_SOCKETIO_VERSION = 4.3.1 I had reached out to you by email. Anyway I was hoping the latest version of HA might cure it but no luck. please help if you can

Where did you find this information? We are running the same version and supervisor, so I'm assuming the information I took from the github is wrong/out of date.

I was able to remove and add the integration successfully and the data is back. No reboots since.

I followed instructions at https://github.com/home-assistant/home-assistant/issues/24509#issuecomment-517512537

bachya commented 4 years ago

@harfordhawk If this has been happening regularly, do you see any indication in the logs? What happens when it occurs? (do entities disappear? stop updating their values?) Have you had any network events (e.g., internet outages) that might correspond to outages?

Since I have not been able to reproduce this, every level of detail – no matter how small – will help the debugging process.

collinsjoshw commented 4 years ago

@bachya When it occurs for me, after the restarting home assistant, the sensors are empty. They show unknown. On the integrations pages, there are no sensors listed under the Ambient integration. The only error that surfaces for me in home-assistant.log is the one included with this issue.

harfordhawk commented 4 years ago

@harfordhawk If this has been happening regularly, do you see any indication in the logs? What happens when it occurs? (do entities disappear? stop updating their values?) Have you had any network events (e.g., internet outages) that might correspond to outages?

Since I have not been able to reproduce this, every level of detail – no matter how small – will help the debugging process.

just rebooted... this is the only error I see ERROR (MainThread) [homeassistant.components.ambient_station] Error with the websocket connection: Connection error

no internet problems, etc and same as jccshmny says above, the sensors just show as unknown

I have tried both using the config file to integrate ambient and also I have tried removing from config file and using the integrations page. nothing sticks for me

I should say I have also went to ambient and created new app key and api just to see if that made any difference and of course it did not change anything

harfordhawk commented 4 years ago

I can create a custom component if you have any thoughts on a test or something. just send me the replacement file. I will be out of town for a few days though

bachya commented 4 years ago

@harfordhawk Understood. The challenge with connection errors is that they almost always relate to the underlying libraries I'm using (python-socketio and python-engineio) – hence why I was asking for versions.

Let me noodle on this. We will get it solved! Appreciate your patience.

bachya commented 4 years ago

@harfordhawk @jccshmny I traced the reported error you from my library back to python-socketio and came across some relevant-looking code in version 4.3.1:

try:
    await self.connect(self.connection_url,
                       headers=self.connection_headers,
                       transports=self.connection_transports,
                       namespaces=self.connection_namespaces,
                       socketio_path=self.socketio_path)
except (exceptions.ConnectionError, ValueError):
    pass
else:
    self.logger.info('Reconnection successful')
    self._reconnect_task = None
    break
if self.reconnection_attempts and \
        attempt_count >= self.reconnection_attempts:
    self.logger.info(
        'Maximum reconnection attempts reached, giving up')
    break

As I read it, here's the flow:

  1. Attempt to connect to the websocket (i.e., the Ambient Weather API's websocket)
  2. If the connection operation has a ConnectionError (which, although I can't prove it, seems connected to the error you're seeing), try again after an ever-increasing delay (and up to a maximum number of retries)
  3. If the connection succeeds at any point, log an INFO-level log that says "Reconnection successful"
  4. If the connection reaches its maximum number of retries with all failures, log an INFO-level log that says "Maximum reconnection attempts reached, giving up"

So, this gives me a couple different ideas.

Idea 1: Test the Library Directly

It might be worthwhile to see whether you can access the Ambient Weather websocket API at all. Fortunately, I have a script that can help you do that.

In a terminal, clone aioambient:

$ git clone https://github.com/bachya/aioambient.git
$ cd aioambient/

Initialize the dev environment:

$ make init

(FYI, the only reason that command would fail is if you don't have Python3 installed.)

Open example_websocket.py in a text editor and add your API/App keys to lines 12 and 13:

API_KEY = "<YOUR API KEY>"
APP_KEY = "<YOUR APPLICATION KEY>"

Save the file and close your text editor. Back in your terminal, run example_websocket.py:

$ pipenv run python3 example_websocket.py

If this works, you should see output that looks like the following (and you can move onto Idea 2):

$ pipenv run python3 example_websocket.py
INFO:engineio.client:Attempting WebSocket connection to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=<YOUR APPLICATION KEY>&transport=websocket&EIO=3
INFO:engineio.client:WebSocket connection accepted with {'sid': 'xxxxxxxxxxxxxxx', 'upgrades': [], 'pingInterval': 25000, 'pingTimeout': 60000}
INFO:socketio.client:Engine.IO connection established
INFO:root:Simulating some other task occurring...
INFO:engineio.client:Sending packet PING data None
INFO:engineio.client:Received packet MESSAGE data 0
INFO:socketio.client:Namespace / is connected
INFO:socketio.client:Emitting event "subscribe" [/]
INFO:engineio.client:Sending packet MESSAGE data 2["subscribe",{"apiKeys":["<YOUR API KEY>"]}]
INFO:root:Client has connected to the websocket
INFO:engineio.client:Received packet PONG data None
INFO:engineio.client:Received packet MESSAGE data 2["subscribed",{"devices":[{"macAddress":"12:34:56:AB:CD:EF","lastData":{"dateutc":1573150080000,"winddir":335,"windspeedmph":1.1,"windgustmph":1.1,"maxdailygust":4.5,"tempf":46.8,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0.01,"weeklyrainin":0.01,"monthlyrainin":0.07,"totalrainin":11.3,"baromrelin":30.58,"baromabsin":25.09,"humidity":57,"tempinf":86.2,"humidityin":21,"uv":2,"solarradiation":212.49,"feelsLike":46.8,"dewPoint":32.38,"feelsLikein":83.1,"dewPointin":41.7,"lastRain":"2019-11-07T15:48:00.000Z","deviceId":"xxxxxxxxxxxxxxxxxxxxxxxxx","tz":"YOUR/TZ","date":"2019-11-07T18:08:00.000Z"},"info":{"name":"Side Yard","location":"Home"},"apiKey":"<YOUR API KEY>"}],"method":"subscribe"}]
INFO:socketio.client:Received event "subscribed" [/]
INFO:root:Data received: {'devices': [{'macAddress': '12:34:56:AB:CD:EF', 'lastData': {'dateutc': 1573150080000, 'winddir': 335, 'windspeedmph': 1.1, 'windgustmph': 1.1, 'maxdailygust': 4.5, 'tempf': 46.8, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0.01, 'weeklyrainin': 0.01, 'monthlyrainin': 0.07, 'totalrainin': 11.3, 'baromrelin': 30.58, 'baromabsin': 25.09, 'humidity': 57, 'tempinf': 86.2, 'humidityin': 21, 'uv': 2, 'solarradiation': 212.49, 'feelsLike': 46.8, 'dewPoint': 32.38, 'feelsLikein': 83.1, 'dewPointin': 41.7, 'lastRain': '2019-11-07T15:48:00.000Z', 'deviceId': 'xxxxxxxxxxxxxxxxxxxxxxxxx', 'tz': 'YOUR/TZ', 'date': '2019-11-07T18:08:00.000Z'}, 'info': {'name': 'Side Yard', 'location': 'Home'}, 'apiKey': '<YOUR API KEY>'}], 'method': 'subscribe'}
INFO:engineio.client:Received packet MESSAGE data 2["data",{"dateutc":1573150140000,"winddir":337,"windspeedmph":2.2,"windgustmph":2.2,"maxdailygust":4.5,"tempf":45.9,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0.01,"weeklyrainin":0.01,"monthlyrainin":0.07,"totalrainin":11.3,"baromrelin":30.58,"baromabsin":25.09,"humidity":60,"tempinf":86.2,"humidityin":21,"uv":2,"solarradiation":211.15,"feelsLike":45.9,"dewPoint":32.81,"feelsLikein":83.1,"dewPointin":41.7,"lastRain":"2019-11-07T15:48:00.000Z","tz":"YOUR/TZ","date":"2019-11-07T18:09:00.000Z","macAddress":"12:34:56:AB:CD:EF"}]
INFO:socketio.client:Received event "data" [/]
INFO:root:Data received: {'dateutc': 1573150140000, 'winddir': 337, 'windspeedmph': 2.2, 'windgustmph': 2.2, 'maxdailygust': 4.5, 'tempf': 45.9, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0.01, 'weeklyrainin': 0.01, 'monthlyrainin': 0.07, 'totalrainin': 11.3, 'baromrelin': 30.58, 'baromabsin': 25.09, 'humidity': 60, 'tempinf': 86.2, 'humidityin': 21, 'uv': 2, 'solarradiation': 211.15, 'feelsLike': 45.9, 'dewPoint': 32.81, 'feelsLikein': 83.1, 'dewPointin': 41.7, 'lastRain': '2019-11-07T15:48:00.000Z', 'tz': 'YOUR/TZ', 'date': '2019-11-07T18:09:00.000Z', 'macAddress': '12:34:56:AB:CD:EF'}

If this doesn't work, you'll see a familiar error:

$ pipenv run python3 example_websocket.py
INFO:engineio.client:Attempting WebSocket connection to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=<YOUR APPLICATION KEY>&transport=websocket&EIO=3
ERROR:root:There was a websocket error: Connection error

...and we can assume that there's a problem with either your API key or your APP key.

Idea 2: Increase the HASS Log Level for ambient_station

If we have verified that aioambient works as expected, let's see if we can get the expected log messages in HASS.

Change the log level for ambient_station in your configuration.yaml:

logger:
  default: warning
  logs:
    homeassistant.components.ambient_station: info

Restart HASS and let it run a while (even an hour should be good enough). Then, paste back here any log entries related to:

There will be a lot of them, but if you can paste these (and only these) in the order they came in, we'll be able to analyze together.

Thanks for your help! Let me know how you get on.

harfordhawk commented 4 years ago

I can't run make

i am in hassio so I can't ssh in using putty ( at least I don't know how) I use the addons for ssh. That I guess limits what I can do I even turned off protection mode in addon but still no lusk running make

On Thu, Nov 7, 2019 at 1:21 PM Aaron Bach notifications@github.com wrote:

@harfordhawk https://github.com/harfordhawk @jccshmny https://github.com/jccshmny I traced the reported error you from my library back to python-socketio and came across some relevant-looking code https://github.com/miguelgrinberg/python-socketio/blob/7c32b379aeeafdb4d6e24e8695734c985753a9d7/socketio/asyncio_client.py#L400-L416 in version 4.3.1:

try: await self.connect(self.connection_url, headers=self.connection_headers, transports=self.connection_transports, namespaces=self.connection_namespaces, socketio_path=self.socketio_path)except (exceptions.ConnectionError, ValueError): passelse: self.logger.info('Reconnection successful') self._reconnect_task = None breakif self.reconnection_attempts and \ attempt_count >= self.reconnection_attempts: self.logger.info( 'Maximum reconnection attempts reached, giving up') break

As I read it, here's the flow:

  1. Attempt to connect to the websocket (i.e., the Ambient Weather API's websocket)
  2. If the connection operation has a ConnectionError (which, although I can't prove it, seems connected to the error you're seeing), try again after an ever-increasing delay (and up to a maximum number of retries)
  3. If the connection succeeds at any point, log an INFO-level log that says "Reconnection successful"
  4. If the connection reaches its maximum number of retries with all failures, log an INFO-level log that says "Maximum reconnection attempts reached, giving up"

So, this gives me a couple different ideas. Idea 1: Test the Library Directly

It might be worthwhile to see whether you can access the Ambient Weather websocket API at all. Fortunately, I have a script that can help you do that.

In a terminal, clone aioambient:

$ git clone https://github.com/bachya/aioambient.git $ cd aioambient/

Initialize the dev environment:

$ make init

(FYI, the only reason that command would fail is if you don't have Python3 installed.)

Open example_websocket.py in a text editor and add your API/App keys to lines 12 and 13:

API_KEY = ""APP_KEY = ""

Save the file and close your text editor. Back in your terminal, run example_websocket.py:

$ pipenv run python3 example_websocket.py

If this works, you should see output that looks like the following (and you can move onto Idea 2):

$ pipenv run python3 example_websocket.py INFO:engineio.client:Attempting WebSocket connection to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=&transport=websocket&EIO=3 INFO:engineio.client:WebSocket connection accepted with {'sid': 'xxxxxxxxxxxxxxx', 'upgrades': [], 'pingInterval': 25000, 'pingTimeout': 60000} INFO:socketio.client:Engine.IO connection established INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:engineio.client:Received packet MESSAGE data 0 INFO:socketio.client:Namespace / is connected INFO:socketio.client:Emitting event "subscribe" [/] INFO:engineio.client:Sending packet MESSAGE data 2["subscribe",{"apiKeys":[""]}] INFO:root:Client has connected to the websocket INFO:engineio.client:Received packet PONG data None INFO:engineio.client:Received packet MESSAGE data 2["subscribed",{"devices":[{"macAddress":"12:34:56:AB:CD:EF","lastData":{"dateutc":1573150080000,"winddir":335,"windspeedmph":1.1,"windgustmph":1.1,"maxdailygust":4.5,"tempf":46.8,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0.01,"weeklyrainin":0.01,"monthlyrainin":0.07,"totalrainin":11.3,"baromrelin":30.58,"baromabsin":25.09,"humidity":57,"tempinf":86.2,"humidityin":21,"uv":2,"solarradiation":212.49,"feelsLike":46.8,"dewPoint":32.38,"feelsLikein":83.1,"dewPointin":41.7,"lastRain":"2019-11-07T15:48:00.000Z","deviceId":"xxxxxxxxxxxxxxxxxxxxxxxxx","tz":"YOUR/TZ","date":"2019-11-07T18:08:00.000Z"},"info":{"name":"Side Yard","location":"Home"},"apiKey":""}],"method":"subscribe"}] INFO:socketio.client:Received event "subscribed" [/] INFO:root:Data received: {'devices': [{'macAddress': '12:34:56:AB:CD:EF', 'lastData': {'dateutc': 1573150080000, 'winddir': 335, 'windspeedmph': 1.1, 'windgustmph': 1.1, 'maxdailygust': 4.5, 'tempf': 46.8, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0.01, 'weeklyrainin': 0.01, 'monthlyrainin': 0.07, 'totalrainin': 11.3, 'baromrelin': 30.58, 'baromabsin': 25.09, 'humidity': 57, 'tempinf': 86.2, 'humidityin': 21, 'uv': 2, 'solarradiation': 212.49, 'feelsLike': 46.8, 'dewPoint': 32.38, 'feelsLikein': 83.1, 'dewPointin': 41.7, 'lastRain': '2019-11-07T15:48:00.000Z', 'deviceId': 'xxxxxxxxxxxxxxxxxxxxxxxxx', 'tz': 'YOUR/TZ', 'date': '2019-11-07T18:08:00.000Z'}, 'info': {'name': 'Side Yard', 'location': 'Home'}, 'apiKey': ''}], 'method': 'subscribe'} INFO:engineio.client:Received packet MESSAGE data 2["data",{"dateutc":1573150140000,"winddir":337,"windspeedmph":2.2,"windgustmph":2.2,"maxdailygust":4.5,"tempf":45.9,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0.01,"weeklyrainin":0.01,"monthlyrainin":0.07,"totalrainin":11.3,"baromrelin":30.58,"baromabsin":25.09,"humidity":60,"tempinf":86.2,"humidityin":21,"uv":2,"solarradiation":211.15,"feelsLike":45.9,"dewPoint":32.81,"feelsLikein":83.1,"dewPointin":41.7,"lastRain":"2019-11-07T15:48:00.000Z","tz":"YOUR/TZ","date":"2019-11-07T18:09:00.000Z","macAddress":"12:34:56:AB:CD:EF"}] INFO:socketio.client:Received event "data" [/] INFO:root:Data received: {'dateutc': 1573150140000, 'winddir': 337, 'windspeedmph': 2.2, 'windgustmph': 2.2, 'maxdailygust': 4.5, 'tempf': 45.9, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0.01, 'weeklyrainin': 0.01, 'monthlyrainin': 0.07, 'totalrainin': 11.3, 'baromrelin': 30.58, 'baromabsin': 25.09, 'humidity': 60, 'tempinf': 86.2, 'humidityin': 21, 'uv': 2, 'solarradiation': 211.15, 'feelsLike': 45.9, 'dewPoint': 32.81, 'feelsLikein': 83.1, 'dewPointin': 41.7, 'lastRain': '2019-11-07T15:48:00.000Z', 'tz': 'YOUR/TZ', 'date': '2019-11-07T18:09:00.000Z', 'macAddress': '12:34:56:AB:CD:EF'}

If this doesn't work, you'll see a familiar error:

$ pipenv run python3 example_websocket.py INFO:engineio.client:Attempting WebSocket connection to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=&transport=websocket&EIO=3 ERROR:root:There was a websocket error: Connection error

...and we can assume that there's a problem with either your API key or your APP key. Idea 2: Increase the HASS Log Level for ambient_station

If we have verified that aioambient works as expected, let's see if we can get the expected log messages from my analysis above.

Change the log level for ambient_station in your configuration.yaml:

logger: default: warning logs: homeassistant.components.ambient_station: info

Restart HASS and let it run a while (even an hour should be good enough). Then, paste back here any log entries related to homeassistant.components.ambient_station, aioambient, python-socketio, or python-engineio; there will be a lot of them, but if you can paste these (and only these) in the order they came in, we'll be able to analyze.

Thanks for your help! Let me know what these ideas produce.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/28559?email_source=notifications&email_token=AAZJMFOVGRO7VYWSTTV7GETQSRMBZA5CNFSM4JJCOWWKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDNKVLY#issuecomment-551201455, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAZJMFKCWDESCCIGVRUJPJLQSRMBZANCNFSM4JJCOWWA .

-- "Go serve your King" https://www.wretched.org/biggestquestion/

bachya commented 4 years ago

Do you have another computer you can attempt these steps on?

harfordhawk commented 4 years ago

can I run this test from another server on same network? I do have another linux machine running here

On Thu, Nov 7, 2019 at 1:35 PM Mack Goodman mackgoodman@gmail.com wrote:

I can't run make

i am in hassio so I can't ssh in using putty ( at least I don't know how) I use the addons for ssh. That I guess limits what I can do I even turned off protection mode in addon but still no lusk running make

On Thu, Nov 7, 2019 at 1:21 PM Aaron Bach notifications@github.com wrote:

@harfordhawk https://github.com/harfordhawk @jccshmny https://github.com/jccshmny I traced the reported error you from my library back to python-socketio and came across some relevant-looking code https://github.com/miguelgrinberg/python-socketio/blob/7c32b379aeeafdb4d6e24e8695734c985753a9d7/socketio/asyncio_client.py#L400-L416 in version 4.3.1:

try: await self.connect(self.connection_url, headers=self.connection_headers, transports=self.connection_transports, namespaces=self.connection_namespaces, socketio_path=self.socketio_path)except (exceptions.ConnectionError, ValueError): passelse: self.logger.info('Reconnection successful') self._reconnect_task = None breakif self.reconnection_attempts and \ attempt_count >= self.reconnection_attempts: self.logger.info( 'Maximum reconnection attempts reached, giving up') break

As I read it, here's the flow:

  1. Attempt to connect to the websocket (i.e., the Ambient Weather API's websocket)
  2. If the connection operation has a ConnectionError (which, although I can't prove it, seems connected to the error you're seeing), try again after an ever-increasing delay (and up to a maximum number of retries)
  3. If the connection succeeds at any point, log an INFO-level log that says "Reconnection successful"
  4. If the connection reaches its maximum number of retries with all failures, log an INFO-level log that says "Maximum reconnection attempts reached, giving up"

So, this gives me a couple different ideas. Idea 1: Test the Library Directly

It might be worthwhile to see whether you can access the Ambient Weather websocket API at all. Fortunately, I have a script that can help you do that.

In a terminal, clone aioambient:

$ git clone https://github.com/bachya/aioambient.git $ cd aioambient/

Initialize the dev environment:

$ make init

(FYI, the only reason that command would fail is if you don't have Python3 installed.)

Open example_websocket.py in a text editor and add your API/App keys to lines 12 and 13:

API_KEY = ""APP_KEY = ""

Save the file and close your text editor. Back in your terminal, run example_websocket.py:

$ pipenv run python3 example_websocket.py

If this works, you should see output that looks like the following (and you can move onto Idea 2):

$ pipenv run python3 example_websocket.py INFO:engineio.client:Attempting WebSocket connection to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=&transport=websocket&EIO=3 INFO:engineio.client:WebSocket connection accepted with {'sid': 'xxxxxxxxxxxxxxx', 'upgrades': [], 'pingInterval': 25000, 'pingTimeout': 60000} INFO:socketio.client:Engine.IO connection established INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:engineio.client:Received packet MESSAGE data 0 INFO:socketio.client:Namespace / is connected INFO:socketio.client:Emitting event "subscribe" [/] INFO:engineio.client:Sending packet MESSAGE data 2["subscribe",{"apiKeys":[""]}] INFO:root:Client has connected to the websocket INFO:engineio.client:Received packet PONG data None INFO:engineio.client:Received packet MESSAGE data 2["subscribed",{"devices":[{"macAddress":"12:34:56:AB:CD:EF","lastData":{"dateutc":1573150080000,"winddir":335,"windspeedmph":1.1,"windgustmph":1.1,"maxdailygust":4.5,"tempf":46.8,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0.01,"weeklyrainin":0.01,"monthlyrainin":0.07,"totalrainin":11.3,"baromrelin":30.58,"baromabsin":25.09,"humidity":57,"tempinf":86.2,"humidityin":21,"uv":2,"solarradiation":212.49,"feelsLike":46.8,"dewPoint":32.38,"feelsLikein":83.1,"dewPointin":41.7,"lastRain":"2019-11-07T15:48:00.000Z","deviceId":"xxxxxxxxxxxxxxxxxxxxxxxxx","tz":"YOUR/TZ","date":"2019-11-07T18:08:00.000Z"},"info":{"name":"Side Yard","location":"Home"},"apiKey":""}],"method":"subscribe"}] INFO:socketio.client:Received event "subscribed" [/] INFO:root:Data received: {'devices': [{'macAddress': '12:34:56:AB:CD:EF', 'lastData': {'dateutc': 1573150080000, 'winddir': 335, 'windspeedmph': 1.1, 'windgustmph': 1.1, 'maxdailygust': 4.5, 'tempf': 46.8, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0.01, 'weeklyrainin': 0.01, 'monthlyrainin': 0.07, 'totalrainin': 11.3, 'baromrelin': 30.58, 'baromabsin': 25.09, 'humidity': 57, 'tempinf': 86.2, 'humidityin': 21, 'uv': 2, 'solarradiation': 212.49, 'feelsLike': 46.8, 'dewPoint': 32.38, 'feelsLikein': 83.1, 'dewPointin': 41.7, 'lastRain': '2019-11-07T15:48:00.000Z', 'deviceId': 'xxxxxxxxxxxxxxxxxxxxxxxxx', 'tz': 'YOUR/TZ', 'date': '2019-11-07T18:08:00.000Z'}, 'info': {'name': 'Side Yard', 'location': 'Home'}, 'apiKey': ''}], 'method': 'subscribe'} INFO:engineio.client:Received packet MESSAGE data 2["data",{"dateutc":1573150140000,"winddir":337,"windspeedmph":2.2,"windgustmph":2.2,"maxdailygust":4.5,"tempf":45.9,"hourlyrainin":0,"eventrainin":0,"dailyrainin":0.01,"weeklyrainin":0.01,"monthlyrainin":0.07,"totalrainin":11.3,"baromrelin":30.58,"baromabsin":25.09,"humidity":60,"tempinf":86.2,"humidityin":21,"uv":2,"solarradiation":211.15,"feelsLike":45.9,"dewPoint":32.81,"feelsLikein":83.1,"dewPointin":41.7,"lastRain":"2019-11-07T15:48:00.000Z","tz":"YOUR/TZ","date":"2019-11-07T18:09:00.000Z","macAddress":"12:34:56:AB:CD:EF"}] INFO:socketio.client:Received event "data" [/] INFO:root:Data received: {'dateutc': 1573150140000, 'winddir': 337, 'windspeedmph': 2.2, 'windgustmph': 2.2, 'maxdailygust': 4.5, 'tempf': 45.9, 'hourlyrainin': 0, 'eventrainin': 0, 'dailyrainin': 0.01, 'weeklyrainin': 0.01, 'monthlyrainin': 0.07, 'totalrainin': 11.3, 'baromrelin': 30.58, 'baromabsin': 25.09, 'humidity': 60, 'tempinf': 86.2, 'humidityin': 21, 'uv': 2, 'solarradiation': 211.15, 'feelsLike': 45.9, 'dewPoint': 32.81, 'feelsLikein': 83.1, 'dewPointin': 41.7, 'lastRain': '2019-11-07T15:48:00.000Z', 'tz': 'YOUR/TZ', 'date': '2019-11-07T18:09:00.000Z', 'macAddress': '12:34:56:AB:CD:EF'}

If this doesn't work, you'll see a familiar error:

$ pipenv run python3 example_websocket.py INFO:engineio.client:Attempting WebSocket connection to wss://dash2.ambientweather.net/socket.io/?api=1&applicationKey=&transport=websocket&EIO=3 ERROR:root:There was a websocket error: Connection error

...and we can assume that there's a problem with either your API key or your APP key. Idea 2: Increase the HASS Log Level for ambient_station

If we have verified that aioambient works as expected, let's see if we can get the expected log messages from my analysis above.

Change the log level for ambient_station in your configuration.yaml:

logger: default: warning logs: homeassistant.components.ambient_station: info

Restart HASS and let it run a while (even an hour should be good enough). Then, paste back here any log entries related to homeassistant.components.ambient_station, aioambient, python-socketio, or python-engineio; there will be a lot of them, but if you can paste these (and only these) in the order they came in, we'll be able to analyze.

Thanks for your help! Let me know what these ideas produce.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/28559?email_source=notifications&email_token=AAZJMFOVGRO7VYWSTTV7GETQSRMBZA5CNFSM4JJCOWWKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDNKVLY#issuecomment-551201455, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAZJMFKCWDESCCIGVRUJPJLQSRMBZANCNFSM4JJCOWWA .

-- "Go serve your King" https://www.wretched.org/biggestquestion/

-- "Go serve your King" https://www.wretched.org/biggestquestion/

bachya commented 4 years ago

You can use whatever machine you like – as long as it has a terminal/command prompt and you can install Git, you're good. It doesn't need to be on the same network as your HASS machine.

harfordhawk commented 4 years ago

Okay, i did task 1 and I see the output that looks like it is connecting fine. I have put logger in config and will see what that says

On Thu, Nov 7, 2019 at 1:40 PM Aaron Bach notifications@github.com wrote:

You can use whatever machine you like – as long as it has a terminal/command prompt and you can install Git, you're good. It doesn't need to be on the same network as your HASS machine.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/28559?email_source=notifications&email_token=AAZJMFNQ6DULG4TOYQ3QU3DQSROKRA5CNFSM4JJCOWWKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDNMQ6Y#issuecomment-551209083, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAZJMFOXTFA5GF2LI74Y3FTQSROKRANCNFSM4JJCOWWA .

-- "Go serve your King" https://www.wretched.org/biggestquestion/

harfordhawk commented 4 years ago

got this at end of test... was this suppose to happen?

INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:engineio.client:Sending packet MESSAGE data 1 INFO:engineio.client:Sending packet CLOSE data None INFO:socketio.client:Engine.IO connection dropped INFO:engineio.client:Received packet PONG data None INFO:engineio.client:Waiting for write loop task to end INFO:engineio.client:Write loop: WebSocket connection was closed, aborting INFO:engineio.client:Exiting write loop task INFO:engineio.client:Waiting for ping loop task to end INFO:engineio.client:Exiting ping task INFO:engineio.client:Exiting read loop task

On Thu, Nov 7, 2019 at 1:59 PM Mack Goodman mackgoodman@gmail.com wrote:

Okay, i did task 1 and I see the output that looks like it is connecting fine. I have put logger in config and will see what that says

On Thu, Nov 7, 2019 at 1:40 PM Aaron Bach notifications@github.com wrote:

You can use whatever machine you like – as long as it has a terminal/command prompt and you can install Git, you're good. It doesn't need to be on the same network as your HASS machine.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/28559?email_source=notifications&email_token=AAZJMFNQ6DULG4TOYQ3QU3DQSROKRA5CNFSM4JJCOWWKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDNMQ6Y#issuecomment-551209083, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAZJMFOXTFA5GF2LI74Y3FTQSROKRANCNFSM4JJCOWWA .

-- "Go serve your King" https://www.wretched.org/biggestquestion/

-- "Go serve your King" https://www.wretched.org/biggestquestion/

bachya commented 4 years ago

I can't tell without seeing the entire output of Test 1. Can you paste the entire thing (removing any sensitive information as needed)?

bachya commented 4 years ago

Yep, that looks reasonable to me. 👍

harfordhawk commented 4 years ago

okay, nothing different in logs yet.. I do see this error and it has been around for a while but not sure if it is related..

2019-11-07 14:12:21 ERROR (EndpointThread-Subscribe-0) [pubnub] Exception in subscribe loop: Connection Error: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))

On Thu, Nov 7, 2019 at 2:07 PM Mack Goodman mackgoodman@gmail.com wrote:

mack@ubuntu:~/test/aioambient$ pipenv run python3 example_websocket.py INFO:engineio.client:Attempting WebSocket connection to wss:// dash2.ambientweather.net/socket.io/?api=1&applicationKey=abd0ef464eab4db39e2ecb9d9e1ce7821e411f22ffb64dc8a2e9cb5e6992e6d2&transport=websocket&EIO=3 INFO:engineio.client:WebSocket connection accepted with {'sid': 'YL0TjgCEvrur7V8-AAYT', 'upgrades': [], 'pingInterval': 25000, 'pingTimeout': 60000} INFO:socketio.client:Engine.IO connection established INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:engineio.client:Received packet MESSAGE data 0 INFO:socketio.client:Namespace / is connected INFO:socketio.client:Emitting event "subscribe" [/] INFO:engineio.client:Sending packet MESSAGE data 2["subscribe",{"apiKeys":["737a0736b892413bb263010dd92d5d0"]}] INFO:root:Client has connected to the websocket INFO:engineio.client:Received packet PONG data None INFO:engineio.client:Received packet MESSAGE data 2["subscribed",{"devices":[{"macAddress":"5C:CF:7F:22:78:19","lastData":{"dateutc":1573152900000,"winddir":162,"windspeedmph":0,"windgustmph":0,"maxdailygust":4.5,"tempf":80.1,"hourlyrainin":0,"dailyrainin":0,"weeklyrainin":0.2,"monthlyrainin":0.2,"totalrainin":185.45,"baromrelin":30.14,"baromabsin":30.05,"humidity":67,"tempinf":72,"humidityin":56,"uv":4,"solarradiation":501.82,"feelsLike":82.74,"dewPoint":68.13,"feelsLikein":71.5,"dewPointin":55.4,"lastRain":"2019-11-06T06:59:00.000Z","deviceId":"5a2fd5000c54bb2c","tz":"Etc/GMT","date":"2019-11-07T18:55:00.000Z"},"info":{"location":"Home","name":"My Weather Station"},"apiKey":"737a0736b892413bb26301f482343b4ac0d5d0"}],"method":"subscribe"}] INFO:socketio.client:Received event "subscribed" [/] INFO:root:Data received: {'devices': [{'macAddress': '5C:CF:7F:22:78:19', 'lastData': {'dateutc': 1573152900000, 'winddir': 162, 'windspeedmph': 0, 'windgustmph': 0, 'maxdailygust': 4.5, 'tempf': 80.1, 'hourlyrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0.2, 'monthlyrainin': 0.2, 'totalrainin': 185.45, 'baromrelin': 30.14, 'baromabsin': 30.05, 'humidity': 67, 'tempinf': 72, 'humidityin': 56, 'uv': 4, 'solarradiation': 501.82, 'feelsLike': 82.74, 'dewPoint': 68.13, 'feelsLikein': 71.5, 'dewPointin': 55.4, 'lastRain': '2019-11-06T06:59:00.000Z', 'deviceId': '5a2fdd031c', 'tz': 'Etc/GMT', 'date': '2019-11-07T18:55:00.000Z'}, 'info': {'location': 'Home', 'name': 'My Weather Station'}, 'apiKey': '737a0736b892413bd92d5d0'}], 'method': 'subscribe'} INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:engineio.client:Received packet MESSAGE data 2["data",{"dateutc":1573152960000,"winddir":199,"windspeedmph":0.2,"windgustmph":1.1,"maxdailygust":4.5,"tempf":80.1,"hourlyrainin":0,"dailyrainin":0,"weeklyrainin":0.2,"monthlyrainin":0.2,"totalrainin":185.45,"baromrelin":30.14,"baromabsin":30.05,"humidity":67,"tempinf":72,"humidityin":56,"uv":4,"solarradiation":499.25,"feelsLike":82.74,"dewPoint":68.13,"feelsLikein":71.5,"dewPointin":55.4,"lastRain":"2019-11-06T06:59:00.000Z","tz":"Etc/GMT","date":"2019-11-07T18:56:00.000Z","macAddress":""}] INFO:socketio.client:Received event "data" [/] INFO:root:Data received: {'dateutc': 1573152960000, 'winddir': 199, 'windspeedmph': 0.2, 'windgustmph': 1.1, 'maxdailygust': 4.5, 'tempf': 80.1, 'hourlyrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0.2, 'monthlyrainin': 0.2, 'totalrainin': 185.45, 'baromrelin': 30.14, 'baromabsin': 30.05, 'humidity': 67, 'tempinf': 72, 'humidityin': 56, 'uv': 4, 'solarradiation': 499.25, 'feelsLike': 82.74, 'dewPoint': 68.13, 'feelsLikein': 71.5, 'dewPointin': 55.4, 'lastRain': '2019-11-06T06:59:00.000Z', 'tz': 'Etc/GMT', 'date': '2019-11-07T18:56:00.000Z', 'macAddress': ''} INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:root:Simulating some other task occurring... INFO:engineio.client:Received packet PONG data None INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:root:Simulating some other task occurring... INFO:engineio.client:Received packet PONG data None INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:root:Simulating some other task occurring... INFO:engineio.client:Received packet PONG data None INFO:engineio.client:Received packet MESSAGE data 2["data",{"dateutc":1573153020000,"winddir":199,"windspeedmph":0,"windgustmph":0,"maxdailygust":4.5,"tempf":80.1,"hourlyrainin":0,"dailyrainin":0,"weeklyrainin":0.2,"monthlyrainin":0.2,"totalrainin":185.45,"baromrelin":30.14,"baromabsin":30.05,"humidity":67,"tempinf":72,"humidityin":56,"uv":4,"solarradiation":497.54,"feelsLike":82.74,"dewPoint":68.13,"feelsLikein":71.5,"dewPointin":55.4,"lastRain":"2019-11-06T06:59:00.000Z","tz":"Etc/GMT","date":"2019-11-07T18:57:00.000Z","macAddress":""}] INFO:socketio.client:Received event "data" [/] INFO:root:Data received: {'dateutc': 1573153020000, 'winddir': 199, 'windspeedmph': 0, 'windgustmph': 0, 'maxdailygust': 4.5, 'tempf': 80.1, 'hourlyrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0.2, 'monthlyrainin': 0.2, 'totalrainin': 185.45, 'baromrelin': 30.14, 'baromabsin': 30.05, 'humidity': 67, 'tempinf': 72, 'humidityin': 56, 'uv': 4, 'solarradiation': 497.54, 'feelsLike': 82.74, 'dewPoint': 68.13, 'feelsLikein': 71.5, 'dewPointin': 55.4, 'lastRain': '2019-11-06T06:59:00.000Z', 'tz': 'Etc/GMT', 'date': '2019-11-07T18:57:00.000Z', 'macAddress': ''} INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:root:Simulating some other task occurring... INFO:engineio.client:Received packet PONG data None INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:engineio.client:Received packet PONG data None INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:engineio.client:Received packet MESSAGE data 2["data",{"dateutc":1573153080000,"winddir":199,"windspeedmph":1.1,"windgustmph":1.1,"maxdailygust":4.5,"tempf":80.2,"hourlyrainin":0,"dailyrainin":0,"weeklyrainin":0.2,"monthlyrainin":0.2,"totalrainin":185.45,"baromrelin":30.14,"baromabsin":30.04,"humidity":66,"tempinf":72,"humidityin":56,"uv":4,"solarradiation":499.74,"feelsLike":82.77,"dewPoint":67.79,"feelsLikein":71.5,"dewPointin":55.4,"lastRain":"2019-11-06T06:59:00.000Z","tz":"Etc/GMT","date":"2019-11-07T18:58:00.000Z","macAddress":""}] INFO:socketio.client:Received event "data" [/] INFO:root:Data received: {'dateutc': 1573153080000, 'winddir': 199, 'windspeedmph': 1.1, 'windgustmph': 1.1, 'maxdailygust': 4.5, 'tempf': 80.2, 'hourlyrainin': 0, 'dailyrainin': 0, 'weeklyrainin': 0.2, 'monthlyrainin': 0.2, 'totalrainin': 185.45, 'baromrelin': 30.14, 'baromabsin': 30.04, 'humidity': 66, 'tempinf': 72, 'humidityin': 56, 'uv': 4, 'solarradiation': 499.74, 'feelsLike': 82.77, 'dewPoint': 67.79, 'feelsLikein': 71.5, 'dewPointin': 55.4, 'lastRain': '2019-11-06T06:59:00.000Z', 'tz': 'Etc/GMT', 'date': '2019-11-07T18:58:00.000Z', 'macAddress': ''} INFO:root:Simulating some other task occurring... INFO:root:Simulating some other task occurring... INFO:engineio.client:Sending packet PING data None INFO:engineio.client:Sending packet MESSAGE data 1 INFO:engineio.client:Sending packet CLOSE data None INFO:socketio.client:Engine.IO connection dropped INFO:engineio.client:Received packet PONG data None INFO:engineio.client:Waiting for write loop task to end INFO:engineio.client:Write loop: WebSocket connection was closed, aborting INFO:engineio.client:Exiting write loop task INFO:engineio.client:Waiting for ping loop task to end INFO:engineio.client:Exiting ping task INFO:engineio.client:Exiting read loop task

On Thu, Nov 7, 2019 at 2:03 PM Aaron Bach notifications@github.com wrote:

I can't tell without seeing the entire output of Test 1. Can you paste the entire thing (removing any sensitive information as needed)?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/28559?email_source=notifications&email_token=AAZJMFN7RORB4ASIFSAVM53QSRRAZA5CNFSM4JJCOWWKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDNOXGA#issuecomment-551218072, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAZJMFNS3MV6ROQ7XEZPYLTQSRRAZANCNFSM4JJCOWWA .

-- "Go serve your King" https://www.wretched.org/biggestquestion/

-- "Go serve your King" https://www.wretched.org/biggestquestion/

bachya commented 4 years ago

Looks like that error comes from pubnub, which isn't something the ambient_station integration uses.

harfordhawk commented 4 years ago

So any chance this has progressed while I was away? I made the changes to the config file for logger and I still only see the one error regarding ambient "ERROR (MainThread) [homeassistant.components.ambient_station] Error with the websocket connection: Connection error"

bachya commented 4 years ago

As you can see above, our conversation was the last there had been. I continue to be unable to reproduce the issue.

harfordhawk commented 4 years ago

This seems to be corrected in HA .102 so for me I would say this issue is fixed.

bachya commented 4 years ago

Thanks for the update, @harfordhawk.