Tibber binding hangs when a new week starts

My Tibber binding stop getting values after midnight between sunday and monday. After disabling the Tibber thing and then enable it again it start working.
Here is my log:

2022-09-26 00:02:38.059 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":{"priceInfo":{"current":{"total":1.7853,"startsAt":"2022-09-26T00:00:00.000+02:00","level":"VERY_CHEAP"}}},"daily":{"nodes":[{"from":"2022-09-25T00:00:00.000+02:00","to":"2022-09-26T00:00:00.000+02:00","cost":51.6696666,"unitPrice":2.230217,"consumption":23.168,"consumptionUnit":"kWh"}]},"hourly":{"nodes":[{"from":"2022-09-25T23:00:00.000+02:00","to":"2022-09-26T00:00:00.000+02:00","cost":null,"unitPrice":0.661675,"consumption":null,"consumptionUnit":"kWh"}]}}}}}
2022-09-26 00:03:37.975 [DEBUG] [ibber.internal.handler.TibberHandler] - Error during websocket communication: java.util.concurrent.TimeoutException: Idle timeout expired: 30001/30000 ms
2022-09-26 00:03:37.977 [DEBUG] [ibber.internal.handler.TibberHandler] - Sending websocket disconnect message
2022-09-26 00:03:37.977 [DEBUG] [ibber.internal.handler.TibberHandler] - Send message: {"type":"connection_terminate","payload":null}
2022-09-26 00:03:38.084 [DEBUG] [ibber.internal.handler.TibberHandler] - Closing a WebSocket due to Disconnected
2022-09-26 00:03:38.139 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":{"priceInfo":{"current":{"total":1.7853,"startsAt":"2022-09-26T00:00:00.000+02:00","level":"VERY_CHEAP"}}},"daily":{"nodes":[{"from":"2022-09-25T00:00:00.000+02:00","to":"2022-09-26T00:00:00.000+02:00","cost":51.6696666,"unitPrice":2.230217,"consumption":23.168,"consumptionUnit":"kWh"}]},"hourly":{"nodes":[{"from":"2022-09-25T23:00:00.000+02:00","to":"2022-09-26T00:00:00.000+02:00","cost":null,"unitPrice":0.661675,"consumption":null,"consumptionUnit":"kWh"}]}}}}}
2022-09-26 00:03:38.142 [DEBUG] [ibber.internal.handler.TibberHandler] - Attempting to reopen Websocket connection
2022-09-26 00:03:53.090 [WARN ] [org.eclipse.jetty.io.ManagedSelector] - java.nio.channels.ClosedSelectorException
2022-09-26 00:03:53.090 [WARN ] [ibber.internal.handler.TibberHandler] - CLOSE FRAME - Failed to stop websocket client: null
2022-09-26 00:03:53.201 [DEBUG] [ibber.internal.handler.TibberHandler] - New socket being created
2022-09-26 00:03:53.203 [DEBUG] [ibber.internal.handler.TibberHandler] - Starting Websocket connection
2022-09-26 00:03:53.208 [WARN ] [ty.util.ssl.SslContextFactory.config] - Trusting all certificates configured for Client@732d2941[provider=null,keyStore=null,trustStore=null]
2022-09-26 00:03:53.208 [WARN ] [ty.util.ssl.SslContextFactory.config] - No Client EndPointIdentificationAlgorithm configured for Client@732d2941[provider=null,keyStore=null,trustStore=null]
2022-09-26 00:03:53.209 [DEBUG] [ibber.internal.handler.TibberHandler] - Connecting Websocket connection
2022-09-26 00:03:53.390 [DEBUG] [ibber.internal.handler.TibberHandler] - Sending websocket connect message
2022-09-26 00:03:53.390 [DEBUG] [ibber.internal.handler.TibberHandler] - Send message: {"type":"connection_init", "payload":"token=XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"}
2022-09-26 00:03:53.439 [DEBUG] [ibber.internal.handler.TibberHandler] - Connected to Server
2022-09-26 00:03:53.439 [DEBUG] [ibber.internal.handler.TibberHandler] - Send message: {"id":"1","type":"start","payload":{"variables":null,"extensions":null,"operationName":null,"query":"subscription {\n liveMeasurement(homeId:\"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX\") {\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"}}
2022-09-26 00:03:53.553 [DEBUG] [ibber.internal.handler.TibberHandler] - Error/terminate received from server: {"type":"data","id":"1","payload":{"errors":[{"message":"unable to start stream api:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX for device XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX","locations":[{"line":2,"column":2}],"path":["liveMeasurement"]}]}}
2022-09-26 00:03:53.553 [DEBUG] [ibber.internal.handler.TibberHandler] - Sending websocket disconnect message
2022-09-26 00:03:53.553 [DEBUG] [ibber.internal.handler.TibberHandler] - Send message: {"type":"connection_terminate","payload":null}
2022-09-26 00:03:53.555 [DEBUG] [ibber.internal.handler.TibberHandler] - Closing a WebSocket due to Disconnected
2022-09-26 00:04:03.211 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at org.openhab.binding.tibber.internal.handler.TibberHandler.open(TibberHandler.java:345) ~[?:?]
	at org.openhab.binding.tibber.internal.handler.TibberHandler.updateRequest(TibberHandler.java:248) ~[?:?]
	at org.openhab.binding.tibber.internal.handler.TibberHandler.lambda$0(TibberHandler.java:236) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2022-09-26 00:04:23.556 [WARN ] [ibber.internal.handler.TibberHandler] - CLOSE FRAME - Failed to stop websocket client: java.lang.InterruptedException

