search

Bogdanp / django_dramatiq

A Django app that integrates with Dramatiq.
https://dramatiq.io
Other
347 stars 77 forks source link

intermittent test failure #22

Closed MattBlack85 closed 3 years ago

MattBlack85 commented 6 years ago

I went through a test that seems to fail randomly from time to time

================================================================================================================================== FAILURES ==================================================================================================================================
_________________________________________________________________________________________________________________ test_admin_middleware_keeps_track_of_tasks _________________________________________________________________________________________________________________

transactional_db = None, broker = <dramatiq.brokers.stub.StubBroker object at 0x7f5bd128f748>, worker = <dramatiq.worker.Worker object at 0x7f5bd0870eb8>

    def test_admin_middleware_keeps_track_of_tasks(transactional_db, broker, worker):
        # Given an actor
        @dramatiq.actor
        def do_work():
            pass

        # When I send it a delayed message
        do_work.send_with_options(delay=1000)

        # Then a Task should be stored to the database
        task = Task.tasks.get()
        assert task
        assert task.status == Task.STATUS_DELAYED

        # When I join on the broker
        broker.join(do_work.queue_name)
        worker.join()

        # And reload the task
        task.refresh_from_db()

        # The the Task's status should be updated
>       assert task.status == Task.STATUS_DONE
E       AssertionError: assert 'enqueued' == 'done'
E         - enqueued
E         + done

tests/test_admin_middleware.py:28: AssertionError

----------- coverage: platform linux, python 3.7.0-final-0 -----------
Coverage HTML written to dir htmlcov

===================================================================================================================== 1 failed, 9 passed in 2.36 seconds =====================================================================================================================

not sure about the cause nor I have investigated this deeply but maybe worth a look at some point

MattBlack85 commented 6 years ago

could it be that the task isn't finished when the test checks the status?

ashleybartlett commented 3 years ago

The issue here is that sqlite table is locked when trying to write the task object using the middleware. Which is surprising, as I thought the task wouldn't execute until after the middleware has written, so must be something else causing the table to be locked due to threading. 

Traceback (most recent call last):
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/dramatiq/broker.py", line 98, in emit_after
    getattr(middleware, "after_" + signal)(self, *args, **kwargs)
  File "/Users/abartlett/src/github/django_dramatiq/django_dramatiq/middleware.py", line 21, in after_enqueue
    Task.tasks.create_or_update_from_message(
  File "/Users/abartlett/src/github/django_dramatiq/django_dramatiq/models.py", line 16, in create_or_update_from_message
    task, _ = self.using(DATABASE_LABEL).update_or_create(
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/query.py", line 608, in update_or_create
    obj, created = self.select_for_update().get_or_create(defaults, **kwargs)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/query.py", line 588, in get_or_create
    return self.create(**params), True
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/query.py", line 453, in create
    obj.save(force_insert=True, using=self.db)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/base.py", line 726, in save
    self.save_base(using=using, force_insert=force_insert,
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/base.py", line 763, in save_base
    updated = self._save_table(
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/base.py", line 868, in _save_table
    results = self._do_insert(cls._base_manager, using, fields, returning_fields, raw)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/base.py", line 906, in _do_insert
    return manager._insert(
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/query.py", line 1270, in _insert
    return query.get_compiler(using=using).execute_sql(returning_fields)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1416, in execute_sql
    cursor.execute(sql, params)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/backends/utils.py", line 66, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/utils.py", line 90, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/lib/python3.8/site-packages/django/db/backends/sqlite3/base.py", line 423, in execute
    return Database.Cursor.execute(self, query, params)
django.db.utils.OperationalError: database table is locked

I can consistently get this test to fail using pytest-flakefinder. 

❯ pytest -k test_test.py -vv --flake-finder
=============================================================================== test session starts ================================================================================
platform darwin -- Python 3.8.1, pytest-6.2.4, py-1.10.0, pluggy-0.13.1 -- /Users/abartlett/.pyenv/versions/3.8.1/envs/django_dramatiq/bin/python
cachedir: .pytest_cache
django: settings: tests.settings (from ini)
rootdir: /Users/abartlett/src/github/django_dramatiq, configfile: setup.cfg, testpaths: tests
plugins: cov-2.11.1, django-4.2.0, flakefinder-1.0.0
collected 701 items / 700 deselected / 1 selected

tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks FAILED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks FAILED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks FAILED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks PASSED                                                                                                  [  2%]
===================================================================================== FAILURES =====================================================================================
.... <failures cut out for brevity> 
============================================================================= short test summary info ==============================================================================
FAILED tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks - AssertionError: 'failed' != 'done'
FAILED tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks - AssertionError: 'failed' != 'done'
FAILED tests/test_test.py::TestDramatiqTestCase::test_worker_consumes_tasks - AssertionError: 'failed' != 'done'
================================================================== 3 failed, 47 passed, 700 deselected in 13.22s ===================================================================

I did try doing a retry on error in the test task, though it never seems to be a problem at that side, only when creating in the middleware.

ashleybartlett commented 3 years ago
Oh wait, It looks like the `after_enqueue` update is what is failing. Which does run after the task, which makes some sense now. I tried adding a sleep to the task, and that just made it sad. Though that might be because i'm running the same thing 50 times with an inherent added delay. Nope, travis seems to show I was wrong. ```Traceback (most recent call last): File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/dramatiq/broker.py", line 89, in emit_before getattr(middleware, "before_" + signal)(self, *args, **kwargs) File "/home/travis/build/Bogdanp/django_dramatiq/django_dramatiq/middleware.py", line 36, in before_process_message queue_name=message.queue_name, File "/home/travis/build/Bogdanp/django_dramatiq/django_dramatiq/models.py", line 20, in create_or_update_from_message **extra_fields, File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/query.py", line 594, in update_or_create obj, created = self._create_object_from_params(kwargs, params, lock=True) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/query.py", line 610, in _create_object_from_params obj = self.create(**params) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/query.py", line 447, in create obj.save(force_insert=True, using=self.db) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/base.py", line 754, in save force_update=force_update, update_fields=update_fields) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/base.py", line 792, in save_base force_update, using, update_fields, File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/base.py", line 895, in _save_table results = self._do_insert(cls._base_manager, using, fields, returning_fields, raw) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/base.py", line 935, in _do_insert using=using, raw=raw, File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/manager.py", line 85, in manager_method return getattr(self.get_queryset(), name)(*args, **kwargs) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/query.py", line 1254, in _insert return query.get_compiler(using=using).execute_sql(returning_fields) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1397, in execute_sql cursor.execute(sql, params) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/backends/utils.py", line 66, in execute return self._execute_with_wrappers(sql, params, many=False, executor=self._execute) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers return executor(sql, params, many, context) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/backends/utils.py", line 84, in _execute return self.cursor.execute(sql, params) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/utils.py", line 90, in __exit__ raise dj_exc_value.with_traceback(traceback) from exc_value File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/backends/utils.py", line 84, in _execute return self.cursor.execute(sql, params) File "/home/travis/build/Bogdanp/django_dramatiq/.tox/py37-cpython-django31/lib/python3.7/site-packages/django/db/backends/sqlite3/base.py", line 413, in execute return Database.Cursor.execute(self, query, params) django.db.utils.OperationalError: database table is locked CRITICAL dramatiq.broker.StubBroker:broker.py:100 Unexpected failure in after_enqueue. ```