Fix broken 3.8 SQLite test pipeline by eric-eclecticiq · Pull Request #266 · eclecticiq/OpenTAXII

eric-eclecticiq · 2023-12-20T10:29:33Z

Problem

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 Add sqlalchemy logs #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.

Normally SQLite can provide more logs, but the sqlite3 is 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

Fix bug in multithreaded use of sqlite #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 = <sqlalchemy.engine.base.Connection object at 0x7f5b483b9790>
    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       = <sqlalchemy.engine.base.Connection object at 0x7f5b483b9790>

    .tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:1094: 
    _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

    self = <sqlalchemy.dialects.sqlite.pysqlite.SQLiteDialect_pysqlite object at 0x7f5b483b0880>
    dbapi_connection = <sqlalchemy.pool.base._ConnectionFairy object at 0x7f5b483b97f0>

        def do_commit(self, dbapi_connection):
    >       dbapi_connection.commit()
    E       sqlite3.OperationalError: disk I/O error

    dbapi_connection = <sqlalchemy.pool.base._ConnectionFairy object at 0x7f5b483b97f0>
    self       = <sqlalchemy.dialects.sqlite.pysqlite.SQLiteDialect_pysqlite object at 0x7f5b483b0880>

    .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 = <SubRequest 'db_api_roots' for <Function test_delete_object[wrong collection]>>
    taxii2_sqldb_api = <opentaxii.persistence.sqldb.api.Taxii2SQLDatabaseAPI object at 0x7f5b483b0640>

        @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    = <SubRequest 'db_api_roots' for <Function test_delete_object[wrong collection]>>
    taxii2_sqldb_api = <opentaxii.persistence.sqldb.api.Taxii2SQLDatabaseAPI object at 0x7f5b483b0640>

    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       = <sqlalchemy.orm.session.Session object at 0x7f5b483b9340>
    .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       = <sqlalchemy.engine.base.Connection object at 0x7f5b483b9790>
            self       = <sqlalchemy.orm.session.SessionTransaction object at 0x7f5b483b9400>
            should_commit = True
            trans      = <sqlalchemy.engine.base.RootTransaction object at 0x7f5b4852c600>
    .tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2469: in commit
        self._do_commit()
            self       = <sqlalchemy.engine.base.RootTransaction object at 0x7f5b4852c600>
    .tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2659: in _do_commit
        self._connection_commit_impl()
            self       = <sqlalchemy.engine.base.RootTransaction object at 0x7f5b4852c600>
    .tox/py38-sqlalchemy14-werkzeuglt21-sqlite/lib/python3.8/site-packages/sqlalchemy/engine/base.py:2630: in _connection_commit_impl
        self.connection._commit_impl()
            self       = <sqlalchemy.engine.base.RootTransaction object at 0x7f5b4852c600>
    .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       = <sqlalchemy.engine.base.Connection object at 0x7f5b483b9790>
    .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   = (<class 'sqlite3.OperationalError'>, OperationalError('disk I/O error'), <traceback object at 0x7f5b48b4fbc0>)
            invalidate_pool_on_disconnect = True
            is_exit_exception = False
            newraise   = None
            parameters = None
            self       = <sqlalchemy.engine.base.Connection object at 0x7f5b483b9790>
            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       = <sqlalchemy.engine.base.Connection object at 0x7f5b483b9790>
    _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

    self = <sqlalchemy.dialects.sqlite.pysqlite.SQLiteDialect_pysqlite object at 0x7f5b483b0880>
    dbapi_connection = <sqlalchemy.pool.base._ConnectionFairy object at 0x7f5b483b97f0>

        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 = <sqlalchemy.pool.base._ConnectionFairy object at 0x7f5b483b97f0>
    self       = <sqlalchemy.dialects.sqlite.pysqlite.SQLiteDialect_pysqlite object at 0x7f5b483b0880>

    .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

eric-eclecticiq added 2 commits December 20, 2023 11:29

Update GH action versions

6acafd0

Recreate tox

e015e0b

eric-eclecticiq changed the title ~~Update GH action versions~~ Fix broken 3.8 SQLite test pipeline Dec 21, 2023

eric-eclecticiq mentioned this pull request Dec 21, 2023

Add sqlalchemy logs #264

Closed

Dispose DB connections as a teardown fixture

3481939

saaj approved these changes Dec 21, 2023

View reviewed changes

eric-eclecticiq merged commit 855bb45 into master Dec 21, 2023

eric-eclecticiq deleted the update-gh-actions branch December 21, 2023 16:17

Navigation Menu

Repository navigation

Fix broken 3.8 SQLite test pipeline - #266

Fix broken 3.8 SQLite test pipeline#266
eric-eclecticiq merged 3 commits into
masterfrom
update-gh-actions

eric-eclecticiq commented Dec 20, 2023 •

edited

Loading

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Conversation

eric-eclecticiq commented Dec 20, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Problem

How to reproduce

Hypothesis

Solution

Other

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

eric-eclecticiq commented Dec 20, 2023 •

edited

Loading