bisand / node-red-contrib-tibber-api

Node Red module for integrating with Tibber api
MIT License
20 stars 2 forks source link

Tibber feed disconnected #50

Closed martinsund999 closed 2 years ago

martinsund999 commented 2 years ago

The Tibber feed gets disconnected. I think the Node Red Tibber node hammering the Tibber API and gets banned or something. If I deactivate the node and wait for 10 min and then activate it once again, then it works for a while again.

Maybe a solution: Make a user input how often the node should connect to the Tibber API to get the payload. image

image image

image

image

bisand commented 2 years ago

The tibber-feed node is a "streaming" node that leverages websockets to receive "push" messages. I know that Tibber have suffered from some stability issues lately and the issue could be a result of that. The node will timeout if it has not received any data for 30 seconds after connecting to the feed. It should also have a retry logic that should take care of this automatically.

I will do some investigation into the retry logic to see if there is anything left out or needs to be improved.

bisand commented 2 years ago

@m4rt1n5und, are you still experiencing this issue?

martinsund999 commented 2 years ago

@bisand, Yes, it is still the same. If I deactivate the Tibber node for 10 min and then activate the node, then it works for 1h or so. Then I get the same error messages until i deactivate the node once again.

bisand commented 2 years ago

Ok, I haven't been able to replicate the problem on my side. Could you share some info about the system you are running on, just for me to try to replicate the problem. OS version, Node.js version and Node-Red version. That would help my troubleshooting. Thanks!

Sungtroll commented 2 years ago

This uses to happen many times when restart node-red immediatly after it was shut down. If viewing in the tibber API explorer on developer.tibber.com/explorer it will say "Too many concurrent sockets for token". Sometimes tibber API explorer will not recover from this and then i sendt message to tibber support and they fixed this almost immediatly and said it was because it hung on the server end.

image

bisand commented 2 years ago

OK, thanks for testing. Then it could be a couple of scenarios.

  1. When Node-Red restarts it fires up an extra instance before restarting.
  2. The user have the Tibber API explorer open, or some other instance/program/script using the feed somewhere else.

Since the feed is limited to only having one instance per token and home, it will lock out connections when that limit has reached.

A good place to start is to check if you are using it other places simultaneously with Node-Red.

I will do some testing and try to prevent Node-Red from firing up multiple instances of the feed. I have some logic around that already, but will try to see if I can prevent it in a more "global" manner.

Sungtroll commented 2 years ago

I can see in node-red console window that tuya-smart-device and Xiaomi Gateway do some cleaning up before node-red exits. I would like to see that tibber feed node also report to the console window that the tibberfeed has ended. This will maybe prevent problems when the node-red is starting up again almost immediatly after it was shut down.

Node-Red console window after pressing ctrl+c to exit node-red:

4 Jan 10:08:42 - [info] Stopping flows

4 Jan 10:08:42 - [info] [tuya-smart-device:16A Varmtvann] closeComm(): Cleaning up the state 4 Jan 10:08:42 - [info] [tuya-smart-device:16A Varmtvann] closeComm(): Clearing the find timeout handler 4 Jan 10:08:42 - [info] [tuya-smart-device:16A Varmtvann] closeComm(): Disconnecting from Tuya Device 4 Jan 10:08:42 - [info] [tuya-smart-device:16A Varmtvann] Disconnected from tuyaDevice. shouldTryReconnect = false

4 Jan 10:08:42 - [info] [udp in:Xiaomi Gateway] udp listener stopped

4 Jan 10:08:42 - [info] Stopped flows

Terminate batch job (Y/N)? y

Sungtroll commented 2 years ago

Today i did a lot of quick restarts of node-red, shutting it down and almost immediatly start up again.

Tibber-feed logs to console window: 4 Jan 10:47:07 - [warn] [tibber-feed:86f85c24.6e13b] Connection timed out after 30000 ms. 4 Jan 10:47:07 - [info] [tibber-feed:86f85c24.6e13b] Reconnecting... 4 Jan 10:47:07 - [info] [tibber-feed:86f85c24.6e13b] Connected to Tibber feed. 4 Jan 10:47:07 - [error] [tibber-feed:86f85c24.6e13b] [object Object] 4 Jan 10:47:07 - [info] [tibber-feed:86f85c24.6e13b] Sent connection_terminate to Tibber feed. 4 Jan 10:47:07 - [info] [tibber-feed:86f85c24.6e13b] Closed Tibber Feed. 4 Jan 10:47:07 - [info] [tibber-feed:86f85c24.6e13b] Disconnected from Tibber feed

In the line "4 Jan 10:47:07 - [error] [tibber-feed:86f85c24.6e13b] [object Object]" looking further this is what node-red showing in the node-red debug window:

