Restarting client leads to exponential(?) growth of subscriptions

[GrimmiMeloni]

We are observing the following behavior.

Scenario:
Client is connected to a tibber pulse and has a single subscription.

What happens:

• Subscribing works as expected.
• In case of connection errors, retries done by the graphql client recreate the subscription with a new id, the old id is gone.

Log example

...
[pulse ] TRACE 2025/02/17 14:12:49 {"id":"9eed0f34-0e98-4949-b1fd-ecba8314ee66","type":"next","payload":{"data":{"liveMeasurement":{"power":0,"powerProduction":483.59,"lastMeterConsumption":17492.18065271,"lastMeterProduction":535.57547554,"currentL1":null,"currentL2":null,"currentL3":null}}}} server
[pulse ] TRACE 2025/02/17 14:12:59 failed to read JSON message: failed to get reader: context deadline exceeded server
[pulse ] TRACE 2025/02/17 14:12:59 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:12:59 {"type":"connection_ack"} server
[pulse ] TRACE 2025/02/17 14:12:59 {"id":"bd4e24bf-9db1-43e6-8db0-bf2c68804630","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:13:04 {"id":"bd4e24bf-9db1-43e6-8db0-bf2c68804630","type":"next","payload":{"data":{"liveMeasurement":{"power":0,"powerProduction":473.48,"lastMeterConsumption":17492.18065271,"lastMeterProduction":535.5775975,"currentL1":null,"currentL2":null,"currentL3":null}}}} server
...

So far so good. Now next:

• During one of the above mentioned reconnects the server fails to acknowledge the subscription. Similar log scenario as above, but this time the subscribing fails and the client exits gracefully.

[pulse ] TRACE 2025/02/17 14:15:39 failed to read JSON message: failed to get reader: context deadline exceeded server
[pulse ] TRACE 2025/02/17 14:15:39 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:39 {"type":"connection_ack"} server
[pulse ] TRACE 2025/02/17 14:15:39 {"id":"e6edc84a-62dd-4870-bcd7-ef8e6fd4e1a6","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:15:39 {"id":"e6edc84a-62dd-4870-bcd7-ef8e6fd4e1a6","type":"next","payload":{"errors":[{"message":"unable to start stream api:90c423074bbc4ff58fe47ddb8fce7020 for device 90c42307-4bbc-4ff5-8fe4-7ddb8fce7020; userId 6d634dc6-cb9b-48fd-9ff2-1a665ed80b9b","locations":[{"line":1,"column":28}],"path":["liveMeasurement"]}]}} server
[pulse ] TRACE 2025/02/17 14:15:39 {"id":"e6edc84a-62dd-4870-bcd7-ef8e6fd4e1a6","type":"complete"} server
[pulse ] ERROR 2025/02/17 14:15:39 Message: unable to start stream api:90c423074bbc4ff58fe47ddb8fce7020 for device 90c42307-4bbc-4ff5-8fe4-7ddb8fce7020; userId 6d634dc6-cb9b-48fd-9ff2-1a665ed80b9b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
[pulse ] TRACE 2025/02/17 14:15:39 no running subscription. exiting... client

To my understanding, in this moment flow control given back to the calling code, in our case evcc.
As we need the client to retry connecting, even in situation where the client exits, we do the following:

1. we call SubscriptionClient.Subscribe(...)
2. we restart the client via SubscriptionClient.Run()

I would expect from hereon, the subscription just again does its thing like before, i.e. send an connection_init and once successfully subscribed, it just streams the events.

However, what we DO see, is a multiplication of the subscription, which I frankly don't understand. So what we see in the logs after calling .Run() is a burst of consecutive connection_init requests, which then lead to MULTIPLE subscriptions, where there actually should only be a single subscription.

[pulse ] TRACE 2025/02/17 14:15:39 no running subscription. exiting... client
[pulse ] TRACE 2025/02/17 14:15:39 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:41 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:41 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:41 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:41 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:41 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:41 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:42 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:48 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:48 {"type":"connection_ack"} server
[pulse ] TRACE 2025/02/17 14:15:48 {"id":"27599e79-183d-460e-94f9-d8047a56d9c8","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:15:48 {"id":"99d89c41-a145-40eb-bae3-11826e9d26df","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:15:48 {"id":"fb6ccf36-5c4b-4fdd-9ed5-1543e4368be1","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:15:48 {"id":"27599e79-183d-460e-94f9-d8047a56d9c8","type":"next","payload":{"errors":[{"message":"unable to start stream api:90c423074bbc4ff58fe47ddb8fce7020 for device 90c42307-4bbc-4ff5-8fe4-7ddb8fce7020; userId 6d634dc6-cb9b-48fd-9ff2-1a665ed80b9b","locations":[{"line":1,"column":28}],"path":["liveMeasurement"]}]}} server
[pulse ] TRACE 2025/02/17 14:15:48 {"id":"27599e79-183d-460e-94f9-d8047a56d9c8","type":"complete"} server
[pulse ] ERROR 2025/02/17 14:15:48 Message: unable to start stream api:90c423074bbc4ff58fe47ddb8fce7020 for device 90c42307-4bbc-4ff5-8fe4-7ddb8fce7020; userId 6d634dc6-cb9b-48fd-9ff2-1a665ed80b9b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
[pulse ] TRACE 2025/02/17 14:15:49 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:58 {"type":"connection_init","payload":{"token":"***"}} client
[pulse ] TRACE 2025/02/17 14:15:58 {"type":"connection_ack"} server
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"4ff3daa4-8b0c-4154-aaef-592507787842","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"6c08576b-402a-487f-9b54-f7fd77d64537","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"a295186e-83a6-40a1-bf7a-9d00aa30b929","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"abfd1e95-3a40-4d94-97f6-3b868e4b126e","type":"subscribe","payload":{"query":"subscription ($homeId:ID!){liveMeasurement(homeId: $homeId){power,powerProduction,lastMeterConsumption,lastMeterProduction,currentL1,currentL2,currentL3}}","variables":{"homeId":"***"}}} client
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"4ff3daa4-8b0c-4154-aaef-592507787842","type":"next","payload":{"errors":[{"message":"unable to start stream api:90c423074bbc4ff58fe47ddb8fce7020 for device 90c42307-4bbc-4ff5-8fe4-7ddb8fce7020; userId 6d634dc6-cb9b-48fd-9ff2-1a665ed80b9b","locations":[{"line":1,"column":28}],"path":["liveMeasurement"]}]}} server
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"4ff3daa4-8b0c-4154-aaef-592507787842","type":"complete"} server
[pulse ] ERROR 2025/02/17 14:15:58 Message: unable to start stream api:90c423074bbc4ff58fe47ddb8fce7020 for device 90c42307-4bbc-4ff5-8fe4-7ddb8fce7020; userId 6d634dc6-cb9b-48fd-9ff2-1a665ed80b9b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"6c08576b-402a-487f-9b54-f7fd77d64537","type":"complete"} client
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"a295186e-83a6-40a1-bf7a-9d00aa30b929","type":"complete"} client
[pulse ] TRACE 2025/02/17 14:15:58 {"id":"abfd1e95-3a40-4d94-97f6-3b868e4b126e","type":"complete"} client
...

This "pattern" continues, and subscriptions start to pile up. After a few minutes we already have 12 subscriptions, where there used to be a single one.

I am not sure if this is a bug, or if we are doing something wrong on the client side by i.e. reusing the SubscriptionClient. Any advise would be helpful.

[hgiasac]

@GrimmiMeloni if it's possible can you share the code block example on how you handle the connection restart? There would be some race conditions so we need to improve the sync lock logic

[GrimmiMeloni]

Sure, it's anyways all open source. ;)

https://github.com/evcc-io/evcc/blob/13bb84651c843ccbdcbbb3c2a8ecc171bdeeb590/meter/tibber-pulse.go#L115-L135

[hgiasac]

@GrimmiMeloni After reading the code, I have a few comments:

• This line can be removed. The subscription client now keeps raw subscription information. When restarting, the client will reset the original state, not be removed as before. So when you call subscribe again the subscription will be duplicated.
• Let's update the library with the latest commit on master.

Then test again to verify if the duplicated subscription issue still happens.

[GrimmiMeloni]

Thanks @hgiasac - will do as suggested and follow up here once we have feedback from the field.

[toini]

I can confirm that yesterday 24.4 around 11:46 CET after server restart we saw a client accumulating enormous amounts subscriptions eventually crashing the tibber graphql-ws service.

Also, we see that many users running evcc with this client are disconnecting and reconnecting super frequently leading to high resource usage/instability. I've posted some graphs here evcc-io/evcc#20841 (comment).

Toni
Tibber

[andig]

@hgiasac we're still having issues, if not this specific one. Please see this log:

evcc-py  | [pulse ] ERROR 2025/05/13 07:47:48 Message: unable to start stream api:e90e4c627d25417383ba9b4cb7821497 for device e90e4c62-7d25-4173-83ba-9b4cb7821497; userId 29fbf633-dee7-4959-9d19-df7e81d5c97b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
evcc-py  | [pulse ] ERROR 2025/05/13 07:47:53 Message: unable to start stream api:e90e4c627d25417383ba9b4cb7821497 for device e90e4c62-7d25-4173-83ba-9b4cb7821497; userId 29fbf633-dee7-4959-9d19-df7e81d5c97b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
evcc-py  | [pulse ] ERROR 2025/05/13 07:47:59 Message: unable to start stream api:e90e4c627d25417383ba9b4cb7821497 for device e90e4c62-7d25-4173-83ba-9b4cb7821497; userId 29fbf633-dee7-4959-9d19-df7e81d5c97b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
evcc-py  | [pulse ] ERROR 2025/05/13 07:48:05 Message: unable to start stream api:e90e4c627d25417383ba9b4cb7821497 for device e90e4c62-7d25-4173-83ba-9b4cb7821497; userId 29fbf633-dee7-4959-9d19-df7e81d5c97b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
evcc-py  | [pulse ] ERROR 2025/05/13 07:48:15 Message: unable to start stream api:e90e4c627d25417383ba9b4cb7821497 for device e90e4c62-7d25-4173-83ba-9b4cb7821497; userId 29fbf633-dee7-4959-9d19-df7e81d5c97b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
evcc-py  | [site  ] ERROR 2025/05/13 07:48:27 grid power: outdated
evcc-py  | [pulse ] ERROR 2025/05/13 07:48:36 Message: unable to start stream api:e90e4c627d25417383ba9b4cb7821497 for device e90e4c62-7d25-4173-83ba-9b4cb7821497; userId 29fbf633-dee7-4959-9d19-df7e81d5c97b, Locations: [{Line:1 Column:28}], Extensions: map[], Path: [liveMeasurement]
evcc-py  | [site  ] ERROR 2025/05/13 07:48:41 grid power: outdated
evcc-py  | [pulse ] ERROR 2025/05/13 07:48:45 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:48:50 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [site  ] ERROR 2025/05/13 07:48:55 grid power: outdated
evcc-py  | [pulse ] ERROR 2025/05/13 07:48:55 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:01 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:06 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:11 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [site  ] ERROR 2025/05/13 07:49:12 grid power: outdated
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:16 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:21 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:26 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [site  ] ERROR 2025/05/13 07:49:27 grid power: outdated
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:31 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:36 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [site  ] ERROR 2025/05/13 07:49:41 grid power: outdated
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:42 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:47 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"
evcc-py  | [pulse ] ERROR 2025/05/13 07:49:52 failed to read JSON message: failed to get reader: received close frame: status = StatusCode(4429) and reason = "Too many open connections on this server; count 2; user agent evcc/v0.0.0 hasura/go-graphql-client/v0.14.0"

It seems that for some reasons, the graphql API seems to create an additional, unexpected connection under certain conditions. Do you have any hint why that may be looking at how we initialise the connection?

// subscription client
client := graphql.NewSubscriptionClient(res.Viewer.WebsocketSubscriptionUrl).
	WithProtocol(graphql.GraphQLWS).
	WithWebSocketOptions(graphql.WebsocketOptions{
		HTTPClient: &http.Client{
			Transport: &transport.Decorator{
				Base: http.DefaultTransport,
				Decorator: transport.DecorateHeaders(map[string]string{
					"User-Agent": getUserAgent(),
				}),
			},
		},
	}).
	WithConnectionParams(map[string]any{
		"token": cc.Token,
	}).
	WithRetryTimeout(0).
	WithRetryDelay(5 * time.Second).
	WithWriteTimeout(request.Timeout).
	WithReadTimeout(90 * time.Second).
	WithLog(log.TRACE.Println).
	OnError(func(_ *graphql.SubscriptionClient, err error) error {
		// exit the subscription client due to unauthorized error
		if strings.Contains(err.Error(), "invalid x-hasura-admin-secret/x-hasura-access-key") {
			return err
		}
		log.ERROR.Println(err)
		return nil
	})

[hgiasac]

@andig, the client config looks okay to me. I also tested the Tibber API in the example with a demo token. The output is expected, so I can't reproduce your issue yet. The rate limit won't happen if the total concurrent websocket connections don't exceed 10. In your logs, each error message is exactly delayed by 5 seconds, which matches the WithRetryDelay setting. If there is a race condition, the interval should be smaller.

AFAIK, Tibber likely calculates the rate limit by IPs. If the cluster has multiple replicas that are in the same NAT IP, the rate limit may be exceeded by other replicas.

Anyway, I have improved logging and metrics for WebSocket connections. You can upgrade v0.14.3 to debug it. Each log line will contain a session_id and connection_id. You can track the current session and connection. And use the GetWebSocketStats function to get the global metrics of current active WebSockets.