Tibber sensors become available - not able to reload integration without a HA restart

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.06k stars 29.72k forks source link

Tibber sensors become available - not able to reload integration without a HA restart #84179

Closed gulli1986 closed 1 year ago

gulli1986 commented 1 year ago

The problem

Tibber have been very unstable lately. Sensors for the Tibber integration can suddenly become unavailable.

Earlier this could be fixed by reloading the integration. This is not possible anymore, the integration requests to restart HA without having the possibility to reload:

Even after re-start the sensors do not always show up. Tibber is working fine on the iOS app.

What version of Home Assistant Core has the issue?

core-2022.12.7

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Tibber

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: tibber
Source: runner.py:120
First occurred: 11:27:38 AM (1 occurrences)
Last logged: 11:27:38 AM

Timed out when connecting to Tibber

Additional information

No response

AgentFalcon commented 1 year ago

I'm not seeing the same issue with reload. However I also did notice Tibber becoming more unstable right after installing 2022.12.7 today (which had some Tibber "real time streaming" changes), but I could still trigger manual reloads and after a couple host reboots it seems to have stabilized.

I've seen sensors becoming unavailable a couple times after, seemingly due to Timeout connecting to Tibber, but it also seems to be recovering by itself a bit later.

So maybe just try to restart your host and wait for a while to see if it works itself out. Also, disable any automations to reload the integration. I had one as a temporary solution earlier, but it might cause issues with the updated version.

gulli1986 commented 1 year ago

Thanks. I do not have any automation for reload enabled. Some sensors are available while other never show up, especially the power sensor seems to never be available. Getting this error in the logs:

Logger: tibber.tibber_home Source: /usr/local/lib/python3.10/site-packages/tibber/tibber_home.py:473 First occurred: 3:30:13 PM (1 occurrences) Last logged: 3:30:13 PM

Tibber connection closed, will reconnect in 61 seconds
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 455, in _start
    await self._tibber_control.rt_connect()
  File "/usr/local/lib/python3.10/site-packages/tibber/__init__.py", line 97, in rt_connect
    await self.sub_manager.connect_async()
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 632, in connect_async
    await self.transport.connect()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 512, in connect
    await self._initialize()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 152, in _initialize
    await self._send_init_message_and_wait_ack()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 149, in _send_init_message_and_wait_ack
    await asyncio.wait_for(self._wait_ack(), self.ack_timeout)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 126, in _wait_ack
    answer_type, answer_id, execution_result = self._parse_answer(init_answer)
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 425, in _parse_answer
    return self._parse_answer_apollo(json_answer)
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 398, in _parse_answer_apollo
    raise TransportServerError(f"Server error: '{repr(error_payload)}'")
gql.transport.exceptions.TransportServerError: Server error: '{'message': 'Prohibited connection!'}'

AgentFalcon commented 1 year ago

Strange. My power sensor value is becoming unavailable about 3-5 times pr hour, which didn't happen before the update to 2022.12.7, but it also comes back within 1-2mins. No errors in the log, but I can see the line breaks in the entity graph.

Your issues seem similar to this one: https://github.com/home-assistant/core/issues/83723

Seems the 2022.12.7 update today was meant to fix it, but maybe it didn't work out as I see there's another issue opened today similar to yours: https://github.com/home-assistant/core/issues/84193

gulli1986 commented 1 year ago

I removed the integration, re-started HA and re-installed the integration again. Everything is back as normal. Will see if this lasts...

home-assistant[bot] commented 1 year ago

Hey there @danielhiversen, mind taking a look at this issue as it has been labeled with an integration (tibber) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `tibber` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Change the title of the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign tibber` Removes the current integration label and assignees on the issue, add the integration domain after the command.

_{^{(message by CodeOwnersMention)}}

tibber documentation tibber source _{^{(message by IssueLinks)}}

Danielhiversen commented 1 year ago

Not sure why it is not possible to reload it.

For those where Tibber Pulse sensors stop updating: Tibber API has been quite unstable lately, so shorter outages are expected in HA. It should recover after maximum 60 min.

If it does not recover, could you enable debug logging for Tibber and copy the last tibber logs before it stops receiving Pulse data? Use HA 2022.12.7 (or newer) And please open a new bug report with the information.


logger:
  default: warning
  logs:
    tibber: debug

gulli1986 commented 1 year ago

Will do, it stopped working again yesterday. Have now enabled the logger. Will make a new bug report next time it stops.

erikssonphd commented 1 year ago

Same issue here, sensors become unavailable sporadically and reloading the integration doesn't help anymore. I've also turned on logging and will upload next time it happens.

ashpool commented 1 year ago

Logger: homeassistant.components.tibber.sensor
Source: helpers/update_coordinator.py:168
Integration: Tibber (documentation, issues)
First occurred: 21 December 2022 at 16:00:56 (1 occurrences)
Last logged: 21 December 2022 at 16:00:56

Timeout fetching Tibber XX data

Danielhiversen commented 1 year ago

@ashpool That is because of issues at Tibber.

cod3gen commented 1 year ago

I am also experiencing similiar issues. This last month the tibber sensors have been unavailable, or not been updating mostly. @Danielhiversen i am attaching some logs for you to help debug, this is on HA 2022.12.8.

Logger: tibber.tibber_home
Source: runner.py:120
First occurred: December 28, 2022 at 10:23:33 (62251 occurrences)
Last logged: 09:24:17

No data received for 1 seconds, reconnecting home 99d95b83-e810-4c1f-9c3d-15ae0a2fea79 in 59 seconds
No data received for 1 seconds, reconnecting home 99d95b83-e810-4c1f-9c3d-15ae0a2fea79 in 28 seconds
No data received for 1 seconds, reconnecting home 99d95b83-e810-4c1f-9c3d-15ae0a2fea79 in 33 seconds
No data received for 1 seconds, reconnecting home 99d95b83-e810-4c1f-9c3d-15ae0a2fea79 in 30 seconds
No data received for 1 seconds, reconnecting home 99d95b83-e810-4c1f-9c3d-15ae0a2fea79 in 32 seconds

Logger: tibber.tibber_home
Source: /usr/local/lib/python3.10/site-packages/tibber/tibber_home.py:495
First occurred: December 28, 2022 at 10:59:02 (53105 occurrences)
Last logged: 09:24:17

Tibber connection closed
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 482, in _start
    await self._tibber_control.rt_connect()
  File "/usr/local/lib/python3.10/site-packages/tibber/__init__.py", line 103, in rt_connect
    await self.sub_manager.connect_async()
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 632, in connect_async
    await self.transport.connect()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 490, in connect
    self.websocket = await asyncio.wait_for(
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 650, in _wrap_awaitable
    return (yield from awaitable.__await__())
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 659, in __await_impl_timeout__
    return await asyncio.wait_for(self.__await_impl__(), self.open_timeout)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 666, in __await_impl__
    await protocol.handshake(
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 332, in handshake
    raise InvalidStatusCode(status_code, response_headers)
websockets.exceptions.InvalidStatusCode: server rejected WebSocket connection: HTTP 428

Logger: tibber
Source: components/tibber/__init__.py:55
First occurred: December 28, 2022 at 10:20:45 (1027 occurrences)
Last logged: 09:23:51

Error connecting to Tibber, resp code: 428
Timed out when connecting to Tibber

Logger: tibber.tibber_home
Source: /usr/local/lib/python3.10/site-packages/tibber/tibber_home.py:495
First occurred: December 28, 2022 at 13:58:16 (9 occurrences)
Last logged: 07:50:18

Tibber connection closed
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 968, in transfer_data
    message = await self.read_message()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1038, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1113, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1170, in read_frame
    frame = await Frame.read(
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/framing.py", line 69, in read
    data = await reader(2)
  File "/usr/local/lib/python3.10/asyncio/streams.py", line 706, in readexactly
    raise exceptions.IncompleteReadError(incomplete, n)
asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 2 expected bytes

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 483, in _start
    async for data in self._tibber_control.sub_manager.session.subscribe(
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe
    answer_type, execution_result = await listener.get()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get
    raise item
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 301, in _receive_data_loop
    answer = await self._receive()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 231, in _receive
    data: Data = await self.websocket.recv()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 568, in recv
    await self.ensure_open()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 944, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: no close frame received or sent

Logger: homeassistant.components.sensor
Source: helpers/entity_platform.py:520
Integration: Sensor ([documentation](https://www.home-assistant.io/integrations/sensor), [issues](https://github.com/home-assistant/home-assistant/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+sensor%22))
First occurred: December 28, 2022 at 16:21:25 (98 occurrences)
Last logged: 05:21:44

Platform tibber does not generate unique IDs. ID 99d95b83-e810-4c1f-9c3d-15ae0a2fea79_rt_current L1 already exists - ignoring sensor.current_l1_x
Platform tibber does not generate unique IDs. ID 99d95b83-e810-4c1f-9c3d-15ae0a2fea79_rt_current L2 already exists - ignoring sensor.current_l2_x
Platform tibber does not generate unique IDs. ID 99d95b83-e810-4c1f-9c3d-15ae0a2fea79_rt_current L3 already exists - ignoring sensor.current_l3_x
Platform tibber does not generate unique IDs. ID 99d95b83-e810-4c1f-9c3d-15ae0a2fea79_rt_accumulated cost already exists - ignoring sensor.accumulated_cost_x
Platform tibber does not generate unique IDs. ID 99d95b83-e810-4c1f-9c3d-15ae0a2fea79_rt_power factor already exists - ignoring sensor.power_factor_x

Logger: tibber.tibber_home
Source: /usr/local/lib/python3.10/site-packages/tibber/tibber_home.py:495
First occurred: December 28, 2022 at 10:27:37 (519 occurrences)
Last logged: 05:21:42

Tibber connection closed
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 482, in _start
    await self._tibber_control.rt_connect()
  File "/usr/local/lib/python3.10/site-packages/tibber/__init__.py", line 103, in rt_connect
    await self.sub_manager.connect_async()
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 632, in connect_async
    await self.transport.connect()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 512, in connect
    await self._initialize()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 152, in _initialize
    await self._send_init_message_and_wait_ack()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 149, in _send_init_message_and_wait_ack
    await asyncio.wait_for(self._wait_ack(), self.ack_timeout)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 126, in _wait_ack
    answer_type, answer_id, execution_result = self._parse_answer(init_answer)
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 425, in _parse_answer
    return self._parse_answer_apollo(json_answer)
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets.py", line 398, in _parse_answer_apollo
    raise TransportServerError(f"Server error: '{repr(error_payload)}'")
gql.transport.exceptions.TransportServerError: Server error: '{'message': 'Prohibited connection!'}'

Logger: tibber.tibber_home
Source: /usr/local/lib/python3.10/site-packages/tibber/tibber_home.py:495
First occurred: December 28, 2022 at 10:23:31 (12 occurrences)
Last logged: December 28, 2022 at 14:30:11

Tibber connection closed
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 483, in _start
    async for data in self._tibber_control.sub_manager.session.subscribe(
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe
    answer_type, execution_result = await listener.get()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get
    raise item
gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user

Logger: homeassistant.components.sensor
Source: helpers/entity_platform.py:430
Integration: Sensor ([documentation](https://www.home-assistant.io/integrations/sensor), [issues](https://github.com/home-assistant/home-assistant/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+sensor%22))
First occurred: December 28, 2022 at 11:37:54 (1 occurrences)
Last logged: December 28, 2022 at 11:37:54

Timed out adding entities for domain sensor with platform tibber after 500s

Logger: tibber
Source: runner.py:120
First occurred: December 28, 2022 at 11:11:09 (8601 occurrences)
Last logged: December 28, 2022 at 11:37:54

Error connecting to Tibber, resp code: 428

Logger: tibber
Source: components/tibber/sensor.py:392
First occurred: December 28, 2022 at 11:11:09 (1 occurrences)
Last logged: December 28, 2022 at 11:11:09

Error connecting to Tibber, resp code: 428

Logger: homeassistant.components.sensor
Source: components/tibber/sensor.py:276
Integration: Sensor ([documentation](https://www.home-assistant.io/integrations/sensor), [issues](https://github.com/home-assistant/home-assistant/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+sensor%22))
First occurred: December 28, 2022 at 10:59:52 (1 occurrences)
Last logged: December 28, 2022 at 10:59:52

Error while setting up tibber platform for sensor
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 281, in _async_setup_platform
    await asyncio.shield(task)
  File "/usr/src/homeassistant/homeassistant/components/tibber/sensor.py", line 276, in async_setup_entry
    old_id = home.info["viewer"]["home"]["meteringPointData"]["consumptionEan"]
KeyError: 'viewer'

jreidel commented 1 year ago

I have the same issue, here is some data from the log (this is just looping):

2022-12-29 09:04:24.465 DEBUG (MainThread) [tibber.tibber_home] Last data timestamp: 2022-12-29 09:04:23.460999, 1s 2022-12-29 09:04:24.475 ERROR (MainThread) [tibber.tibber_home] No data received for 1 seconds, reconnecting home d6b2719a-5d62-4246-bb2f-3c61f09bc447 in 46 seconds 2022-12-29 09:04:24.806 ERROR (MainThread) [tibber] Error connecting to Tibber, resp code: 428 2022-12-29 09:04:25.087 DEBUG (MainThread) [tibber.tibber_home] Canceling previous run 2022-12-29 09:04:25.088 DEBUG (MainThread) [tibber.tibber_home] Closing connection 2022-12-29 09:04:25.088 DEBUG (MainThread) [tibber.tibber_home] Starting new run 2022-12-29 09:04:25.089 DEBUG (MainThread) [tibber.tibber_home] Last data timestamp: 2022-12-29 09:04:25.088635, 0s 2022-12-29 09:04:25.139 DEBUG (MainThread) [tibber.tibber_home] Canceling previous run 2022-12-29 09:04:25.139 DEBUG (MainThread) [tibber.tibber_home] Closing connection 2022-12-29 09:04:25.139 DEBUG (MainThread) [tibber.tibber_home] Starting new run 2022-12-29 09:04:25.140 DEBUG (MainThread) [tibber.tibber_home] Last data timestamp: 2022-12-29 09:04:25.139895, 0s 2022-12-29 09:04:25.377 ERROR (MainThread) [tibber.tibber_home] Tibber connection closed Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 482, in _start await self._tibber_control.rt_connect() File "/usr/local/lib/python3.10/site-packages/tibber/init.py", line 103, in rt_connect await self.sub_manager.connect_async() File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 632, in connect_async await self.transport.connect() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 490, in connect self.websocket = await asyncio.wait_for( File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for return fut.result() File "/usr/local/lib/python3.10/asyncio/tasks.py", line 650, in _wrap_awaitable return (yield from awaitable.await()) File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 659, in await_impl_timeout return await asyncio.wait_for(self.await_impl(), self.open_timeout) File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for return fut.result() File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 666, in await_impl await protocol.handshake( File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 332, in handshake raise InvalidStatusCode(status_code, response_headers) websockets.exceptions.InvalidStatusCode: server rejected WebSocket connection: HTTP 428 2022-12-29 09:04:25.671 ERROR (MainThread) [tibber.tibber_home] Tibber connection closed Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 482, in _start await self._tibber_control.rt_connect() File "/usr/local/lib/python3.10/site-packages/tibber/init.py", line 103, in rt_connect await self.sub_manager.connect_async() File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 632, in connect_async await self.transport.connect() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 490, in connect self.websocket = await asyncio.wait_for( File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for return fut.result() File "/usr/local/lib/python3.10/asyncio/tasks.py", line 650, in _wrap_awaitable return (yield from awaitable.await()) File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 659, in await_impl_timeout return await asyncio.wait_for(self.await_impl(), self.open_timeout) File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for return fut.result() File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 666, in await_impl await protocol.handshake( File "/usr/local/lib/python3.10/site-packages/websockets/legacy/client.py", line 332, in handshake raise InvalidStatusCode(status_code, response_headers) websockets.exceptions.InvalidStatusCode: server rejected WebSocket connection: HTTP 428 2022-12-29 09:04:25.931 DEBUG (MainThread) [tibber.tibber_home] Canceling previous run 2022-12-29 09:04:25.932 DEBUG (MainThread) [tibber.tibber_home] Closing connection 2022-12-29 09:04:25.932 DEBUG (MainThread) [tibber.tibber_home] Starting new run 2022-12-29 09:04:25.932 DEBUG (MainThread) [tibber.tibber_home] Last data timestamp: 2022-12-29 09:04:25.932308, 0s 2022-12-29 09:04:26.104 DEBUG (MainThread) [tibber.tibber_home] Last data timestamp: 2022-12-29 09:04:25.103614, 1s 2022-12-29 09:04:26.113 ERROR (MainThread) [tibber.tibber_home] No data received for 1 seconds, reconnecting home 30f10884-3f84-42ab-850f-fc3f3649149d in 25 seconds 2022-12-29 09:04:26.152 DEBUG (MainThread) [tibber.tibber_home] Last data timestamp: 2022-12-29 09:04:25.151604, 1s 2022-12-29 09:04:26.168 ERROR (MainThread) [tibber.tibber_home] No data received for 1 seconds, reconnecting home d6b2719a-5d62-4246-bb2f-3c61f09bc447 in 32 seconds 2022-12-29 09:04:26.224 ERROR (MainThread) [tibber.tibber_home] Tibber connection closed

RicardP commented 1 year ago

@Danielhiversen I do not see any clear improvement since months, running 2023.1.2, Today my 4pcs of Pulse dongle polling hanged in HA at CET 13:03:30, after manual reload (now 21:40:00) of the Tibber plugin it works again. How cannot this problem be nailed and forgotten? 😵 Still, many thanks for your efforts to provide a well working appreciated plugin 🤩😅

Danielhiversen commented 1 year ago

@RicardP Could you enable debug logging for Tibber and share the logs?

gulli1986 commented 1 year ago

From my side, running core 2023.1.2. Haven't had any issue on Tibber integration since your last 2 updates @Danielhiversen . Sometimes sensors become unavailable but they always come back by themselves, really happy, big improvement!

RicardP commented 1 year ago

@Danielhiversen Sure I activated debug log now. I think I need your help to extract the log later on... :)

However I checked my Grafana statistics since 24 hours and it looks like a lot of short period drop outs happening from Tibber side, Can it be that the Tibber integration gives up by times out after certain down time? Because the manual restart at 21:40 solved the problem?

Many thanks :)

clip

ChrVage commented 1 year ago

I finally logged when my Tibber pulse data disappeared from HA.

I have 2 pulse sensors in 2 locations. Both seems to drop simultaneously, but they have historically restored themselves in minutes or a few hours. Since I upgraded to 2022.12.08 and started logging "tibber: debug" they have been stable with one exception - that I didn't log.

My HA now runs on 2023.1.2

Yesterday (10/1) they dropped at 13:04. They did not recover until restart (11/1 10:00). This is what the log shows:

2023-01-09 10:01:02.680 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-09 10:01:02.835 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-09 10:01:05.293 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-09 10:01:08.287 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-09 10:01:09.165 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-09 10:01:11.982 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-09 10:01:12.962 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
(...)
2023-01-10 13:03:42.737 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-10 13:03:43.519 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-10 13:03:44.035 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-10 13:03:44.682 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-10 13:03:45.449 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-10 13:03:46.625 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-10 13:03:47.364 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-10 13:03:48.311 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-10 13:03:49.039 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-10 13:03:49.248 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-10 13:03:50.729 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-10 13:03:51.766 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-10 13:03:52.277 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-10 13:03:54.042 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-10 13:03:59.045 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-10 13:04:04.048 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-10 13:04:09.052 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-10 13:04:14.056 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-10 13:04:19.059 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-10 13:04:24.062 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
(...)
2023-01-11 09:38:58.688 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-11 09:39:03.691 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-11 09:39:08.695 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-11 09:39:13.698 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-11 09:39:18.701 DEBUG (MainThread) [tibber] Watchdog: Connection is alive

I restarted HA and they are both up and running again.

Will this help you @Danielhiversen ? I appreciate the work done, and I am more than willing to help if you need anything else.

// Christian

Danielhiversen commented 1 year ago

So after 2023-01-10 13:04:24.062, there is nothing else than "Watchdog: Connection is alive" ?

ChrVage commented 1 year ago

That's correct. Not one single Data received for after 13:04 yesterday.

Danielhiversen commented 1 year ago

Strange. Must be a case it still not handle correct. Thanks for the logs. Will look at it later.

RicardP commented 1 year ago

@Danielhiversen I lost my data at the same time as @ChrVage "13:03:30" and it did not recover by itself, like he reports as well, ...If you did not note this already.

Danielhiversen commented 1 year ago

So something probably happened with the Tibber API at that time, but the HA integration should be able to recover. I will look into it.

RicardP commented 1 year ago

@Danielhiversen Maybe Tibber API that rejects to many "requests" during certain time (even the error is on their side) and after some time Tibber HA integration times out because no response from Tibber API.... :)

gulli1986 commented 1 year ago

@RicardP , @ChrVage If that can help, I disabled my automation that reloaded the Tibber integration automatically since my sensors now seem to recover by themselves. Maybe that triggered too many requests to the Tibber API, do not know if that can explain your issues?

AgentFalcon commented 1 year ago

@RicardP , @ChrVage If that can help, I disabled my automation that reloaded the Tibber integration automatically since my sensors now seem to recover by themselves. Maybe that triggered too many requests to the Tibber API, do not know if that can explain your issues?

I still have my reload automation on. It checks every 15min if theres been >2min of inactivity of the power entity and I see in the log that it triggered yesterday at 13.15 (norway time).
So seems like something happened areoubd 13.00 as others have noted. But it recovered after the reload.

Although, if a reload automation is set to run too quickly and keeps trying lots of times in a short period, maybe Tibber times you out for a while.

RicardP commented 1 year ago

@Danielhiversen Issue happened again, no data since yesterday 15/1 CET: 20:46. After reload of Tibber addon now 16/1 10:46 it started up again. Unfortunately I turned off logging since fix 0.26.8, will activate now again.

datom commented 1 year ago

@Danielhiversen Here also. It stopped at the exact same time "CET: 20:46" like @RicardP

Danielhiversen commented 1 year ago

Anything in the logs?

Danielhiversen commented 1 year ago

Are you both using 2023.1.4 or newer?

RicardP commented 1 year ago

Sorry could told, I am on 2023.1.4 "since it came".

Danielhiversen commented 1 year ago

No errors in the log?

RicardP commented 1 year ago

I wrote earlier "I unfortunately turned off logging after the fix 0.26.8" ...it is on again since.

Danielhiversen commented 1 year ago

Errors should still be logged. Or do you also disabled error logging?

RicardP commented 1 year ago

Ok I found out I think :)

2023-01-15 20:46:38.646 ERROR (MainThread) [tibber] Watchdog: Connection is down, 2023-01-15 20:48:07.284779, True 2023-01-16 10:28:39.039 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( 2023-01-16 10:28:39.044 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( 2023-01-16 10:28:39.048 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( 2023-01-16 10:28:39.053 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( 2023-01-16 10:28:39.054 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( 2023-01-16 10:41:09.606 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 2 data 2023-01-16 10:41:09.609 DEBUG (MainThread) [tibber.tibber_home] Data received for e46ec8f5-bfc5-46d0-88c8-cce8e151e2f9 2023-01-16 10:41:09.649 DEBUG (MainThread) [tibber] Watchdog: Connection is alive 2023-01-16 10:41:09.916 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -1 data 2023-01-16 10:41:09.918 DEBUG (MainThread) [tibber.tibber_home] Data received for cf94b695-602f-4cee-9c08-b201983b655e 2023-01-16 10:41:09.924 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 1 data 2023-01-16 10:41:09.925 DEBUG (MainThread) [tibber.tibber_home] Data received for d912f4c9-fe77-4321-b7ed-75395ce4e86c 2023-01-16 10:41:09.951 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -3 data 2023-01-16 10:41:09.952 DEBUG (MainThread) [tibber.tibber_home] Data received for 46305150-a7c7-47cc-a2a5-cabf14384be3 2023-01-16 10:41:10.085 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 2 data 2023-01-16 10:41:10.087 DEBUG (MainThread) [tibber.tibber_home] Data received for e46ec8f5-bfc5-46d0-88c8-cce8e151e2f9 2023-01-16 10:41:10.525 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -2 data 2023-01-16 10:41:10.527 DEBUG (MainThread) [tibber.tibber_home] Data received for 296f2621-dab0-4b52-b9f7-be28a8a27473 2023-01-16 10:41:10.819 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -1 data 2023-01-16 10:41:10.820 DEBUG (MainThread) [tibber.tibber_home] Data received for cf94b695-602f-4cee-9c08-b201983b655e 2023-01-16 10:41:10.831 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 1 data 2023-01-16 10:41:10.833 DEBUG (MainThread) [tibber.tibber_home] Data received for d912f4c9-fe77-4321-b7ed-75395ce4e86c 2023-01-16 10:41:10.947 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -3 data 2023-01-16 10:41:10.949 DEBUG (MainThread) [tibber.tibber_home] Data received for 46305150-a7c7-47cc-a2a5-cabf14384be3 2023-01-16 10:41:11.311 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -1 data 2023-01-16 10:41:11.313 DEBUG (MainThread) [tibber.tibber_home] Data received for cf94b695-602f-4cee-9c08-b201983b655e 2023-01-16 10:41:11.517 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -2 data 2023-01-16 10:41:11.519 DEBUG (MainThread) [tibber.tibber_home] Data received for 296f2621-dab0-4b52-b9f7-be28a8a27473 2023-01-16 10:41:11.574 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 2 data 2023-01-16 10:41:11.576 DEBUG (MainThread) [tibber.tibber_home] Data received for e46ec8f5-bfc5-46d0-88c8-cce8e151e2f9 2023-01-16 10:41:11.806 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 1 data 2023-01-16 10:41:11.807 DEBUG (MainThread) [tibber.tibber_home] Data received for d912f4c9-fe77-4321-b7ed-75395ce4e86c 2023-01-16 10:41:11.985 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -3 data 2023-01-16 10:41:11.987 DEBUG (MainThread) [tibber.tibber_home] Data received for 46305150-a7c7-47cc-a2a5-cabf14384be3 2023-01-16 10:41:12.059 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 2 data 2023-01-16 10:41:12.060 DEBUG (MainThread) [tibber.tibber_home] Data received for e46ec8f5-bfc5-46d0-88c8-cce8e151e2f9 2023-01-16 10:41:12.503 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -2 data 2023-01-16 10:41:12.505 DEBUG (MainThread) [tibber.tibber_home] Data received for 296f2621-dab0-4b52-b9f7-be28a8a27473 2023-01-16 10:41:12.778 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -1 data 2023-01-16 10:41:12.779 DEBUG (MainThread) [tibber.tibber_home] Data received for cf94b695-602f-4cee-9c08-b201983b655e 2023-01-16 10:41:12.921 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -3 data 2023-01-16 10:41:12.923 DEBUG (MainThread) [tibber.tibber_home] Data received for 46305150-a7c7-47cc-a2a5-cabf14384be3 2023-01-16 10:41:13.045 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 2 data 2023-01-16 10:41:13.046 DEBUG (MainThread) [tibber.tibber_home] Data received for e46ec8f5-bfc5-46d0-88c8-cce8e151e2f9 2023-01-16 10:41:13.281 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 1 data 2023-01-16 10:41:13.282 DEBUG (MainThread) [tibber.tibber_home] Data received for d912f4c9-fe77-4321-b7ed-75395ce4e86c 2023-01-16 10:41:13.484 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -2 data 2023-01-16 10:41:13.485 DEBUG (MainThread) [tibber.tibber_home] Data received for 296f2621-dab0-4b52-b9f7-be28a8a27473 2023-01-16 10:41:13.798 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -1 data 2023-01-16 10:41:13.800 DEBUG (MainThread) [tibber.tibber_home] Data received for cf94b695-602f-4cee-9c08-b201983b655e 2023-01-16 10:41:13.886 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -3 data 2023-01-16 10:41:13.887 DEBUG (MainThread) [tibber.tibber_home] Data received for 46305150-a7c7-47cc-a2a5-cabf14384be3 2023-01-16 10:41:14.022 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 2 data 2023-01-16 10:41:14.024 DEBUG (MainThread) [tibber.tibber_home] Data received for e46ec8f5-bfc5-46d0-88c8-cce8e151e2f9 2023-01-16 10:41:14.257 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 1 data 2023-01-16 10:41:14.259 DEBUG (MainThread) [tibber.tibber_home] Data received for d912f4c9-fe77-4321-b7ed-75395ce4e86c 2023-01-16 10:41:14.469 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -2 data 2023-01-16 10:41:14.470 DEBUG (MainThread) [tibber.tibber_home] Data received for 296f2621-dab0-4b52-b9f7-be28a8a27473 2023-01-16 10:41:14.652 DEBUG (MainThread) [tibber] Watchdog: Connection is alive 2023-01-16 10:41:14.737 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -1 data 2023-01-16 10:41:14.739 DEBUG (MainThread) [tibber.tibber_home] Data received for cf94b695-602f-4cee-9c08-b201983b655e 2023-01-16 10:41:14.857 DEBUG (MainThread) [homeassistant.components.tibber.sensor] Manually updated Site 3 -3 data

ChrVage commented 1 year ago

My log at 15.01.2023 20:46 showed something, but I still received data after it happened:

2023-01-15 20:46:34.592 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-15 20:46:35.067 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-15 20:46:36.568 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-15 20:46:37.017 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-15 20:46:38.528 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-15 20:46:39.410 ERROR (MainThread) [tibber] Watchdog: Connection is down, 2023-01-15 20:48:08.522860, True
2023-01-15 20:46:41.487 WARNING (MainThread) [gql.transport.websockets] Ignoring exception in _clean_close: ConnectionClosedOK(Close(code=1001, reason='Going away'), Close(code=1001, reason='Going away'), True)
2023-01-15 20:46:42.490 DEBUG (MainThread) [tibber] Watchdog: Reconnected successfully
2023-01-15 20:46:42.492 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-15 20:46:47.495 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-15 20:46:52.498 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-15 20:46:56.523 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-15 20:46:57.117 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-15 20:46:57.501 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-15 20:46:58.927 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73

The data disappeared 16.01.2023 at 00:02:

2023-01-16 00:02:05.621 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-16 00:02:06.078 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-16 00:02:06.703 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-16 00:02:07.214 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-16 00:02:08.672 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-16 00:02:11.081 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-16 00:02:16.084 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-16 00:02:21.087 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-16 00:02:26.090 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-16 00:02:31.094 DEBUG (MainThread) [tibber] Watchdog: Connection is alive

It came back a bit later:

2023-01-16 10:55:36.646 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-16 10:55:41.650 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-16 10:55:46.653 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-16 10:55:51.657 DEBUG (MainThread) [tibber] Watchdog: Connection is alive

(...)

2023-01-16 10:55:55.179 DEBUG (MainThread) [tibber] Stopping watchdog
2023-01-16 10:55:55.707 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-16 10:55:56.411 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73

Edit: Will this help, or do you need more information?

Danielhiversen commented 1 year ago

@ChrVage So no data between 2023-01-16 00:02:08.672 and 2023-01-16 10:55:55.707 ? Do you also use 2023.1.4 or newer?

ChrVage commented 1 year ago

I use 2023.1.4 and I found no Data received for ... between 023-01-16 00:02:08.672 and 2023-01-16 10:55:55.707.

Danielhiversen commented 1 year ago

Another try: https://github.com/home-assistant/core/pull/86044 This is difficult to debug, when I am not able to reproduce it myself.

ChrVage commented 1 year ago

I am running HA Core 2023.1.5 since January 18th.

At 2023-01-19 16:24 data from Tibber stopped:

2023-01-19 16:24:26.560 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-19 16:24:28.227 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-19 16:24:28.532 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-19 16:24:30.758 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-19 16:24:30.973 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-19 16:24:31.411 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-19 16:24:32.162 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-19 16:24:32.452 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-19 16:24:34.405 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-19 16:24:34.608 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-19 16:24:36.365 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-19 16:24:36.412 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-19 16:24:41.413 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-19 16:24:46.416 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-19 16:24:51.417 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-19 16:24:56.419 DEBUG (MainThread) [tibber] Watchdog: Connection is alive
2023-01-19 16:25:01.421 DEBUG (MainThread) [tibber] Watchdog: Connection is alive

No data received before I manually reloaded the integration at 2023-01-20 09:40:

2023-01-20 09:40:17.303 DEBUG (MainThread) [tibber] Stopping watchdog
2023-01-20 09:40:18.699 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-20 09:40:19.323 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:21.189 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-20 09:40:21.303 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:23.123 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-20 09:40:23.257 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:25.080 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-20 09:40:25.212 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:27.036 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f
2023-01-20 09:40:27.164 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:27.312 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start
    async for data in self._tibber_control.sub_manager.session.subscribe(
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe
    answer_type, execution_result = await listener.get()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get
    raise item
gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user
2023-01-20 09:40:27.319 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start
    async for data in self._tibber_control.sub_manager.session.subscribe(
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe
    answer_type, execution_result = await listener.get()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get
    raise item
  File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start
    async for data in self._tibber_control.sub_manager.session.subscribe(
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe
    async for result in inner_generator:
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe
    answer_type, execution_result = await listener.get()
  File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get
    raise item
gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user
2023-01-20 09:40:28.375 DEBUG (MainThread) [tibber] Starting watchdog
2023-01-20 09:40:29.140 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:31.578 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:33.069 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:35.105 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:37.189 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:37.736 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform tibber is taking over 10 seconds.
2023-01-20 09:40:39.626 DEBUG (MainThread) [tibber.tibber_home] Data received for 5a851a78-ff3d-445d-91a0-cf26f8299b73
2023-01-20 09:40:41.262 DEBUG (MainThread) [tibber.tibber_home] Data received for 25c66787-6c30-4655-93ad-e236e4f41c6f

I can see some errors in the end here, I hope you can make sense of them @Danielhiversen

frenck commented 1 year ago

I am running HA Core 2023.1.5 since January 18th.

This fix is closed in #86044, which is not in that release.

ChrVage commented 1 year ago

Ok, this was in the release notes of 2023.1.5, so I assumed it to be in there:

Update pyTibber to 0.26.8 (@Danielhiversen - #86044) (tibber docs) (dependency)

Danielhiversen commented 1 year ago

Another try to fix this was included in 2023.1.7

LAPDragnet commented 1 year ago

I still have it in 2023.1 7. Happens 2-5 times per week. Last time 2 hours ago.

RicardP commented 1 year ago

@Danielhiversen (2023.1.7) From 14:59 no data was received until I reloaded Tibber plugin at 19:17....

2023-01-23 14:59:56.284 ERROR (MainThread) [tibber] Watchdog: Connection is down, 2023-01-23 15:01:22.743427 2023-01-23 16:45:43.683 WARNING (MainThread) [zigpy_deconz.api] No response to 'Command.aps_data_indication' command with seq id '0xb6' 2023-01-23 16:45:49.701 WARNING (MainThread) [zigpy_deconz.api] No response to 'Command.aps_data_indication' command with seq id '0xb9' 2023-01-23 16:45:55.716 WARNING (MainThread) [zigpy_deconz.api] No response to 'Command.aps_data_indication' command with seq id '0xbc' 2023-01-23 18:47:32.776 ERROR (MainThread) [custom_components.hacs] Could not update integration - Timeout of 60s reached 2023-01-23 18:47:32.777 ERROR (MainThread) [custom_components.hacs] Could not update theme - Timeout of 60s reached 2023-01-23 19:17:54.950 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user 2023-01-23 19:17:54.952 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user 2023-01-23 19:17:54.954 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user 2023-01-23 19:17:54.956 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user 2023-01-23 19:17:54.958 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start async for data in self._tibber_control.sub_manager.session.subscribe( File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe async for result in inner_generator: File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe answer_type, execution_result = await listener.get() File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get raise item gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user

4homeassistant commented 1 year ago

Got that log entry this morning but it recovered and I received live data until 15:00 before it stopped.

2023-01-23 10:47:33.194 ERROR (MainThread) [tibber] Watchdog: Connection is down, 2023-01-23 10:48:57.386995
2023-01-23 10:47:33.706 ERROR (MainThread) [tibber] Error in watchdog connect, retrying in 60 seconds, 1
2023-01-23 10:48:33.711 ERROR (MainThread) [tibber] Watchdog: Connection is down, 2023-01-23 10:49:03.202815
2023-01-23 10:48:52.611 WARNING (MainThread) [homeassistant.components.rest.sensor] JSON result was not a dictionary or list with 0th element a dictionary
2023-01-23 10:48:54.604 ERROR (MainThread) [tibber.tibber_home] Error in rt_subscribe
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/tibber/tibber_home.py", line 414, in _start
async for data in self._tibber_control.sub_manager.session.subscribe(
File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 1064, in subscribe
async for result in inner_generator:
File "/usr/local/lib/python3.10/site-packages/gql/client.py", line 960, in _subscribe
async for result in inner_generator:
File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 388, in subscribe
answer_type, execution_result = await listener.get()
File "/usr/local/lib/python3.10/site-packages/gql/transport/websockets_base.py", line 56, in get
raise item
gql.transport.exceptions.TransportClosed: Websocket GraphQL transport closed by user
2023-01-23 10:48:55.378 ERROR (MainThread) [tibber] Error connecting to Tibber, resp code: 500

It stopped parallel to that log entry and didn't come back until I reloaded the integration:

2023-01-23 14:59:56.338 ERROR (MainThread) [tibber] Watchdog: Connection is down, 2023-01-23 15:01:21.792695

Two times in three days. I see that you are trying to fix it @Danielhiversen but it doesn't seem to work. Is there anything I can do to make it easier for you. Just enabled debug logging to hopefully see more details but this throws a huge amount of data.

Danielhiversen commented 1 year ago

@RicardP @4homeassistant Are you both using 2023.1.7 (released yesterday)?

4homeassistant commented 1 year ago

@Danielhiversen, yes upgraded yesterday to 2013.1.7 but your latest changes didn't fix it unfortunately. How can I support you?

RicardP commented 1 year ago

@RicardP @4homeassistant Are you both using 2023.1.7 (released yesterday)?

Yes, updated yesterday.

blackburn77 commented 1 year ago

I also had these issues frequently after upgrading from 2022.10.5 (with pytibber 0.25.2) to 2022.11.5 (with pytibber 0.26.1) and reloading the integration didn't help whenever the reporting stopped like it did almost daily. So about a month ago I downgraded to 2022.10.5 / pytibber 0.25.2 again and all issues are gone and reloading works again whenever Tibber is having issues (like today around 10.50CET). Just FYI if it can be of any help troubleshooting this.

Danielhiversen commented 1 year ago

It would be great if you could make sure you have pyTibber 0.26.11. It can take up to 60 minutes before the integration reconnects. So some downtime is expected, but it should recover itself after a while. I do not have a Tibber Pulse, so need some debug logging.


logger:
  logs:
    tibber: debug

It would be great to open a new issue with debug info.