Pulse doesn't update data for long periods of time

[CRidge]

I notice that the data from Pulse often fails to update for long periods of time:

The longest period without updates, during the last 14 days, is nearly two days long.

I assume this may be down to a poor connection locally, but according to my router, Tibber Pulse has great connection quality right now, but I haven't seen an update in 8 hours.

I've tried restarting both the Tibber app and Homey itself, as well as removing the cable from the Pulse for a while before returning it, with no improvement.

[CRidge]

Just to try to keep this issue from dying: This behavior is still as described two months ago.

I see that both the current price and the current effect has this problem - but the price is usually not delayed for as many hours as the effect.

[toini]

Are you seeing this same problem in the Tibber app as well? I'm looking at your data for the past few days and I'm not seeing any flats. If you do see that in Homey then the issue might be between Homey <-> Tibber API and not between Pulse <-> Tibber platform.

[CRidge]

@toini I can't see any signs of this in the Tibber app, no.

If the issue is indeed (as I too think) between Homey <-> Tibber API, are you suggesting it is a local network issue? If so, I haven't noticed any other network related issues in the affected time spans - which sometimes has lasted for days.

I have also tried to restart Homey when I had this state, which previously has solved any network issues I may have experienced at other times - but Tibber would still not report updated values.

[CRidge]

@toini On march 4th, the "Consumption since midnight" stopped updating at 14:00 and didn't update again until march 7th at 02:00.

The current price reported from Tibber was being updated until march 4th at 23:00 - when it is unchanged until (again) March 7th at 02:00.

I see the same pattern at other times when this happens for a long time: The price continues to update for quite a few hours - and then that stops to update too.

[toini]

Could you send a diagnostics report from the Tibber Homey app so we can see if there's anything suspicious there?

[CRidge]

Report sent with ID 5b3ae2df-739b-47da-a37a-fecf236e4aa2 (manually typed from the cell phone, but I think I copied it correctly :))

Of course, it's been unusually stable lately - the last stop was three days ago, so I hope the report will be enough to see what's going on.

[toini]

I can see your log report with the id above. It only contains few hundred rows (not sure if this is a Homey limitation) but I think I see something weird there

---- stdout ---- [log] 2022-03-19 16:08:18 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Set 'measure_power' capability to 4970 [log] 2022-03-19 16:08:18 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Latest current values [L1: null, L2: null, L3: null] [log] 2022-03-19 16:08:18 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Trigger power changed 4970 [log] 2022-03-19 16:08:27 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Set 'measure_power' capability to 3452 [log] 2022-03-19 16:08:27 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Latest current values [L1: null, L2: null, L3: null] [log] 2022-03-19 16:08:27 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Trigger power changed 3452 [log] 2022-03-19 16:08:32 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Set 'measure_power' capability to 3403 [log] 2022-03-19 16:08:32 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Latest current values [L1: null, L2: null, L3: null] [log] 2022-03-19 16:08:32 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Trigger power changed 3403 ... ... ...

[log] 2022-03-19 16:15:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Trigger current L2 changed 5.943 [log] 2022-03-19 16:15:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Set 'measure_current.L3' capability to 13.453 [log] 2022-03-19 16:15:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Trigger current L3 changed 13.453 [log] 2022-03-19 16:25:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Unsubscribing from previous connection [log] 2022-03-19 16:25:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribing to live data for homeId 1e56f310-3a0a-4f51-afbd-be87af16ac1e [log] 2022-03-19 16:25:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribe to live [log] 2022-03-19 16:35:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Unsubscribing from previous connection [log] 2022-03-19 16:35:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribing to live data for homeId 1e56f310-3a0a-4f51-afbd-be87af16ac1e [log] 2022-03-19 16:35:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribe to live [log] 2022-03-19 16:45:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Unsubscribing from previous connection [log] 2022-03-19 16:45:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribing to live data for homeId 1e56f310-3a0a-4f51-afbd-be87af16ac1e [log] 2022-03-19 16:45:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribe to live [log] 2022-03-19 16:55:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Unsubscribing from previous connection [log] 2022-03-19 16:55:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribing to live data for homeId 1e56f310-3a0a-4f51-afbd-be87af16ac1e [log] 2022-03-19 16:55:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribe to live [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] Begin update [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] last price info entry is for day 2022-03-20T00:00:00+00:00 [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] Expected price publish time is after 2022-03-19T13:00:00+01:00 [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] Last price info entry is up-to-date [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] Next time to run update is at 2022-03-19T18:00:00+00:00 [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] Scheduling update again in 3599.923 seconds [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] End update [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] Triggering price_changed { total: 0.168, energy: 0.1264, tax: 0.0416, startsAt: '2022-03-19T18:00:00.000+01:00', level: 'NORMAL' } [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] 0.17 is lower than the lowest (0.1173) today = false [log] 2022-03-19 17:00:00 [ManagerDrivers] [Driver:home] [Device:30221884-7a92-4c10-974d-892b3159e584] 0.17 is higher than the highest (0.1703) today = false [log] 2022-03-19 17:05:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Unsubscribing from previous connection [log] 2022-03-19 17:05:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribing to live data for homeId 1e56f310-3a0a-4f51-afbd-be87af16ac1e [log] 2022-03-19 17:05:14 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribe to live

During 16:08 - 16:15 we receive Pulse data at least once per minute and after that it stops and logs indicate we are having some kind of connection troubles. I will investigate this further on the server side.

[toini]

I deployed a new version of the API to improve logging for web socket connections. I'm not seeing your device getting authenticated which is odd.

[toini]

Now I see a successful connection at 14:04:57. It seems it took about 30 minutes. Could you share another diagnostics report?

[toini]

I deployed a new version again at 14:25 CET. Let's see how long it takes for your homey to re-connect.

[CRidge]

New diagnostics report sent (a63b1e0-a224-49e8-bb99-1fc1e96024d5

Since my last report, there has been another outage - from around 3 am till 7 pm yesterday.

[CRidge]

And it seems another outage just started - my data is now 17-18 minutes old ...

[toini]

I deployed a new version at 14:25 CET which causes the web socket connection to close. The client should detect that and reopen the connection.

From the logs I see that your homey was connected before 14:25 CET but after that it does not seem to be able to detect that the connection was closed and seems to hang.

[log] 2022-03-21 13:24:16 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Latest current values [L1: null, L2: null, L3: null]
[log] 2022-03-21 13:24:16 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Trigger power changed 3403

[log] 2022-03-21 13:34:20 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Unsubscribing from previous connection
[log] 2022-03-21 13:34:20 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribing to live data for homeId 1e56f310-3a0a-4f51-afbd-be87af16ac1e
[log] 2022-03-21 13:34:20 [ManagerDrivers] [Driver:pulse] [Device:8a2dfb07-4c4c-475c-9b79-0a356f2747d6] Subscribe to live

I see a connection established at 14:44:22.281 CET

[CRidge]

It is updating again now - sent a new report: 8f69dd3b-0539-4260-86ef-e8b1a9873594

[toini]

Now with the improved logging on the server side I see your homey was disconnected at 3:35:00 CET and then reconnected 10 seconds later 3:35:10 CET. That would leave only 10 seconds of outage which does not really match what you are observing in the client side/what we saw in the diagnostics report.

Could you once more send a diagnostics report (no need to type the id of the report if you need to do it manually)? I'm hoping I could see what the client logs indicate happened around 3:35:00 CET.

[toini]

Another disconnect at 12:36:15. This time it didnt reconnect in 10 seconds but only after 8 minutes later at 12:44:52.

[CRidge]

I'm connected remotely at the moment, and I'm not allowed to send a new report - I'll send one when I get home.

I don't see any long disconnects since the one previously mentioned, so what you see fits. An 8 minute stop is hard to spot from my end. I see nothing special (in my logs) which happened at the times you mentioned.

[toini]

I havent confirmed the actual problem here but I did some optimizations that seem to allow the service perform much better. This might help cure the problem you are seeing.

[CRidge]

Sounds good - thanks! I'll keep my eye on it and see if it happens again. No new disconnect lately.

I wasn't able to send a new report even when I got home - the "Send report" button is disabled. I see this for other apps too, so a Homey bug perhaps?

[CRidge]

@toini It was looking very good - but when I checked today, I see a disconnect from Saturday at 9 pm until today at 1 am.

I've sent a new diagnostics report.

[CRidge]

@toini In the last week since my last update, I see three more disconnects, one lasting for over 24 hours :(

[toini]

I have now implemented and deployed support for a new web socket sub protocol graphql-transport-ws (in library https://github.com/enisdenjo/graphql-ws) replacing the currently used sub protocol graphql-ws (in https://github.com/apollographql/subscriptions-transport-ws). The latter library is no longer maintained and has known memory leaks causing instability in our API.

I will next implement the client side changes required to switch to the newer protocol in Homey Tibber app. Once that's ready I'll deploy it as a test version and notify you so you can test it.

[toini]

There's a new test version available here: https://homey.app/en-us/app/com.tibber/Tibber/test/ Could you install and try it out?

[CRidge]

@toini I'm sorry – I somehow missed your last comment. I'll install it now.

[CRidge]

@toini I see version 1.6.2 was automatically installed on April 14. And I see an immediate change in the disconnect – but unfortunately for the worse :(

[toini]

Thanks for the info. I will continue with analysis tomorrow.

[toini]

During the past 12 hours I see several reconnections:

2022-04-26T22:18:45.100Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-26T22:47:39.029Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-26T23:20:11.367Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 2 2022-04-26T23:23:33.846Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-26T23:26:57.678Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 2 2022-04-26T23:28:28.043Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-26T23:32:18.253Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 2 2022-04-26T23:34:52.656Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-26T23:39:35.823Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-26T23:42:54.612Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-27T00:28:11.788Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-27T00:31:22.577Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-27T01:04:23.657Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-27T01:35:11.646Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1

But for the day when you see outage 2022-04-23 - 2022-04-24 there was very little. I see no errors though.

2022-04-23T07:36:15.735Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1 2022-04-24T01:35:12.147Z INFO [websocket] client connected; verified token (hashed) OJ5/EEbjpeL+lLnF26trsPcmXExBwoKD9kKsH3Inncg= for user d8cc2b05-2649-421a-8eb3-274ae606e793; Homey/7.4.0-rc.22 com.tibber/1.6.2; 88.95.34.225; count 1

[toini]

What kind of Homey device do you have? Is it one of those running in the cloud (i.e. it's the cloud connecting to us).

[toini]

I have just now learned that we had a bypass rule for homey rate limit that broke during last app release resulting in 429 too many requests for anything running on the homey cloud. This has now been fixed.

[toini]

Would you share another diagnostics report so we can see if there is any errors in the client side logs?

[CRidge]

I have a Homey Pro (2019).

I've sent another diagnostic.

I still see many more disconnects than before 6.1.2.

[CRidge]

@toini Any update on this? I still see these disconnects about every two days - and with some of them lasting 30+ hours, my automations built on top of Tibber is pretty much useless ...

[toini]

Shit now it was my turn to miss the communication. I didnt see a notification from your last reply. Need to check the diagnostics report.

[toini]

Has there been any changes to internet connectivity in the area?

[CRidge]

@toini I haven't experienced anything in particular, no. My router needs a restart every now and then (once a month?), other than that I find my Internet connection to be stable.

I have quite a few thing relying on the network, both internally at home and externally, and there is rarely any issues.

[toini]

Ok I now retrieved the log (attached) for 2022-04-28 23:08:31 - 2022-04-28 23:15:08. Was there an outage between that period? If yes, when exactly?

Homey-log-2022-04-29.txt

[toini]

I see a lot of these:

Thu Apr 28 2022 07:18:18 GMT+0000 (Coordinated Universal Time) Error while fetching home features FetchError: request to https://api.tibber.com/v1-beta/gql failed, reason: read ECONNRESET at ClientRequest.<anonymous> (/node_modules/node-fetch/lib/index.js:1491:11) at ClientRequest.emit (node:events:526:28) at TLSSocket.socketErrorListener (node:_http_client:442:9) at TLSSocket.emit (node:events:526:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) { type: 'system', errno: 'ECONNRESET', code: 'ECONNRESET' }

Could you send another diagnostics report now so I can see if that's constant?

[CRidge]

@toini I'm sorry - I sort of gave up on this issue after such a long time ...

However, after being completely unreliable for a long time, it's suddenly has been completely stable for three days now. Two things changed three days ago:

• I updated to Homey version 8. This caused some problems with other apps, for which the solution was to:
• Disable AiProtection on my Asus router

I'm not sure which of these made the difference (or if the stability will continue), but I thought I'd share if it helps anyone else.

[toini]

@CRidge thanks for sharing the info. I've been suspecting that the issue probably is at your end as we havent seen others report similar problems. Let me know if the problem returns.