I have a script rule that runs every time current price is changed. I don’t know if that can cause the problem as it also connects to Tibber API. But the think is that this problem only happens at midnight between sundays and mondays.
However, here is my rule script:

/**
 *  SET PRICE LEVEL AS NUMBER FROM TIBBER
 *  Gets todays electrical prices and sort them by price level and then set current price level to an item.
 */

// Load librarys from Openhab
var logger = Java.type('org.slf4j.LoggerFactory').getLogger('org.openhab.rule.rUpdatePriceLevel2');
var newHashMap = Java.type("java.util.HashMap");

// Declare Tibber constants
var TIBBER_API_URL = "https://api.tibber.com/v1-beta/gql";
var TIBBER_TOKEN = "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX";
var TIBBER_HOMEID = 0;

// Various declarations
var HEADERS_TIBBER = new newHashMap();
var TIMEOUT = 5000; //ms
var HTTP = Java.type("org.openhab.core.model.script.actions.HTTP");

// Tibber API query. Tibber uses GraphQL. Wrap as a JSON string for Req.body
var query = '{ "query": "{viewer {homes {currentSubscription {priceInfo {today {total}current {total}}}}}}" }';

var totalPriceArray = [];
var currentPrice;
var priceLevel;
var priceAverage = 0.0;
var priceMedian = 0.0

// Define Tibber Headers
HEADERS_TIBBER.put("Authorization", "Bearer " + TIBBER_TOKEN);

var success = false;
var res;
// Send request to Tibber. Expect JSON response.  
try {
  res = HTTP.sendHttpPostRequest(TIBBER_API_URL, "application/json", query, HEADERS_TIBBER, TIMEOUT);
  success = true; //Quick and dirty way to stop injecting data to influx on data retrievel error.
} catch (error) {
  logger.info("An error occured: " + error.message);
  success = false;
}

