[BUG] Bug in code or Tibber api calculating connection limits wrong?

[jakeri]

Describe the bug

I'm trying to get realtime data from the Tibber api using this tool (I got a Pulse). I'm not sure if it's a bug in the websocket handling or Tibber blocking my requests.
I only have one connection using this token but still have connection problems quite often. I have generated a new token.

From time to time it works.

I can not reproduce this with the demo token.

I have gotten this error also through the Tibber developer/JS console but it clears quite fast there.

I'm NOT using the web api and my python code at the same time.

To Reproduce

Steps to reproduce the behavior:

import tibber

TOKEN="<insert private token>
account = tibber.Account(TOKEN)
home = account.homes[0]

@home.event("live_measurement")
def show_lastMeterConsumption(data):
  print(data.last_meter_consumption)

home.start_live_feed(retries = 1000, retry_interval=15)

Connection to websocket failed... Retrying in 10 seconds...
received 4429 (private use) Too many open connections on this server: 2; then sent 4429 (private use) Too many open connections on this server: 2
Traceback (most recent call last):
  File "/home/pi/.pyenv/versions/py399/lib/python3.9/site-packages/tibber/types/home.py", line 228, in start_live_feed
    self._loop.run_until_complete(self.run_websocket_loop(exit_condition, retries = retries, **kwargs))
  File "/home/pi/.pyenv/versions/3.9.9/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/home/pi/.pyenv/versions/py399/lib/python3.9/site-packages/tibber/types/home.py", line 295, in run_websocket_loop
    await self._websocket_client.close_async()
  File "/home/pi/.pyenv/versions/py399/lib/python3.9/site-packages/gql/client.py", line 651, in close_async
    if isinstance(self.session, ReconnectingAsyncClientSession):
AttributeError: 'Client' object has no attribute 'session'

Expected behavior

Connection should be established.

Version

Latest from pip.

[BeatsuDev]

Thanks a lot for bringing this up. Since I don't have a tibber pulse I can't test it myself. I'll have a look into possible causes as soon as I can!

[BeatsuDev]

It could be that I need to implement jitter and exponential delay to the retry mechanism as stated in the docs here:
https://developer.tibber.com/docs/guides/calling-api#:~:text=Best%20practices%20for%20implementing%20websocket%20subscription%20clients

I've noticed now that there are a few other things I haven't accounted for that should be implemented too, so I'll update those things as soon as I can and see if it helps!

[JoshuaDodds]

Hi @BeatsuDev

I have noticed the same since the last changes you have made but have been too busy to come and comment. But for a little more detail of what i see happening... Here is the behaviour i see.

After 2 disconnects (either intentional or non-intentional) the connections never seem to reset and you stuck with a failure message 2 many open connections. The only work around for this seems to be to delete your token from the tibber dev portal and create a new one. Then you can run again for a few days until you hit this connection limit again.

So indeed something is going wrong here with retry/disconnect/reconnect logic.

Thanks for looking into it!

[BeatsuDev]

I've made a lot of changes to the code now and added backoff + jitter. I explicitly call the gql.Client.close_async() method now too just in case, even though the websocket connection should be closed because of the context manager associated with the subscribe method for gql.Client. I'm not aware of any ways the websocket connection can remain after the python interpreter has exited... If the problem persists, I might have to dig deeper into that.

Could you test the branch I created for this issue and report back if the problem still persists @jakeri @JoshuaDodds (https://github.com/BeatsuDev/tibber.py/tree/bug/connection-limit)? Also, @jakeri you mentioned you got the same error through the developer console (although it clears faster there). Could you see if this still is the case and if it is the same error? I might have to ask Tibber support directly if the error is originating from the Tibber API and not this project...

To test the branch I think running these commands should work:

git clone https://github.com/BeatsuDev/tibber.py.git
git checkout bug/connection-limit
python <test_file.py>

Thanks again for bringing up this issue, and Merry Christmas! 🎄

[JoshuaDodds]

Could you test the branch I created for this issue and report back if the problem still persists @jakeri @JoshuaDodds (https://github.com/BeatsuDev/tibber.py/tree/bug/connection-limit)? Also, @jakeri you mentioned you got the same error through the developer console (although it clears faster there). Could you see if this still is the case and if it is the same error? I might have to ask Tibber support directly if the error is originating from the Tibber API and not this project...

Thanks again for bringing up this issue, and Merry Christmas! 🎄

On it now! Thanks for the attempt to fix! Will let you know and Merry Xmas to you too!

[JoshuaDodds]

@BeatsuDev this seems to improve the issue slightly. Normally with a fresh token i would only be able to break with control-c twice before hitting the connection limit and then needing to rest my access token. See below...

root@jdhp:/Development/tibber.py# python main.py
31121.64
31121.64
31121.64
31121.64
^CClosing websocket...
root@jdhp:/Development/tibber.py# ^C
root@jdhp:/Development/tibber.py# python main.py
31121.64
31121.64
31121.64
^CClosing websocket...
root@jdhp:/Development/tibber.py# python main.py
31121.64
31121.64
31121.64
31121.64
^CClosing websocket...
root@jdhp:/Development/tibber.py# python main.py
31121.64
31121.64
31121.64
31121.64
31121.64
^CClosing websocket...
root@jdhp:/Development/tibber.py# python main.py
31121.64
31121.64
31121.64
31121.64
31121.64
^CClosing websocket...

However as i continued to try... i did start getting the same behaviour again... see below:

root@jdhp:/Development/tibber.py# python main.py
Connection to websocket failed... Retrying in 10 seconds...
received 4429 (private use) Too many open connections on this server: 2; then sent 4429 (private use) Too many open connections on this server: 2
main.py has caught an error and is restarting live feed...
Connection to websocket failed... Retrying in 10 seconds...
received 4429 (private use) Too many open connections on this server: 2; then sent 4429 (private use) Too many open connections on this server: 2
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/tibber/types/home.py", line 228, in start_live_feed
    self._loop.run_until_complete(self.run_websocket_loop(exit_condition, retries = retries, **kwargs))
  File "/usr/lib/python3.10/asyncio/base_events.py", line 646, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.10/dist-packages/tibber/types/home.py", line 295, in run_websocket_loop
    await self._websocket_client.close_async()
  File "/usr/local/lib/python3.10/dist-packages/gql/client.py", line 651, in close_async
    if isinstance(self.session, ReconnectingAsyncClientSession):
AttributeError: 'Client' object has no attribute 'session'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Development/tibber.py/main.py", line 13, in <module>
    home.start_live_feed(retry_interval=15)
  File "/usr/local/lib/python3.10/dist-packages/tibber/types/home.py", line 238, in start_live_feed
    self._loop.run_until_complete(self._websocket_client.close_async())
  File "/usr/lib/python3.10/asyncio/base_events.py", line 646, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.10/dist-packages/gql/client.py", line 651, in close_async
    if isinstance(self.session, ReconnectingAsyncClientSession):
AttributeError: 'Client' object has no attribute 'session'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/tibber/types/home.py", line 228, in start_live_feed
    self._loop.run_until_complete(self.run_websocket_loop(exit_condition, retries = retries, **kwargs))
  File "/usr/lib/python3.10/asyncio/base_events.py", line 646, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.10/dist-packages/tibber/types/home.py", line 295, in run_websocket_loop
    await self._websocket_client.close_async()
  File "/usr/local/lib/python3.10/dist-packages/gql/client.py", line 651, in close_async
    if isinstance(self.session, ReconnectingAsyncClientSession):
AttributeError: 'Client' object has no attribute 'session'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Development/tibber.py/main.py", line 17, in <module>
    home.start_live_feed(retry_interval=15)
  File "/usr/local/lib/python3.10/dist-packages/tibber/types/home.py", line 238, in start_live_feed
    self._loop.run_until_complete(self._websocket_client.close_async())
  File "/usr/lib/python3.10/asyncio/base_events.py", line 646, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.10/dist-packages/gql/client.py", line 651, in close_async
    if isinstance(self.session, ReconnectingAsyncClientSession):
AttributeError: 'Client' object has no attribute 'session'

It almost seems like Tibber has something wrong with connection tracking at the API side and it only counts up and never tracks connections after they timeout. Once you hit an increment of 2 you are stuck until you reset the token.

BTW, I would be happy to gift you a Pulse if its a money issue preventing you from getting one. Might help you reproduce issues in real world scenarios a little bit better...

[BeatsuDev]

@JoshuaDodds Do you experience the same error when doing the same thing through the Tibber API explorer or with the pyTibber library?

[BeatsuDev]

About the offer for the Pulse; I'm unable to have a Tibber Pulse in my current housing situation, but thanks a lot for offering to gift me one! If I move and can choose Tibber as my provider I will probably look into getting one with the credits I've received from inviting friends to Tibber 🙌 So for now I'll unfortunately have to rely on bug reports and the demo account.

[JoshuaDodds]

@JoshuaDodds Do you experience the same error when doing the same thing through the Tibber API explorer or with the pyTibber library?

It's been a while since i played with the pyTibber lib but it did not do this then. They have made changes since then so who knows now. You can reproduce via the Tibber Explorer by first running your sample script in a terminal somewhere and then selecting the example query "Realitime subscription" and then hitting the play button in the explorer. But doing this multple times seems to clear the multiple connection error and then after that successfully hitting the button to relaunch the example query seems to work cleanly and without getting the error again.

(I just now tested this)

So i guess, no... i cant really reproduce it without help from the tibber.py lib first... weird issue! :)

[jakeri]

I'm trying the new version as we speak. Seems to be running better for a while, but my Pulse lost wifi-connection for 12 hours. I have a very weak wifi-signal.
I'll report back after some days.

[dobber81]

I have the same issue:

{
"errors": [
"Socket closed with event 4429 Too many open connections on this server: 2"
]
}

This problem is new to me. Everything worked great when using the code from before dec 2022.
I have a Pulse and use tibber.py to monitor pulse in domoticz.

When creating a new api key it works until I restart the script a few times or reboot. Also it works to click the run button in tibbers api explorer a few times to release the lock.

I noticed some other developers has started using websocket-api.tibber.com/v1-beta/gql instead of the old api.tibber.com/v1-beta/gql address for websocket connects. Could that be a part of the issue?

[dobber81]

Thanks for the update!
I'll try it out and report back if I run in to any issues.
Don't forget to update the example in README
I used this line in my script: home.start_live_feed("tibber.py/3.0.0")

[BeatsuDev]

Thanks for the update! I'll try it out and report back if I run in to any issues. Don't forget to update the example in README I used this line in my script: home.start_live_feed("tibber.py/3.0.0")

Thanks a lot for pointing that out! I'll change it now 😄

[JoshuaDodds]

@BeatsuDev I am trying out 0.3.0 and i have again TONS of spam in the logs...did you maybe leave some debugging messages turned on? I will dig deeper later when i have more time but my previous workaround to disable all the log spam is not working now with this update...

as a reminder the way i got rid of all the spam before was by adding this to the top of my module which imports tibber.py:
logging.getLogger("gql.transport.websockets").setLevel(logging.WARNING)

The spam seems to be happening right after a log message which says:
Updating home information to check if real time consumption is enabled.

and:
Subscribing to websocket.

Contents of the spam start with:
{"query": "query IntrospectionQuery {\n __schema {\n queryType {\n

and:
{"data":{"__schema":{"queryType":{"name":"Query"},

and maybe another variation of those two...

For each query there is another log item which contains the data received but it's personal data so i wont paste that here :)

On the upside.... I have restarted this several times and had multiple instances running as well and am not hitting the connection limit error so perhaps this is improved with these latest changes... will let it run over night and do a bit more testing in the morning.

[BeatsuDev]

@BeatsuDev I am trying out 0.3.0 and i have again TONS of spam in the logs...did you maybe leave some debugging messages turned on? I will dig deeper later when i have more time but my previous workaround to disable all the log spam is not working now with this update...

as a reminder the way i got rid of all the spam before was by adding this to the top of my module which imports tibber.py: logging.getLogger("gql.transport.websockets").setLevel(logging.WARNING)

The spam seems to be happening right after a log message which says: Updating home information to check if real time consumption is enabled.

and: Subscribing to websocket.

Contents of the spam start with: {"query": "query IntrospectionQuery {\n __schema {\n queryType {\n

and: {"data":{"__schema":{"queryType":{"name":"Query"},

and maybe another variation of those two...

For each query there is another log item which contains the data received but it's personal data so i wont paste that here :)

On the upside.... I have restarted this several times and had multiple instances running as well and am not hitting the connection limit error so perhaps this is improved with these latest changes... will let it run over night and do a bit more testing in the morning.

I'll have a look and see what's causing the logging to be so verbose... If it's because of the loggers in the gql library, I don't think I would like to change anything about it because it's a separate logger and should be configured separately from the tibber logger. Perhaps I could make it default to WARNING though, regardless of what the tibber level is🤔 I'll take a look!

Great that it helped the connection limit issue! I still don't really understand what fixed/helped the problem, because the logic has always remained the same...

[BeatsuDev]

@JoshuaDodds Someone already raised the issue of verbose logging in the gql repo: graphql-python/gql#178 They decided to keep it that way. The idea behind it is that DEBUG is used for actual debugging, while INFO is reserved for information logs and data exchanged by websockets/transports. The workaround should still be to set the gql logger to a higher logging level like this (I think this should work...):

logging.getLogger("gql.transport").setLevel(logging.WARNING)

or perhaps this could work (as suggested by a maintaner of the gql library)? Downside with this is that you will have to have gql installed because of the imports from the gql library...

import logging                                                                                                          
                                                                                                                        
logging.basicConfig(level=logging.INFO)                                                                                 
                                                                                                                        
from gql import Client, gql                                                                                             
from gql.transport.requests import RequestsHTTPTransport                                                                
from gql.transport.requests import log as requests_logger                                                               
                                                                                                                        
requests_logger.setLevel(logging.WARNING)                                                                               
                                                                                                                        
transport = RequestsHTTPTransport(                                                                                      
    url="https://countries.trevorblades.com/", verify=True, retries=3,                                                  
)                                                                                                                       
                                                                                                                        
client = Client(transport=transport, fetch_schema_from_transport=True)                                                  
                                                                                                                        
query = gql(                                                                                                            
    """                                                                                                                 
    query getContinents {                                                                                               
      continents {                                                                                                      
        code                                                                                                            
        name                                                                                                            
      }                                                                                                                 
    }                                                                                                                   
"""                                                                                                                     
)                                                                                                                       
                                                                                                                        
result = client.execute(query)                                                                                          
logging.info(f'We received the result: {result}')

The logging from the tibber logger should be unaffected by whatever you set the gql.transport logger's level to. I hope that helps!

[BeatsuDev]

Oh of course. I think the logging got verbose again because I switched the query execution method to use gql and aiohttpTransport instead of using aiohttp manually. So the logging is probably from the gql.transport.aiohttp logger. Setting the logger level of gql.trasnport should therefore do the trick! @JoshuaDodds

[JoshuaDodds]

Oh of course. I think the logging got verbose again because I switched the query execution method to use gql and aiohttpTransport instead of using aiohttp manually. So the logging is probably from the gql.transport.aiohttp logger. Setting the logger level of gql.trasnport should therefore do the trick! @JoshuaDodds

Yes indeed! That did the trick! Thank you! Will keep testing the connection reliability over the next few days to see if i hit that connection limit error again... so far looking good... many more restarts than i could have survived before without a new token.

[JoshuaDodds]

Still no connection limit issues after several restarts and the service is running for 20+ hours now without issues... looking good :)

P.S. I just sent you an invite to my currently private project where i am using tibber.py in case you are curious to see how i am using it. The project is in its infancy and a bit of a mess but just in case you are curious :)

[dobber81]

Looks very good here as well! No disconnects or connection limit issues so far.

[BeatsuDev]

Awesome! 🎉
Thanks to all of you for testing this bug for me. I'll close the issue for now, but if the problem turns up again, I'll reopen the issue.

@JoshuaDodds Thanks a lot, I'll check it out! I'm curious to see how tibber.py is being used 😄