4.1.2022, 10:47:07 node: 86f85c24.6e13b msg : Object object type: "connection_error" id: "1" payload: object message: "Too many concurrent sockets for token"

after this is seems like tibber API sends "connection_terminate" to tibber-feed node and it closes tibber-feed, then disconnects.

This has happened before and if it dont recover within a couple of hours i have to message tibber support to fix the problem. I am not logged in to tibber API explorer. This is probably tibber API bug at tibber side. I have tried not to start up node-red and i have even tried to disconnet from the internet for a while.

Maybe it can have something to do about rate limit like in the Airthings API shown here: https://developer.airthings.com/docs/api-rate-limit

Tibber API documentation says: Note that the maximum number of open websockets is limited to two. https://developer.tibber.com/docs/guides/calling-api

Tibber API Rate limiting: We have recently added a rate limit of 100 requests in 5 minutes per IP address to protect the API. Note that prices are calculated once per day in the afternoon (for Norway and Sweden they are first preliminary and later finalized potentially with minor changes after currency rates are confirmed). You can use priceInfo.today and priceInfo.tomorrow for fetching them up front instead of only using priceInfo.current for the current hour. https://developer.tibber.com/docs/overview

Sungtroll commented 2 years ago

I contacted tibber but did not get response. At 16:02 the connection is working again after it was refused since 08:42 I set up a log file for connection status messages, here are the latest messages saved at 21:00

Tue Jan 04 2022 16:01:33 GMT+0100 (sentraleuropeisk normaltid) connected Tue Jan 04 2022 16:01:33 GMT+0100 (sentraleuropeisk normaltid) disconnected Tue Jan 04 2022 16:02:03 GMT+0100 (sentraleuropeisk normaltid) connected Tue Jan 04 2022 16:02:03 GMT+0100 (sentraleuropeisk normaltid) disconnected Tue Jan 04 2022 16:02:33 GMT+0100 (sentraleuropeisk normaltid) connected ( for 2 minutes) Tue Jan 04 2022 16:04:28 GMT+0100 (sentraleuropeisk normaltid) disconnected Tue Jan 04 2022 16:04:29 GMT+0100 (sentraleuropeisk normaltid) connected ( for 3 minutes) Tue Jan 04 2022 17:07:58 GMT+0100 (sentraleuropeisk normaltid) disconnected Tue Jan 04 2022 17:08:28 GMT+0100 (sentraleuropeisk normaltid) connected ( still connected at 21:00) Tue Jan 04 2022 21:04:51 GMT+0100 (sentraleuropeisk normaltid) connected (pressed the Deploy button: Full - deploys everything in the workspace ) Tue Jan 04 2022 21:26:39 GMT+0100 (sentraleuropeisk normaltid) connected (pressed the Deploy button: Full - deploys everything in the workspace )connected (pressed Deploy Full)

image

Sungtroll commented 2 years ago

I also want to mention that the duplicate messages that tibber resolved is back since 2021-11-01T19:52:00+01:00. In two months i have received 135 000 duplicate messages. When tibber solved this issue before they said it was because the Aidon AMS device does not send timestamps so tibber makes its own timestamps. The latest duplicate count number was 135685 and was received 2022-01-02T19:29:00.000+01:00 so no more duplicates the last 3 days. If duplicates starts up again i will report the issue to tibber (again).

bisand commented 2 years ago

Thanks for doing all the research and testing @Sungtroll, it has been really helpful. While Tibber still seem to have some instability issues, I have also tried to improve the connectivity logic in this this module. A new version containing these improvements is available for installation (v2.5.8). I am currently doing some more testing and will hopefully have more improvements to the stability and connectivity in the near future. Thanks!

bisand commented 2 years ago

With the latest improvements in mind (v2.6.0) do you still have issues with instabilities and disconnects @m4rt1n5und? @Sungtroll, what about you? Let me know if we can close this issue?

Sungtroll commented 2 years ago

I upgraded to v2.6.0 and have done several quick restarts and have not had any problems so far. Notice that for Ramona user i have used two different tibber-feed in two different flows, both using the same API endpoint. Someone will do this if they dont use the link in link out node from one flow to another flow. tibber-feed seems to handle this very well according to the log.

(to-do: 1: testing with restart flows. 2: testing with 4G mobile network with poor signal quality and packet loss)

Log after staring node-red:

10 Jan 22:34:20 - [info] [tibber-feed:tibber-feed Ramona dual feed test] Preparing to connect to Tibber... // I notice there is only one "prepering to connect to tibber" even if i have two Ramona tibber feed connected in two different flows 10 Jan 22:34:20 - [info] [tibber-feed:Tibber feed Jacek] Preparing to connect to Tibber... 10 Jan 22:34:20 - [info] [tibber-feed:tibber-feed Harald] Preparing to connect to Tibber...

