SQL Sensor errors after upgrade to 0.64.3

JvS · March 6, 2018, 5:13pm

I just upgraded to HA 0.64.3 and seem to have problems with the sql sensor. They’re not working and I get the following errors in logfile:

sql: Error on device update!
5:47 PM components/sensor/sql.py (ERROR)
Error closing cursor
5:47 PM /srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/base.py (ERROR)
sql: Error on device update!
5:47 PM components/sensor/sql.py (ERROR)
Error closing cursor
5:47 PM /srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/base.py (ERROR)
sql: Error on device update!
5:47 PM components/sensor/sql.py (ERROR)
Error closing cursor
5:47 PM /srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/base.py (ERROR)

Starting with the 1st error received:

Error closing cursor
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1186, in fetchone
    row = self._fetchone_impl()
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1067, in _fetchone_impl
    return self.cursor.fetchone()
sqlite3.ProgrammingError: Cannot operate on a closed database.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1288, in _safe_close_cursor
    cursor.close()
sqlite3.ProgrammingError: Cannot operate on a closed database.

The config:

  - platform: sql
    db_url: sqlite:///home/homeassistant/.homeassistant/slimmemeter/meterdata.db
    queries:
      - name: actueel_electriciteits_verbruik_net
        query: 'SELECT actual_power_received FROM meter_reads_electricity ORDER BY date_time DESC LIMIT 1'
        column: 'actual_power_received'
        unit_of_measurement: kWH
      - name: actueel_electriciteits_verbruik_zon
        query: 'SELECT actual_power_delivered FROM meter_reads_electricity ORDER BY date_time DESC LIMIT 1'
        column: 'actual_power_delivered'
        unit_of_measurement: kWH
      - name: gas_verbruik_laatste_uur
        query: 'SELECT last_hourly_gas_usage FROM meter_reads_gas ORDER BY last_hourly_value_datetime DESC LIMIT 1'
        column: 'last_hourly_gas_usage'
        unit_of_measurement: M3

The same config worked in 0.63.

Any ideas anyone?

namadori · March 6, 2018, 8:40pm

This message to get @dgomes attention

By the way, I’m using the SQL sensor with MySQL (MariaDB) and 0.64.3 with no errors.

dgomes · March 6, 2018, 9:04pm

Hi @JvS,

Can you test with only ONE query in the configuration ?

JvS · March 6, 2018, 10:02pm

Hi @dgomes thanks for your reply!

I just commented out all of the queries except the 1st one and restarted. Still getting errors.

For reference the whole log file since restart:

2018-03-06 22:52:52 ERROR (SyncWorker_12) [sqlalchemy.pool.NullPool] Error closing cursor
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1186, in fetchone
    row = self._fetchone_impl()
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1067, in _fetchone_impl
    return self.cursor.fetchone()
sqlite3.ProgrammingError: Cannot operate on a closed database.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1288, in _safe_close_cursor
    cursor.close()
sqlite3.ProgrammingError: Cannot operate on a closed database.
2018-03-06 22:52:52 ERROR (MainThread) [homeassistant.components.sensor] sql: Error on device update!
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1186, in fetchone
    row = self._fetchone_impl()
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1067, in _fetchone_impl
    return self.cursor.fetchone()
sqlite3.ProgrammingError: Cannot operate on a closed database.

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 197, in _async_add_entity
    yield from entity.async_device_update(warning=False)
  File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 327, in async_device_update
    yield from self.hass.async_add_job(self.update)
  File "/usr/local/lib/python3.6/asyncio/futures.py", line 327, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/local/lib/python3.6/asyncio/tasks.py", line 250, in _wakeup
    future.result()
  File "/usr/local/lib/python3.6/asyncio/futures.py", line 243, in result
    raise self._exception
  File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/components/sensor/sql.py", line 132, in update
    for res in result:
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 868, in __iter__
    row = self.fetchone()
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1195, in fetchone
    self.cursor, self.context)
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
    exc_info
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 186, in reraise
    raise value.with_traceback(tb)
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1186, in fetchone
    row = self._fetchone_impl()
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/result.py", line 1067, in _fetchone_impl
    return self.cursor.fetchone()
sqlalchemy.exc.ProgrammingError: (sqlite3.ProgrammingError) Cannot operate on a closed database. (Background on this error at: http://sqlalche.me/e/f405)
2018-03-06 22:53:45 ERROR (SyncWorker_14) [sqlalchemy.pool.NullPool] Exception during reset or similar
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/pool.py", line 703, in _finalize_fairy
    fairy._reset(pool)
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/pool.py", line 873, in _reset
    pool._dialect.do_rollback(self)
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 457, in do_rollback
    dbapi_connection.rollback()
sqlite3.ProgrammingError: SQLite objects created in a thread can only be used in that same thread.The object was created in thread id 1774896240 and this is thread id 1808450672
2018-03-06 22:53:45 ERROR (SyncWorker_14) [sqlalchemy.pool.NullPool] Exception closing connection <sqlite3.Connection object at 0x688b0420>
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/pool.py", line 703, in _finalize_fairy
    fairy._reset(pool)
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/pool.py", line 873, in _reset
    pool._dialect.do_rollback(self)
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 457, in do_rollback
    dbapi_connection.rollback()
sqlite3.ProgrammingError: SQLite objects created in a thread can only be used in that same thread.The object was created in thread id 1774896240 and this is thread id 1808450672

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/pool.py", line 317, in _close_connection
    self._dialect.do_close(connection)
  File "/srv/homeassistant/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 463, in do_close
    dbapi_connection.close()
sqlite3.ProgrammingError: SQLite objects created in a thread can only be used in that same thread.The object was created in thread id 1774896240 and this is thread id 1808450672

It’s strange, looks like the DB file is not being opened (it exists and works, i just checked with sqlite CLI and also the meterreads are being loaded succesfully. I wonder if something did not go correctly with the upgrade but the history recorder is working, so not sure. (running Python 3.6.4 btw)

Johan

dgomes · March 6, 2018, 10:08pm

how is slimmemeter/meterdata.db updated ? any chance the process updating the database is resetting the database ?

JvS · March 6, 2018, 10:16pm

There’s a Python script running in the background, it has a continuous db connection and updates the meter_read table when receiving a new message from the smart meter (every 10 seconds). I can manually do the same query using sqlite3 without a problem. Also nothing in this process has changed for some time other then the upgrade to 0.64.3 today.

sqlite3 transcript from just now:

(homeassistant) homeassistant@hassbian:~/.homeassistant/slimmemeter $ sqlite3 meterdata.db
SQLite version 3.16.2 2017-01-06 16:32:41
Enter ".help" for usage hints.
sqlite> SELECT actual_power_received FROM meter_reads_electricity ORDER BY date_time DESC LIMIT 1;
2.85
sqlite>

I will try to setup a simple database sensor (on another database file) to see if that works. So then I know if it’s this specific database or something else. Will do that tomorrow and let you know

Thanks anyway for having a look!

dgomes · March 6, 2018, 10:21pm

One change occurred from 0.63 to 0.64 which was a bug fix:

SQL alchemy sessions where not being properly closed. This created in some databases (MySQL) large pools of sessions.

I believe this to be an issue only with SQLalchemy and shared access to db (which is by no means something common for SQLlite)

If possible configure the logger:

logger:
  default: error
  logs:
     sqlalchemy: debug
     homeassistant.components.sensor.sql: debug

and share a full log using hastebin.com

dgomes · March 6, 2018, 11:29pm

@JvS, good news!

I was able to replicate your scenario and traced the error to my bug fix.

I’ve now issued a PR with a bug fix to the bug fix

Hopefully it will make it to the next release.

JvS · March 7, 2018, 4:18pm

Hi @dgomes I just implemented your changes and my sensors are back :-). Thanks a million for your quick resolution!

Johan

Mariusthvdb · March 25, 2018, 9:46pm

hi,
just pursuing my first effort on this new sensor with the below configuration on the recorder db (hence the commenting out of the db_url?):

  - platform: sql
#    db_url: mysql://user:password@localhost/hass
    queries:
      - name: Hassio sql DB size
        query: 'SELECT table_schema "database", Round(Sum(data_length + index_length) / 1024, 1) "value" FROM information_schema.tables WHERE table_schema="hass" GROUP BY table_schema;'
        column: 'value'
        unit_of_measurement: kB

results in this error:

2018-03-25 23:42:04 ERROR (SyncWorker_15) [homeassistant.components.sensor.sql] Error executing query SELECT table_schema "database", Round(Sum(data_length + index_length) / 1024, 1) "value" FROM information_schema.tables WHERE table_schema="hass" GROUP BY table_schema LIMIT 1;: (sqlite3.OperationalError) no such table: information_schema.tables [SQL: 'SELECT table_schema "database", Round(Sum(data_length + index_length) / 1024, 1) "value" FROM information_schema.tables WHERE table_schema="hass" GROUP BY table_schema LIMIT 1;'] (Background on this error at: http://sqlalche.me/e/e3q8)

what would be wrong please?

Thanks,
Marius

JvS · March 27, 2018, 11:51am

hi @Mariusthvdb the key in the error is:

no such table: information_schema.tables

It has nothing to do with the sql_sensor, the query is not correct for sqlite. I’m not behind my system right now but what it looks like is you are sending a mysql query to a sqlite database (sqlite does not have the concept of ‘information_schema’ to my knowledge). Since you commented out the db_url it probably defaults to the sqlite default database for the query.

For documentation about sqlite and HA’s database schema see https://www.sqlite.org/index.html and https://www.home-assistant.io/docs/backend/database/

Mariusthvdb · March 27, 2018, 12:24pm

Hi @JvS
Indeed is was trying to read the default db here, and already knew the query was wrong. Found another one which was also incorrect, so hoped the community would be able to help me with tis default situation.

Even thought the dev’s are changing their minds o this sensor, maybe i could have a go with a precise query for the HA database?

MY SQL is a bit rusty after several years… even this simple… duh

JvS · March 27, 2018, 1:25pm

Trouble is that sqlite is slightly different from mysql which is slightly different from sqlserver etc. So if you use DB specifics like ‘information_schema’ it will only work in that specific DB.

I can’t quite make out from the SQL what you’re trying to achieve, if you can describe I’m happy to help (just DM me).

Also helpful is to use a command-line interface 1st to test your SQL before putting it in a sensor. For sqlite (under Linux) the CLI is sqlite3, see my previous link for sqlite documentation.

Mariusthvdb · March 27, 2018, 3:22pm

thanks for your help was just trying to measure the size of the home-assistant_v2.db file.
It is growing and purge isn’t working anymore, so i need an extra eye on the file

namadori · March 27, 2018, 8:44pm

For The default database you can use the file size sensor instead.

Mariusthvdb · March 27, 2018, 9:12pm

indeed, i do .
was worried using that might interfere with the recorder purge (it doesn’t anymore in my setup)