if (success) {
  res = JSON.parse(res);
  currentPrice = JSON.stringify(res.data.viewer.homes[TIBBER_HOMEID].currentSubscription.priceInfo.current["total"]);
  res = res.data.viewer.homes[TIBBER_HOMEID].currentSubscription.priceInfo.today;
  
  for(var i in res) {
    totalPriceArray.push(JSON.stringify(res[i]["total"]));
    priceAverage = priceAverage + parseFloat(JSON.stringify(res[i]["total"]));
  }
    
  totalPriceArray.sort(function(a, b){return a-b});
  
  priceAverage = priceAverage / 24.0;
  priceMedian = (parseFloat(totalPriceArray[11]) + parseFloat(totalPriceArray[12])) / 2.0;
  
  priceLevel = totalPriceArray.indexOf(currentPrice) + 1;
  
  items.getItem("TibberAPI_PriceLevel2").postUpdate(priceLevel);
  items.getItem("TibberAPI_PriceAverage").postUpdate(priceAverage.toFixed(4));
  items.getItem("TibberAPI_PriceMedian").postUpdate(priceMedian.toFixed(4));
//  logger.info("Current price: " + currentPrice);
//  logger.info("Todays prices: " + totalPriceArray.toString());
  
}

Reported and also discussed here; [tibber] Crash at midnight, fetching of new data stops · Issue #13417 · openhab/openhab-addons · GitHub

Good catch on the pattern (sun-mon midnight) - matches my report as well (which was last weekend).

Arne

For me it seems that the above mentioned Issue #13417 is not solved. I still have occasional ‘hangs’ on midnight (may be new week or other day of week).

Also for me, disabling and re-enabling the Tibber thing again makes it work again (till the next hang occurs).

I am using version 3.4.0 (no updates on the Tibber binding were made through the current 3.4.2).

Strange, my log keeps telling me the same “API response” message all day long:

<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}}}}
2023-02-19 00:04:55.250 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}

Any idea what is going wrong?
Gert

The problem ocurred again yesterday and the logs only keep telling the following:

2023-02-22 23:59:25.289 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-23 00:00:31.409 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-23 00:01:31.465 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-23 00:02:35.409 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}

When I disable and re-enable the Tibber thing then it works again:

2023-02-24 17:21:06.839 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'tibber:tibberapi:0062374f61' takes more than 5000ms.
2023-02-24 17:21:12.114 [DEBUG] [ibber.internal.handler.TibberHandler] - Websocket session established
2023-02-24 17:22:14.337 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}
2023-02-24 17:23:16.747 [DEBUG] [ibber.internal.handler.TibberHandler] - API response: {"data":{"viewer":{"home":{"currentSubscription":null,"daily":null,"hourly":null}}}}

Anything that I could do?

Regards,
Gert

I see the exact same problem on my installation. Is there anything we can provide, to find the underlying issue? I could probably add some more log messages, but I would need some help to find the relevant/interesting places in the code.

Leif

+1

Disabling and re-enabling the Tibber binding instance/thing seems to fix the problem - without manual intervention there are large gaps in the data (CEST):

Data flow restarted at 2023-07-04 03:55:10 CEST and 2023-07-05 03:53:00 CEST - might be a coincidence though.

openHAB 3.4.3 - Release Build
278 x Active x 80 x 3.4.3 x openHAB Add-ons :: Bundles :: Tibber Binding

I found a better solution for me (which works also without an internet connection). It’s based on this project (GitHub - micw/tibber-pulse-reader: A tool to read data directly from tibber pulse and publish it locally) and MQTT. With that I have pretty solid readings of my smart meter.
Funny enough within the first 24h the websocket connection to Tibber died again, but the local readings were there.

Interesting ‘workaround’ - but the modification to the Tibber bridge might be detectable by Tibber and might violate Tibber’s terms and conditions.

That’s correct, but for now an enabled webserver which delivers the binary SML data (not the Man-in-the-middle MQTT version) seems quite unproblematic for me. At least until I found a good offline way to read the consumption or Tibber provides an official way to read out the Pulse directly. Since I had some severe internet connection issues the last couple of weeks, I don’t want to rely on the Tibber graph API anymore.
Either way, I didn’t want to hijack your thread, just wanted to let you know, that I won’t follow this direction anymore. But fingers crossed the underlying problem can be found and fixed!

Have a nice evening!
Leif

Sure - it makes little sense to send the data to the cloud and hope that the cloud is willing to return the data to get access to your own data. :slight_smile: