log flooded with recorder errors: QueuePool limit of size 5 overflow 10 reached, connection timed out

[nkgilley]

Make sure you are running the latest version of Home Assistant before reporting an issue.

You should only file an issue if you found a bug. Feature and enhancement requests should go in the Feature Requests section of our community forum:

Home Assistant release (hass --version):
0.25.0.dev0

Python release (python3 --version):
3.5

Component/platform:
recorder

Description of problem:
Just switched to postgres and I'm seeing a ton of these errors in the log. Also the history and detail cards in the frontend fail to load.

Problem-relevant configuration.yaml entries:

recorder:
  purge_days: 90
  db_url: postgresql://nolan:password@192.168.1.100/homeassistant

Traceback (if applicable):

16-07-30 10:19:30 homeassistant.components.recorder: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30
Traceback (most recent call last):
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/pool.py", line 1044, in _do_get
    return self._pool.get(wait, self._timeout)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/util/queue.py", line 156, in get
    raise Empty
sqlalchemy.util.queue.Empty

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/app/homeassistant/components/recorder/__init__.py", line 65, in execute
    (row.to_native() for row in q)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/orm/query.py", line 2761, in __iter__
    return self._execute_and_instances(context)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/orm/query.py", line 2774, in _execute_and_instances
    close_with_result=True)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/orm/query.py", line 2765, in _connection_from_session
    **kw)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/orm/session.py", line 893, in connection
    execution_options=execution_options)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/orm/session.py", line 898, in _connection_for_bind
    engine, execution_options)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/orm/session.py", line 334, in _connection_for_bind
    conn = bind.contextual_connect()
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/engine/base.py", line 2039, in contextual_connect
    self._wrap_pool_connect(self.pool.connect, None),
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/engine/base.py", line 2074, in _wrap_pool_connect
    return fn()
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/pool.py", line 376, in connect
    return _ConnectionFairy._checkout(self)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/pool.py", line 713, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/pool.py", line 480, in checkout
    rec = pool._do_get()
  File "/usr/local/lib/python3.4/site-packages/sqlalchemy/pool.py", line 1053, in _do_get
    (self.size(), self.overflow(), self._timeout))

[fanaticDavid]

I'm seeing these errors too, starting just 18 minutes after the last restart of my HASS instance. Over time, my home-assistant.log is absolutely flooded with these errors. I did not have this problem with version 0.24 of HASS, but I do with version 0.25 (I skipped version 0.24.1).

I connect to a MariaDB instance running on my Synology NAS. For this, my configuration.yaml file has the following code:

recorder:
  purge_days: 14
  db_url: !env_var RECORDER_DB_URL

And my hass.env file has the following bit:

RECORDER_DB_URL="mysql://username:password@192.168.x.x/HASS_db"

[balloob]

So both of you are using the mysqlclient dependency to connect to your database, right?

Cc @kellerza

[kellerza]

Something is probably not closing a session, but its not clear from the trace.

The recorder.execute function did not change since the first release and as far as I can see not being used internally by the recorder either

What other components/platforms do you have switched on? history logbook speedtest all use recorder.execute

[fanaticDavid]

I am using the Speedtest component in HASS, and now that you mention it that may actually be the culprit: that component was changed in version 0.25 to retrieve the latest test results from the database instead of showing "unknown" (after HASS or the host it's running on has been restarted).

[kellerza]

Yes, just tested it and it is quite persistent (3 updates per update cycle) and that will continue until it either find a valid DB entry or runs the speedtest (value not None)

I guess the question is how to close the execute query's session, since it does not seem to auto-close on scope exit

Please try to disable speedtest and let us know

[nkgilley]

It does appear to be speedtest. After disabling there aren't any errors. My bad!! 😨

[kellerza]

My suggestions for a fix:

• Figure how to close session properly (can you guys try patching recorder with the function below, line 55)
• Only run the speedtest DB query on HOME_ASSISTANT_START

def execute(q):
    """Query the database and convert the objects to HA native form.

    This method also retries a few times in the case of stale connections.
    """
    import sqlalchemy.exc
    try:
        for _ in range(0, RETRIES):
            try:
                return [
                    row for row in
                    (row.to_native() for row in q)
                    if row is not None]
            except sqlalchemy.exc.SQLAlchemyError as e:
                log_error(e, retry_wait=QUERY_RETRY_WAIT, rollback=True)
    finally:
        print('closing session')
        Session().close()
    return []

[kellerza]

@nkgilley in the end I think we should probably improve both. Let me know if the above works for you and I'll push/PR the recorder update.

@nkgilley Although closing the session will remove the problem, do you mind moving the DB query in speedtest?
I would suggest a new function firing once:

hass.bus.listen_once(EVENT_HOMEASSISTANT_START, do_recorder_things_once_if_null)

[nkgilley]

@kellerza I tried your patch and it seems to have fixed the issue. I like your idea to run the db query on home assistant start. I will make that change and propose a PR. Thanks!

[nkgilley]

@kellerza I can't figure out how to get the db query working at home-assistatnt start up. I always get an error that I think is happening because the speedtest component has not completely loaded all of its entities.

Traceback (most recent call last):
  File "/home/nolan/dev/home-assistant/homeassistant/core.py", line 844, in job_handler
    func(*args)
  File "/home/nolan/dev/home-assistant/homeassistant/core.py", line 308, in onetime_listener
    listener(event)
  File "/home/nolan/dev/home-assistant/homeassistant/components/sensor/speedtest.py", line 63, in check_last_state
    recorder.query('States').filter(
  File "/home/nolan/dev/home-assistant/homeassistant/components/recorder/__init__.py", line 115, in query
    return Session().query(get_model(model_name), *args)
TypeError: 'NoneType' object is not callable

[kellerza]

Point me to your branch and I'll have a look in ~30min, PM me on gitter