Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Integration fails to start up on HA restart (Public API) #90

Open
araines opened this issue Jul 18, 2022 · 9 comments
Open

Integration fails to start up on HA restart (Public API) #90

araines opened this issue Jul 18, 2022 · 9 comments

Comments

@araines
Copy link

araines commented Jul 18, 2022

Recently when I've been restarting home assistant, I've been left with failures for the LW integration to start up.

HACS LW Plugin Version: v3.5.15
HACS Version: 1.26.2
Home Assistant Version: 2022.7.5

The way I've been able to get things going again is by turning off the Public API, restarting to get things going. Then waiting a little while until I hit a problem where my energy monitor no longer reports updates to HA (I should raise a separate issue about that I guess!) then switch to the Public API. I think that has been the process anyway, I've been doing a lot of option/restart twiddling recently, so will be paying more attention now to give a more accurate bug report.

Logger: homeassistant.config_entries
Source: custom_components/lightwave2/__init__.py:83
Integration: Lightwave v2 (Smart Series) custom component ([documentation](https://github.com/bigbadblunt/homeassistant-lightwave2))
First occurred: 08:22:13 (1 occurrences)
Last logged: 08:22:13

Error setting up entry <REDACTED> for lightwave2
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 353, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/config/custom_components/lightwave2/__init__.py", line 83, in async_setup_entry
    await link.async_get_hierarchy()
  File "/usr/local/lib/python3.10/site-packages/lightwave2/lightwave2.py", line 601, in async_get_hierarchy
    await self.async_update_featureset_states()
  File "/usr/local/lib/python3.10/site-packages/lightwave2/lightwave2.py", line 688, in async_update_featureset_states
    req = await self._async_postrequest("features/read", body)
  File "/usr/local/lib/python3.10/site-packages/lightwave2/lightwave2.py", line 550, in _async_postrequest
    return await req.json()
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client_reqrep.py", line 1103, in json
    raise ContentTypeError(
aiohttp.client_exceptions.ContentTypeError: 0, message='Attempt to decode JSON with unexpected mimetype: text/html', url=URL('https://publicapi.lightwaverf.com/v1/features/read')

Full logs attached
fulllogs.txt

@araines
Copy link
Author

araines commented Jul 18, 2022

Just confirmed - after around 30mins my energy monitor stops working on the internal API. I switched over to Public API around 3 hours later (without restarting) and it switched over and started working fine. The energy monitor works fine on the Public API.

@bigbadblunt
Copy link
Owner

Thanks for the full logs. Line 216 has "API response 500". A HTML error code of 500 is the not-so-useful "Internal Server Error". Looks like an issue at the LW end.

Can you post additional logs if it recurs? Maybe there's a pattern in which requests cause the error.

@mydliar
Copy link

mydliar commented Aug 8, 2022

I am intermittently getting an LW Plugin config error on HA restart. I restart HA every second day, and I see the error at least once a week. Manual re-adding the LW integration (without removing the old one) always solves the issue.

This error originated from a custom integration.

Logger: homeassistant.config_entries
Source: custom_components/lightwave2/__init__.py:83
Integration: Lightwave v2 (Smart Series) custom component (documentation)
First occurred: 09:39:48 (1 occurrences)
Last logged: 09:39:48

Error setting up entry <xxx>@<yyy>.com for lightwave2
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/asyncio/locks.py", line 214, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/lightwave2/lightwave2.py", line 135, in _async_sendmessage
    await asyncio.wait_for(waitflag.wait(), timeout=5.0)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 353, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/config/custom_components/lightwave2/__init__.py", line 83, in async_setup_entry
    await link.async_get_hierarchy()
  File "/usr/local/lib/python3.10/site-packages/lightwave2/lightwave2.py", line 221, in async_get_hierarchy
    await self._async_read_groups()
  File "/usr/local/lib/python3.10/site-packages/lightwave2/lightwave2.py", line 237, in _async_read_groups
    response = await self._async_sendmessage(readmess)
  File "/usr/local/lib/python3.10/site-packages/lightwave2/lightwave2.py", line 139, in _async_sendmessage
    self._transactions.pop(message._message["transactionId"])
KeyError: 2

full log.txt

I hope the logs help.

@bigbadblunt
Copy link
Owner

@mydliar When the integration sends messages to the server, it waits up to 5 seconds for a reply and then times out. It looks like your responses are taking slightly around 5 seconds (e.g. message 1, sent 0939:33, received 0939:38) - normally this should be pretty instantaneous. Is your network under high load?

In any case, this is a flaw in my code, it should recover from a timeout rather than crashing. I will fix imminently.

@mydliar
Copy link

mydliar commented Aug 11, 2022

@bigbadblunt - thanks for this. I am on a very fast 1Gb fibre broadband (and my home LAN is also running on 1Gb), but the NAS where I run the HA is under permanent network load from the CCTV camera feeds. That could explain it, though I never experienced latency or speed issues on the NAS. Thanks again for looking into it.

@araines
Copy link
Author

araines commented Sep 19, 2022

So I've had my lightwave drop out many times, just kept forgetting to grab the logs before restarting. As far as I can tell I lose data updates to my entities at 21:11:52. At the same time, the debug logs (which have been very verbose up until that point) simply stop. I've attached a snippet from the timeframe:

2022-09-18 21:11:22.319 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","transactionId":5294093,"direction":"notification","class":"feature","operation":"event","items":[{"payload":{"featureId":"5be42d2cb36c6e17729ad10b-76-3157334736+1","deviceId":5,"type":"power","channel":0,"writable":false,"stateless":false,"virtual":false,"value":1041,"status":"ok"},"success":true,"itemId":388}]}', extra='')
2022-09-18 21:11:22.320 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-76-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801c28> 1041), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 21:11:22.321 DEBUG (MainThread) [custom_components.lightwave2] Central callback
2022-09-18 21:11:22.323 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 21:11:22.323 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","transactionId":5294094,"direction":"notification","class":"feature","operation":"event","items":[{"payload":{"featureId":"5be42d2cb36c6e17729ad10b-77-3157334736+1","deviceId":5,"type":"energy","channel":0,"writable":false,"stateless":false,"virtual":false,"value":2222240,"status":"ok"},"success":true,"itemId":389}]}', extra='')
2022-09-18 21:11:22.323 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-77-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801c88> 2222240), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 21:11:22.324 DEBUG (MainThread) [custom_components.lightwave2] Central callback
2022-09-18 21:11:22.330 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 21:11:37.410 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","transactionId":5295047,"direction":"notification","class":"feature","operation":"event","items":[{"payload":{"featureId":"5be42d2cb36c6e17729ad10b-76-3157334736+1","deviceId":5,"type":"power","channel":0,"writable":false,"stateless":false,"virtual":false,"value":1032,"status":"ok"},"success":true,"itemId":390}]}', extra='')
2022-09-18 21:11:37.411 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-76-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801c28> 1032), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 21:11:37.411 DEBUG (MainThread) [custom_components.lightwave2] Central callback
2022-09-18 21:11:37.415 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 21:11:37.437 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","transactionId":5295048,"direction":"notification","class":"feature","operation":"event","items":[{"payload":{"featureId":"5be42d2cb36c6e17729ad10b-77-3157334736+1","deviceId":5,"type":"energy","channel":0,"writable":false,"stateless":false,"virtual":false,"value":2222244,"status":"ok"},"success":true,"itemId":391}]}', extra='')
2022-09-18 21:11:37.438 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-77-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801c88> 2222244), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 21:11:37.438 DEBUG (MainThread) [custom_components.lightwave2] Central callback
2022-09-18 21:11:37.440 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 21:11:52.524 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","transactionId":5295930,"direction":"notification","class":"feature","operation":"event","items":[{"payload":{"featureId":"5be42d2cb36c6e17729ad10b-76-3157334736+1","deviceId":5,"type":"power","channel":0,"writable":false,"stateless":false,"virtual":false,"value":1030,"status":"ok"},"success":true,"itemId":392}]}', extra='')
2022-09-18 21:11:52.525 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-76-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801c28> 1030), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 21:11:52.525 DEBUG (MainThread) [custom_components.lightwave2] Central callback
2022-09-18 21:11:52.528 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 21:11:52.529 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","transactionId":5295931,"direction":"notification","class":"feature","operation":"event","items":[{"payload":{"featureId":"5be42d2cb36c6e17729ad10b-77-3157334736+1","deviceId":5,"type":"energy","channel":0,"writable":false,"stateless":false,"virtual":false,"value":2222248,"status":"ok"},"success":true,"itemId":393}]}', extra='')
2022-09-18 21:11:52.535 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-77-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801c88> 2222248), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 21:11:52.536 DEBUG (MainThread) [custom_components.lightwave2] Central callback
2022-09-18 21:11:52.541 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 21:11:52.567 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","transactionId":5295932,"direction":"notification","class":"feature","operation":"event","items":[{"payload":{"featureId":"5be42d2cb36c6e17729ad10b-78-3157334736+1","deviceId":5,"type":"rssi","channel":0,"writable":false,"stateless":false,"virtual":false,"value":-57,"status":"ok"},"success":true,"itemId":394}]}', extra='')
2022-09-18 21:11:52.573 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-78-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801ce8> -57), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 21:11:52.573 DEBUG (MainThread) [custom_components.lightwave2] Central callback
2022-09-18 21:11:52.575 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 21:28:54.239 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.coinbase_eth_wallet is taking over 10 seconds
2022-09-18 21:55:36.675 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.eth_wallet is taking over 10 seconds
2022-09-18 22:49:54.440 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.coinbase_eth_wallet is taking over 10 seconds
2022-09-18 23:22:54.521 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.coinbase_eth_wallet is taking over 10 seconds
2022-09-19 00:05:36.707 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.eth_wallet is taking over 10 seconds
2022-09-19 00:42:37.676 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x5860:1:0x0b04]: async_initialize: all attempts have failed: [DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>')]

You can see the latest message happens at 21:11:52.575 for lightwave, then the next messages I have in the logs are from other integrations throwing some warnings.

I don't see that this particularly helps, though!

The only other thing I could see in the logs (although its from an hour earlier) was this:

2022-09-18 20:29:51.479 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-77-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801c88> 2221614), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 20:29:51.480 DEBUG (MainThread) [custom_components.lightwave2] Central callback
2022-09-18 20:29:51.483 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:30:06.948 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.CLOSED: 257>, data=None, extra=None)
2022-09-18 20:30:06.949 INFO (MainThread) [lightwave2.lightwave2] consumer_handler: Websocket closed in message handler
2022-09-18 20:30:06.949 INFO (MainThread) [lightwave2.lightwave2] consumer_handler: Websocket reconnect requested by message handler
2022-09-18 20:30:06.949 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:30:06.949 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:30:06.950 DEBUG (MainThread) [lightwave2.lightwave2] connect_to_server: Connecting to websocket
2022-09-18 20:30:07.059 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:30:07.060 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:30:07.161 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:30:07.162 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:30:07.263 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:30:07.263 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
....
2022-09-18 20:31:02.128 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:31:02.230 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:02.230 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:31:02.300 DEBUG (MainThread) [lightwave2.lightwave2] async_force_reconnect: time elapsed, forcing a reconnection
2022-09-18 20:31:02.301 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/lightwave2/lightwave2.py", line 384, in async_force_reconnect
await self._websocket.close()
AttributeError: 'NoneType' object has no attribute 'close'
2022-09-18 20:31:02.330 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:02.331 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:31:02.432 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:02.433 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
...
2022-09-18 20:31:07.116 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:31:07.217 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:07.217 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:31:07.224 WARNING (MainThread) [lightwave2.lightwave2] async_connect: Cannot connect (exception 'WSServerHandshakeError(RequestInfo(url=URL('wss://v1-linkplus-app.lightwaverf.com'), method='GET', headers=<CIMultiDictProxy('Host': 'v1-linkplus-app.lightwaverf.com', 'Upgrade': 'websocket', 'Connection': 'upgrade', 'Sec-WebSocket-Version': '13', 'Sec-WebSocket-Key': 'hSxKYJlsamEhAVlSoVhRmQ==', 'Accept': '*/*', 'Accept-Encoding': 'gzip, deflate', 'User-Agent': 'Python/3.10 aiohttp/3.8.1')>, real_url=URL('wss://v1-linkplus-app.lightwaverf.com')), (), status=504, message='Invalid response status', headers=<CIMultiDictProxy('Server': 'awselb/2.0', 'Date': 'Sun, 18 Sep 2022 19:31:07 GMT', 'Content-Type': 'text/html', 'Content-Length': '132', 'Connection': 'keep-alive')>)'). Waiting 2 seconds to retry
2022-09-18 20:31:07.318 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:07.318 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:31:07.419 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:07.420 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:31:07.521 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
...
2022-09-18 20:31:09.150 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:09.150 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: websocket not ready, sleeping for 0.1 sec
2022-09-18 20:31:09.227 DEBUG (MainThread) [lightwave2.lightwave2] connect_to_server: Connecting to websocket
2022-09-18 20:31:09.248 DEBUG (MainThread) [lightwave2.lightwave2] async_sendmessage: [contents hidden for security]
2022-09-18 20:31:09.250 DEBUG (MainThread) [lightwave2.lightwave2] async_sendmessage: Message sent, waiting for acknowledgement from server
2022-09-18 20:31:09.251 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:09.290 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","direction":"response","source":"_channel","items":[{"itemId":892,"success":true,"payload":{"workerUniqueId":"ip=10=192=22=230*eu=west=1*compute*internal=30194","serverName":"i-067249d7a39d5cbe8","handlerId":"user.7deb1b94-f7f8-4eae-a481-f2b5b7bb45a6.36fb0c86-0a13-4bf0-9247-86be35939b95"}}],"class":"user","operation":"authenticate","transactionId":892}', extra='')
2022-09-18 20:31:09.291 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Response matched for transaction 892
2022-09-18 20:31:09.291 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Starting consumer handler
2022-09-18 20:31:09.292 DEBUG (MainThread) [lightwave2.lightwave2] async_sendmessage: Response received: {'version': 1, 'senderId': '1.ip=10=192=22=230*eu=west=1*compute*internal=30194', 'direction': 'response', 'source': '_channel', 'items': [{'itemId': 892, 'success': True, 'payload': {'workerUniqueId': 'ip=10=192=22=230*eu=west=1*compute*internal=30194', 'serverName': 'i-067249d7a39d5cbe8', 'handlerId': 'user.7deb1b94-f7f8-4eae-a481-f2b5b7bb45a6.36fb0c86-0a13-4bf0-9247-86be35939b95'}}], 'class': 'user', 'operation': 'authenticate', 'transactionId': 892}
2022-09-18 20:31:51.138 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Received WSMessage(type=<WSMsgType.TEXT: 1>, data='{"version":1,"senderId":"1.ip=10=192=22=230*eu=west=1*compute*internal=30194","transactionId":5137281,"direction":"notification","class":"feature","operation":"event","items":[{"payload":{"featureId":"5be42d2cb36c6e17729ad10b-76-3157334736+1","deviceId":5,"type":"power","channel":0,"writable":false,"stateless":false,"virtual":false,"value":899,"status":"ok"},"success":true,"itemId":1}]}', extra='')
2022-09-18 20:31:51.139 DEBUG (MainThread) [lightwave2.lightwave2] consumer_handler: Event received (5be42d2cb36c6e17729ad10b-76-3157334736+1 <lightwave2.lightwave2.LWRFFeature object at 0xa5801c28> 899), calling callbacks ['async_central_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback', 'async_update_callback']
2022-09-18 20:31:51.140 DEBUG (MainThread) [custom_components.lightwave2] Central callback

Which looks like it recovered OK to me.

Hope that helps

@bigbadblunt
Copy link
Owner

What do you mean by "drop out"? You say you lose data updates; can you still control the entities from HA? If so, this is a duplicate of #69

@araines
Copy link
Author

araines commented Sep 26, 2022

Ah, sorry, my bad. I commented on the wrong thing :(

I've actually not been experiencing this restart issue for quite some time now. The only time I've noticed it has problems is when HA has started up before the LW hub is connected to the internet. In this case HA does not connect to LW (and nothing can be controlled) until I restart HA to reestablish the connection properly. I suspect that is a different problem to what I originally raised here.

Personally I'm happy for this one to be closed, as I'm not having this problem any more.

@bigbadblunt
Copy link
Owner

Looks like the original problem here is now fixed in #108. I am keeping open until I fix the recovery from timeout issue uncovered a few comments higher.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants