The test tests/taxii2/test_taxii2_sqldb.py::test_delete_object[wrong collection] returns sqlite3.OperationalError: disk I/O error with the env py38-sqlalchemy14-werkzeuglt21-sqlite.
How to reproduce
Run all the tests with tox -e py38-sqlalchemy14-werkzeuglt21-sqlite on a fresh python environment. Delete the old environment if existing before.
Other failed attempts to reproduce it, eg it passed:
Reuse an existing environment
Split the run in 2 sets tox -e py38-sqlalchemy14-werkzeuglt21-sqlite -- tests/test_* <failed-test> and tox -e py38-sqlalchemy14-werkzeuglt21-sqlite -- tests/taxii2/test_taxii2_sqldb.py. Both succeeded.
Do not use coverage: tox -e py38-sqlalchemy14-werkzeuglt21-sqlite -- --no-cov
Increase log verbosity (see #264)
Another surprising fact is that using the pip freeze output from last successful run job link also failed locally for me.
Hypothesis
A timing issue with sqlite accessing the DB file from a still alive connection while this one is deleted by the fixture app (truncate_app > clean_db).
I am in favor for this hypothesis because, by replacing os.remove(filename) with open(filename, 'w').close() to just prune the file content. The error is then OperationalError: database is locked.
According to this SO thread, this is mostly related to leftover connection. It should be added that this error happened more than for just the problematic test so it is not an exact correlation.
Explicitly dispose all DB connections from sqlalchemy.
It is not clear if the closed connection is the fix or just because it delays the code a bit.
Other
215 introduced sqlite database as files instead of memory. It is easier to do multi-threading with sqlachemy with that design.
This MR also update github actions. It was an attempt to see if there was a caching bug. It did not solve it but the pipeline also continued to work so at least the repo is using recent versions now.
Full test report
==================================== ERRORS ====================================
____________ ERROR at setup of test_delete_object[wrong collection] ____________
self =
autocommit = False
def _commit_impl(self, autocommit=False):
assert not self.__branch_from
# AUTOCOMMIT isolation-level is a dialect-specific concept, however
# if a connection has this set as the isolation level, we can skip
# the "autocommit" warning as the operation will do "autocommit"
# in any case
if autocommit and not self._is_autocommit_isolation():
/home/runner/work/OpenTAXII/OpenTAXII/.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/coverage/inorout.py:503: CoverageWarning: Module /home/runner/work/OpenTAXII/OpenTAXII/.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/opentaxii was never imported. (module-not-imported)
self.warn(f"Module {pkg} was never imported.", slug="module-not-imported")
util.warn_deprecated_20(
"The current statement is being autocommitted using "
"implicit autocommit, which will be removed in "
"SQLAlchemy 2.0. "
"Use the .begin() method of Engine or Connection in order to "
"use an explicit transaction for DML and DDL statements."
)
if self._has_events or self.engine._has_events:
self.dispatch.commit(self)
if self._echo:
if self._is_autocommit_isolation():
self._log_info(
"COMMIT using DBAPI connection.commit(), "
"DBAPI should ignore due to autocommit mode"
)
else:
self._log_info("COMMIT")
try:
> self.engine.dialect.do_commit(self.connection)
autocommit = False
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:1094:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self =
dbapi_connection =
def do_commit(self, dbapi_connection):
> dbapi_connection.commit()
E sqlite3.OperationalError: disk I/O error
dbapi_connection =
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/default.py:686: OperationalError
The above exception was the direct cause of the following exception:
request = >
taxii2_sqldb_api =
@pytest.fixture(scope="function")
def db_api_roots(request, taxii2_sqldb_api):
try:
api_roots = request.param
except AttributeError:
api_roots = API_ROOTS
for api_root in api_roots:
taxii2_sqldb_api.db.session.add(ApiRoot.from_entity(api_root))
> taxii2_sqldb_api.db.session.commit()
api_root = ApiRoot(default=False, description=None, id=7b3b1c50-929d-4a43-a730-243467352e62, is_public=False, title=third title)
api_roots = (ApiRoot(default=False, description=first description, id=e6aeea37-8122-4e45-88f0-99a3a44452d8, is_public=False, title... ApiRoot(default=False, description=None, id=7b3b1c50-929d-4a43-a730-243467352e62, is_public=False, title=third title))
request = >
taxii2_sqldb_api =
tests/conftest.py:310:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/orm/session.py:1454: in commit
self._transaction.commit(_to_root=self.future)
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/orm/session.py:839: in commit
trans.commit()
_to_root = False
autoclose = True
conn =
self =
should_commit = True
trans =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2469: in commit
self._do_commit()
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2659: in _do_commit
self._connection_commit_impl()
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2630: in _connection_commit_impl
self.connection._commit_impl()
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:1096: in _commit_impl
self._handle_dbapi_exception(e, None, None, None, None)
autocommit = False
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2134: in _handle_dbapi_exception
util.raise_(
context = None
cursor = None
e = OperationalError('disk I/O error')
exc_info = (, OperationalError('disk I/O error'), )
invalidate_pool_on_disconnect = True
is_exit_exception = False
newraise = None
parameters = None
self =
should_wrap = True
sqlalchemy_exception = OperationalError('(sqlite3.OperationalError) disk I/O error')
statement = None
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/util/compat.py:211: in raise_
raise exception
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:1094: in _commit_impl
self.engine.dialect.do_commit(self.connection)
autocommit = False
self =
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self =
dbapi_connection =
def do_commit(self, dbapi_connection):
> dbapi_connection.commit()
E sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) disk I/O error
E (Background on this error at: https://sqlalche.me/e/14/e3q8)
dbapi_connection =
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/default.py:686: OperationalError
---------------------------- Captured stderr setup -----------------------------
{"api": "opentaxii.persistence.sqldb.SQLDatabaseAPI", "event": "api.initialized", "logger": "opentaxii.utils", "level": "info", "timestamp": "2023-12-18T09:15:16.405815Z"}
{"event": "opentaxii.server_configured", "logger": "opentaxii.server", "level": "info", "timestamp": "2023-12-18T09:15:16.406071Z"}
{"api": "opentaxii.persistence.sqldb.Taxii2SQLDatabaseAPI", "event": "api.initialized", "logger": "opentaxii.utils", "level": "info", "timestamp": "2023-12-18T09:15:16.434748Z"}
{"api": "opentaxii.auth.sqldb.SQLDatabaseAPI", "event": "api.initialized", "logger": "opentaxii.utils", "level": "info", "timestamp": "2023-12-18T09:15:16.437455Z"}
------------------------------ Captured log setup ------------------------------
INFO opentaxii.utils:utils.py:45 {'api': 'opentaxii.persistence.sqldb.SQLDatabaseAPI', 'event': 'api.initialized', 'logger': 'opentaxii.utils', 'level': 'info', 'timestamp': '2023-12-18T09:15:16.405815Z'}
INFO opentaxii.server:server.py:162 {'event': 'opentaxii.server_configured', 'logger': 'opentaxii.server', 'level': 'info', 'timestamp': '2023-12-18T09:15:16.406071Z'}
INFO opentaxii.utils:utils.py:45 {'api': 'opentaxii.persistence.sqldb.Taxii2SQLDatabaseAPI', 'event': 'api.initialized', 'logger': 'opentaxii.utils', 'level': 'info', 'timestamp': '2023-12-18T09:15:16.434748Z'}
INFO opentaxii.utils:utils.py:45 {'api': 'opentaxii.auth.sqldb.SQLDatabaseAPI', 'event': 'api.initialized', 'logger': 'opentaxii.utils', 'level': 'info', 'timestamp': '2023-12-18T09:15:16.437455Z'}
Additionally these warnings are returned as well:
=============================== warnings summary ===============================
opentaxii/persistence/sqldb/taxii2models.py:12
/home/runner/work/OpenTAXII/OpenTAXII/opentaxii/persistence/sqldb/taxii2models.py:12: MovedIn20Warning: Deprecated API features detected! These feature(s) are not compatible with SQLAlchemy 2.0. To prevent incompatible upgrades prior to updating applications, ensure requirements files are pinned to "sqlalchemy<2.0". Set environment variable SQLALCHEMY_WARN_20=1 to show all deprecation warnings. Set environment variable SQLALCHEMY_SILENCE_UBER_WARNING=1 to silence this message. (Background on SQLAlchemy 2.0 at: https://sqlalche.me/e/b8d9)
Base = declarative_base()
tests/test_auth.py::test_unauthorized_request[11-True]
/home/runner/work/OpenTAXII/OpenTAXII/opentaxii/utils.py:90: RuntimeWarning: Repeated configuration attempted.
structlog.configure_once(
tests/test_cli.py::test_delete_content_blocks[good]
tests/test_delete_content_blocks.py::test_delete_content_blocks[True]
tests/test_delete_content_blocks.py::test_delete_content_blocks[False]
/home/runner/work/OpenTAXII/OpenTAXII/opentaxii/persistence/sqldb/api.py:450: SAWarning: Coercing Subquery object into a select() for use in IN(); please pass a select() construct explicitly
.filter(ContentBlock.id.in_(content_blocks_query.subquery()))
tests/test_config.py::test_env_vars_config[BACKWARDS_COMPAT_ENVVARS]
/home/runner/work/OpenTAXII/OpenTAXII/opentaxii/config.py:140: DeprecationWarning: Setting taxii1 attributes at top level is deprecated. Please nest 'persistence_api' inside 'taxii1'.
warn(
-- Docs: https://docs.pytest.org/en/stable/warnings.html
Problem
The test
tests/taxii2/test_taxii2_sqldb.py::test_delete_object[wrong collection]returnssqlite3.OperationalError: disk I/O errorwith the envpy38-sqlalchemy14-werkzeuglt21-sqlite.How to reproduce
Run all the tests with
tox -e py38-sqlalchemy14-werkzeuglt21-sqliteon a fresh python environment. Delete the old environment if existing before.Other failed attempts to reproduce it, eg it passed:
tox -e py38-sqlalchemy14-werkzeuglt21-sqlite -- tests/test_* <failed-test>andtox -e py38-sqlalchemy14-werkzeuglt21-sqlite -- tests/taxii2/test_taxii2_sqldb.py. Both succeeded.tox -e py38-sqlalchemy14-werkzeuglt21-sqlite -- --no-covAnother surprising fact is that using the
pip freezeoutput from last successful run job link also failed locally for me.Hypothesis
A timing issue with sqlite accessing the DB file from a still alive connection while this one is deleted by the fixture
app(truncate_app>clean_db).I am in favor for this hypothesis because, by replacing
os.remove(filename)withopen(filename, 'w').close()to just prune the file content. The error is thenOperationalError: database is locked.According to this SO thread, this is mostly related to leftover connection. It should be added that this error happened more than for just the problematic test so it is not an exact correlation.
Normally SQLite can provide more logs, but the
sqlite3is not able to leverage it according to this recent discussion. Also SQLite is providing extended error code but those are only available from Python 3.11 where the test always passed.Solution
Explicitly dispose all DB connections from
sqlalchemy.It is not clear if the closed connection is the fix or just because it delays the code a bit.
Other
215 introduced sqlite database as files instead of memory. It is easier to do multi-threading with sqlachemy with that design.
Full test report
==================================== ERRORS ==================================== ____________ ERROR at setup of test_delete_object[wrong collection] ____________ self =
autocommit = False
def _commit_impl(self, autocommit=False):
assert not self.__branch_from
# AUTOCOMMIT isolation-level is a dialect-specific concept, however
# if a connection has this set as the isolation level, we can skip
# the "autocommit" warning as the operation will do "autocommit"
# in any case
if autocommit and not self._is_autocommit_isolation():
/home/runner/work/OpenTAXII/OpenTAXII/.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/coverage/inorout.py:503: CoverageWarning: Module /home/runner/work/OpenTAXII/OpenTAXII/.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/opentaxii was never imported. (module-not-imported)
self.warn(f"Module {pkg} was never imported.", slug="module-not-imported")
util.warn_deprecated_20(
"The current statement is being autocommitted using "
"implicit autocommit, which will be removed in "
"SQLAlchemy 2.0. "
"Use the .begin() method of Engine or Connection in order to "
"use an explicit transaction for DML and DDL statements."
)
if self._has_events or self.engine._has_events:
self.dispatch.commit(self)
if self._echo:
if self._is_autocommit_isolation():
self._log_info(
"COMMIT using DBAPI connection.commit(), "
"DBAPI should ignore due to autocommit mode"
)
else:
self._log_info("COMMIT")
try:
> self.engine.dialect.do_commit(self.connection)
autocommit = False
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:1094:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self =
dbapi_connection =
def do_commit(self, dbapi_connection):
> dbapi_connection.commit()
E sqlite3.OperationalError: disk I/O error
dbapi_connection =
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/default.py:686: OperationalError
The above exception was the direct cause of the following exception:
request = >
taxii2_sqldb_api =
@pytest.fixture(scope="function")
def db_api_roots(request, taxii2_sqldb_api):
try:
api_roots = request.param
except AttributeError:
api_roots = API_ROOTS
for api_root in api_roots:
taxii2_sqldb_api.db.session.add(ApiRoot.from_entity(api_root))
> taxii2_sqldb_api.db.session.commit()
api_root = ApiRoot(default=False, description=None, id=7b3b1c50-929d-4a43-a730-243467352e62, is_public=False, title=third title)
api_roots = (ApiRoot(default=False, description=first description, id=e6aeea37-8122-4e45-88f0-99a3a44452d8, is_public=False, title... ApiRoot(default=False, description=None, id=7b3b1c50-929d-4a43-a730-243467352e62, is_public=False, title=third title))
request = >
taxii2_sqldb_api =
tests/conftest.py:310:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/orm/session.py:1454: in commit
self._transaction.commit(_to_root=self.future)
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/orm/session.py:839: in commit
trans.commit()
_to_root = False
autoclose = True
conn =
self =
should_commit = True
trans =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2469: in commit
self._do_commit()
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2659: in _do_commit
self._connection_commit_impl()
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2630: in _connection_commit_impl
self.connection._commit_impl()
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:1096: in _commit_impl
self._handle_dbapi_exception(e, None, None, None, None)
autocommit = False
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2134: in _handle_dbapi_exception
util.raise_(
context = None
cursor = None
e = OperationalError('disk I/O error')
exc_info = (, OperationalError('disk I/O error'), )
invalidate_pool_on_disconnect = True
is_exit_exception = False
newraise = None
parameters = None
self =
should_wrap = True
sqlalchemy_exception = OperationalError('(sqlite3.OperationalError) disk I/O error')
statement = None
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/util/compat.py:211: in raise_
raise exception
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:1094: in _commit_impl
self.engine.dialect.do_commit(self.connection)
autocommit = False
self =
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self =
dbapi_connection =
def do_commit(self, dbapi_connection):
> dbapi_connection.commit()
E sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) disk I/O error
E (Background on this error at: https://sqlalche.me/e/14/e3q8)
dbapi_connection =
self =
.tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/default.py:686: OperationalError
---------------------------- Captured stderr setup -----------------------------
{"api": "opentaxii.persistence.sqldb.SQLDatabaseAPI", "event": "api.initialized", "logger": "opentaxii.utils", "level": "info", "timestamp": "2023-12-18T09:15:16.405815Z"}
{"event": "opentaxii.server_configured", "logger": "opentaxii.server", "level": "info", "timestamp": "2023-12-18T09:15:16.406071Z"}
{"api": "opentaxii.persistence.sqldb.Taxii2SQLDatabaseAPI", "event": "api.initialized", "logger": "opentaxii.utils", "level": "info", "timestamp": "2023-12-18T09:15:16.434748Z"}
{"api": "opentaxii.auth.sqldb.SQLDatabaseAPI", "event": "api.initialized", "logger": "opentaxii.utils", "level": "info", "timestamp": "2023-12-18T09:15:16.437455Z"}
------------------------------ Captured log setup ------------------------------
INFO opentaxii.utils:utils.py:45 {'api': 'opentaxii.persistence.sqldb.SQLDatabaseAPI', 'event': 'api.initialized', 'logger': 'opentaxii.utils', 'level': 'info', 'timestamp': '2023-12-18T09:15:16.405815Z'}
INFO opentaxii.server:server.py:162 {'event': 'opentaxii.server_configured', 'logger': 'opentaxii.server', 'level': 'info', 'timestamp': '2023-12-18T09:15:16.406071Z'}
INFO opentaxii.utils:utils.py:45 {'api': 'opentaxii.persistence.sqldb.Taxii2SQLDatabaseAPI', 'event': 'api.initialized', 'logger': 'opentaxii.utils', 'level': 'info', 'timestamp': '2023-12-18T09:15:16.434748Z'}
INFO opentaxii.utils:utils.py:45 {'api': 'opentaxii.auth.sqldb.SQLDatabaseAPI', 'event': 'api.initialized', 'logger': 'opentaxii.utils', 'level': 'info', 'timestamp': '2023-12-18T09:15:16.437455Z'}
Additionally these warnings are returned as well:
=============================== warnings summary ===============================
opentaxii/persistence/sqldb/taxii2models.py:12
/home/runner/work/OpenTAXII/OpenTAXII/opentaxii/persistence/sqldb/taxii2models.py:12: MovedIn20Warning: Deprecated API features detected! These feature(s) are not compatible with SQLAlchemy 2.0. To prevent incompatible upgrades prior to updating applications, ensure requirements files are pinned to "sqlalchemy<2.0". Set environment variable SQLALCHEMY_WARN_20=1 to show all deprecation warnings. Set environment variable SQLALCHEMY_SILENCE_UBER_WARNING=1 to silence this message. (Background on SQLAlchemy 2.0 at: https://sqlalche.me/e/b8d9)
Base = declarative_base()
tests/test_auth.py::test_unauthorized_request[11-True]
/home/runner/work/OpenTAXII/OpenTAXII/opentaxii/utils.py:90: RuntimeWarning: Repeated configuration attempted.
structlog.configure_once(
tests/test_cli.py::test_delete_content_blocks[good]
tests/test_delete_content_blocks.py::test_delete_content_blocks[True]
tests/test_delete_content_blocks.py::test_delete_content_blocks[False]
/home/runner/work/OpenTAXII/OpenTAXII/opentaxii/persistence/sqldb/api.py:450: SAWarning: Coercing Subquery object into a select() for use in IN(); please pass a select() construct explicitly
.filter(ContentBlock.id.in_(content_blocks_query.subquery()))
tests/test_config.py::test_env_vars_config[BACKWARDS_COMPAT_ENVVARS]
/home/runner/work/OpenTAXII/OpenTAXII/opentaxii/config.py:140: DeprecationWarning: Setting taxii1 attributes at top level is deprecated. Please nest 'persistence_api' inside 'taxii1'.
warn(
-- Docs: https://docs.pytest.org/en/stable/warnings.html