search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.56k forks source link

[Tibber] Fetching of new data stops occasionally #14735

Open tunichtviel opened 1 year ago

tunichtviel commented 1 year ago

Expected Behavior

Tibber data is continuously fetched/updated.

Current Behavior

Occasionally, the Tibber data is not updated any more.

This happens in average rougly one time per week.

Fetching of data is resumed after disable/enable of the Tibber thing.

Sometimes occurs at midnight (possibly related to issue #13417); sometimes in the middle of the day.

This problem is also described in https://community.openhab.org/t/tibber-binding-hangs-when-a-new-week-starts/139308/3

The logging seems not to provide helpful information. This was the logging when the stop occurred at midnight:

<Logger level="ALL" name="org.openhab.binding.tibber"/>

2023-02-18 23:57:43.553 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-18 23:58:44.741 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-18 23:59:47.714 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-19 00:00:48.141 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-19 00:01:48.315 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-19 00:02:49.093 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-19 00:03:55.139 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}

Steps to Reproduce (for Bugs)

  1. Wait until no more data is fetched
  2. Disable & enable the Tibber thing ->fetching of data is resumed

Context

I use Tibber power consumption/production data.

Your Environment

lsiepel commented 1 year ago

Do you have some logging just before the null responses?

tunichtviel commented 1 year ago

Do you have some logging just before the null responses?

The logging before is identical (i.e. the null responses), it repeats, days long, one log line per minute. This is also the logging when everything works fine.

The only other logging occurs when I disable & enable the Tibber thing (I replaced the token&IDs with xxxx):

2023-04-02 08:55:15.023 [DEBUG] [ibber.internal.handler.TibberHandler] - Sending websocket disconnect message
2023-04-02 08:55:15.025 [DEBUG] [ibber.internal.handler.TibberHandler] - Send message: {"type":"connection_terminate","payload":null}
2023-04-02 08:55:15.028 [DEBUG] [ibber.internal.handler.TibberHandler] - Closing a WebSocket due to Disconnected
2023-04-02 08:55:15.031 [DEBUG] [ibber.internal.handler.TibberHandler] - DISPOSE - Stopping and Terminating Websocket connection
2023-04-02 08:55:15.857 [DEBUG] [ibber.internal.handler.TibberHandler] - Binding version: 3.4.2
2023-04-02 08:55:16.047 [DEBUG] [ibber.internal.handler.TibberHandler] - Pulse associated with HomeId: Live stream will be started
2023-04-02 08:55:16.097 [DEBUG] [ibber.internal.handler.TibberHandler] - Subscribing to: wss://websocket-api.tibber.com/v1-beta/gql/subscriptions
2023-04-02 08:55:16.106 [DEBUG] [ibber.internal.handler.TibberHandler] - New socket being created
2023-04-02 08:55:16.107 [DEBUG] [ibber.internal.handler.TibberHandler] - Starting Websocket connection
2023-04-02 08:55:16.119 [DEBUG] [ibber.internal.handler.TibberHandler] - Connecting Websocket connection
2023-04-02 08:55:16.477 [DEBUG] [ibber.internal.handler.TibberHandler] - Sending websocket connect message
2023-04-02 08:55:16.478 [DEBUG] [ibber.internal.handler.TibberHandler] - Send message: {"type":"connection_init", "payload":{"token":"xxxx"}}
2023-04-02 08:55:16.541 [DEBUG] [ibber.internal.handler.TibberHandler] - Connected to Server
2023-04-02 08:55:16.542 [DEBUG] [ibber.internal.handler.TibberHandler] - Send message: {"id":"1","type":"subscribe","payload":{"variables":null,"extensions":null,"operationName":null,"query":"subscription {\n liveMeasurement(homeId:\"xxxx\") {\n timestamp\n power\n lastMeterConsumption\n accumulatedConsumption\n accumulatedCost\n currency\n minPower\n averagePower\n maxPower\nvoltagePhase1\n voltagePhase2\n voltagePhase3\n currentL1\n currentL2\n currentL3\n powerProduction\n accumulatedProduction\n minPowerProduction\n maxPowerProduction\n }\n }\n"}}
2023-04-02 08:55:26.122 [DEBUG] [ibber.internal.handler.TibberHandler] - Websocket session established
sdillenburg commented 3 weeks ago

I have the same problem. My Tibber binding stops approximately every 2 days. Disabling & enabling the Tibber thing makes the binding work again.

Anything I can assist with in solving the issue?

Is there a workaround, i.e. automatically disable and enable the Tibber thing on a regular basis?

openHAB 4.2.0.M3 on openhabian Raspberry Pi

tunichtviel commented 3 weeks ago

I still have this problem continuously in my environment (openHAB 4.1.2 also on a Raspberry)

Is there a workaround, i.e. automatically disable and enable the Tibber thing on a regular basis?

That's what I do: via cron job I periodically disable and re-enable the "Tibber API" thing. Every few hours.

lsiepel commented 2 weeks ago

Can you try latest 4.2 milestone with the jar file from the link below? and set the binding in debug mode. https://1drv.ms/u/s!AnMcxmvEeupwjvdUQL4Mzu1apc-F3A?e=1lcUga

Fixed some possible NPE's, added additional logging. Hopefully this is either fixed or ginving a lead to the actual cause.

tunichtviel commented 2 weeks ago

Fixed some possible NPE's, added additional logging. Hopefully this is either fixed or ginving a lead to the actual cause.

That's great!!

I have 4.2.0 running since yesterday.

Today I had a 2 hours interruption in my Tibber data. My internet router did not complain about a lost connection.

Last update on an item before the interruption was (from events.log):

2024-07-09 13:36:23.667 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Tibber_API_Power_ProductionNegative' changed from -2610.0 to -2646.0

From openhab.log:

2024-07-09 13:39:09.087 [WARN ] [ibber.internal.handler.TibberHandler] - IO Exception: java.util.concurrent.TimeoutException: Total timeout 20000 ms elapsed

Then no more Tibber log messages (default log4j2.xml; root logger is set to WARN) until 2024-07-09 15:40:52.674 [WARN ] [ibber.internal.handler.TibberHandler] - Websocket Client Stop Exception: java.lang.InterruptedException

Then:

2024-07-09 15:47:05.017 [WARN ] [ty.websocket.common.WebSocketSession] - Exception while notifying onError
org.eclipse.jetty.websocket.api.WebSocketException: Session closed
    at org.eclipse.jetty.websocket.common.WebSocketSession.outgoingFrame(WebSocketSession.java:350) ~[bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint.uncheckedSendFrame(WebSocketRemoteEndpoint.java:322) ~[bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint.blockingWrite(WebSocketRemoteEndpoint.java:109) ~[bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint.sendString(WebSocketRemoteEndpoint.java:400) ~[bundleFile:9.4.54.v20240208]
    at org.openhab.binding.tibber.internal.handler.TibberHandler$TibberWebSocketListener.sendMessage(TibberHandler.java:634) ~[?:?]
    at org.openhab.binding.tibber.internal.handler.TibberHandler.close(TibberHandler.java:464) ~[?:?]
    at org.openhab.binding.tibber.internal.handler.TibberHandler$TibberWebSocketListener.onWebSocketError(TibberHandler.java:538) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
    at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:70) ~[bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72) ~[bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onError(JettyAnnotatedEventDriver.java:192) ~[bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.WebSocketSession.callApplicationOnError(WebSocketSession.java:416) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.close(AbstractWebSocketConnection.java:209) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher.onCompleteFailure(AbstractWebSocketConnection.java:100) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:333) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:229) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.outgoingFrame(AbstractWebSocketConnection.java:581) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.client.io.WebSocketClientConnection.outgoingFrame(WebSocketClientConnection.java:58) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.close(AbstractWebSocketConnection.java:181) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:510) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:440) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.54.v20240208]
    at java.lang.Thread.run(Thread.java:840) [?:?]
2024-07-09 15:47:35.015 [WARN ] [ibber.internal.handler.TibberHandler] - Websocket Client Stop Exception: java.lang.InterruptedException

Resuming of data: 2024-07-09 15:47:38.778 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Tibber_API_Power_consumptionproduction2' changed from 2646 W to 6187 W

Those "long" WebSocketException are repeated for a few times during the next minutes.

Ok, what should I set in log4j2.xml to get more information? Can I filter my log for something like "Tibber", because I have plenty of log entries from other devices/services.