10 Jan 22:34:21 - [info] [tibber-feed:tibber-feed Ramona dual feed test] Connecting to Tibber... 10 Jan 22:34:21 - [info] [tibber-feed:Tibber feed Jacek] Connecting to Tibber... 10 Jan 22:34:21 - [info] [tibber-feed:tibber-feed Harald] Connecting to Tibber... 10 Jan 22:34:21 - [info] [tibber-feed:tibber-feed Ramona dual feed test] "Connected to Tibber feed." 10 Jan 22:34:21 - [info] [tibber-feed:tibber-feed Ramona] "Connected to Tibber feed." 10 Jan 22:34:21 - [info] [tibber-feed:tibber-feed Ramona dual feed test] {"type":"connection_ack"} 10 Jan 22:34:21 - [info] [tibber-feed:tibber-feed Ramona] {"type":"connection_ack"} 10 Jan 22:34:21 - [info] [tibber-feed:Tibber feed Jacek] "Connected to Tibber feed." 10 Jan 22:34:21 - [info] [tibber-feed:Tibber feed Jacek] {"type":"connection_ack"} 10 Jan 22:34:23 - [info] [tibber-feed:tibber-feed Harald] "Connected to Tibber feed." 10 Jan 22:34:23 - [info] [tibber-feed:tibber-feed Harald] {"type":"connection_ack"}

After i stopped node-red: 10 Jan 22:34:38 - [info] Stopping flows 10 Jan 22:34:38 - [info] [tuya-smart-device:16A Varmtvann 3.3] closeComm(): Cleaning up the state 10 Jan 22:34:38 - [info] [tuya-smart-device:16A Varmtvann 3.3] closeComm(): Clearing the find timeout handler 10 Jan 22:34:38 - [info] [tuya-smart-device:16A Varmtvann 3.3] closeComm(): Disconnecting from Tuya Device 10 Jan 22:34:38 - [info] [tuya-smart-device:16A Varmtvann 3.3] Disconnected from tuyaDevice. shouldTryReconnect = false 10 Jan 22:34:38 - [info] [udp in:Xiaomi Gateway] udp listener stopped // I included the above for comparing reason

10 Jan 22:34:38 - [info] [tibber-feed:tibber-feed Ramona dual feed test] Unregistering event handlers... 10 Jan 22:34:38 - [info] [tibber-feed:tibber-feed Ramona dual feed test] Done. 10 Jan 22:34:38 - [info] [tibber-feed:tibber-feed Ramona] Unregistering event handlers... 10 Jan 22:34:38 - [info] [tibber-feed:tibber-feed Ramona] Disconnecting from Tibber feed... 10 Jan 22:34:38 - [info] [tibber-feed:tibber-feed Ramona] Done. 10 Jan 22:34:38 - [info] [tibber-feed:Tibber feed Jacek] Unregistering event handlers... 10 Jan 22:34:38 - [info] [tibber-feed:Tibber feed Jacek] Disconnecting from Tibber feed... 10 Jan 22:34:38 - [info] [tibber-feed:Tibber feed Jacek] Done. 10 Jan 22:34:38 - [info] [tibber-feed:tibber-feed Harald] Unregistering event handlers... 10 Jan 22:34:38 - [info] [tibber-feed:tibber-feed Harald] Disconnecting from Tibber feed... 10 Jan 22:34:38 - [info] [tibber-feed:tibber-feed Harald] Done. 10 Jan 22:34:38 - [info] Stopped flows Terminate batch job (Y/N)? y

bisand commented 2 years ago

That's correct. There is only one connection to the tibber feed per apiToken+homeId. All nodes with same config (apiToken+homeId) will just use one connection. This was implemented a while back to prevent too many concurrent connections.

Sungtroll commented 2 years ago

Passed multiple test of node-red full deploy: successfully. Passed multiple test of handling multiple disruptions of internet connection: successfully.

If i can suggest improvement is would be add a special settings for users with unstable 4G internet to do someting like: if tibber-feed not receiving data, then check if local internet connection lost as first step. like ping 8.8.8.8 or someting else. Then if lost, wait for local internet connection is back before stopping and restart connection to tibber API if restored connection but not receiving data from tibber API, then disconnect and reconnect to tibber API

This will make it quicker to get the live feed after internet connection is restored

Maybe a test connection to tibber demo account is someting to consider to check if tibber API is working or not. It probably have no restrictions of number of concurrent connections.

bisand commented 2 years ago

Great! I will add your improvement suggestion to a new issue. Today you already have the ability to specify the timeout for re-connect when no messages are received. Default value is 60 seconds, but that can be changed. The only quirk is that today you will have to restart node-red for that value to have effect. In the future this might change.

Closing this issue.