beanie icon indicating copy to clipboard operation
beanie copied to clipboard

[BUG] From 1.24.0 the exception RevisionIdWasChanged is raised differently from 1.23.6

Open mamazinho opened this issue 1 year ago • 12 comments

Hi, this fix is broken a testcase that dont brake in 1.23.6. From this PR, an exception " except DuplicateKeyError:

      raise RevisionIdWasChanged

E beanie.exceptions.RevisionIdWasChanged"

is raised on my POST route in .save() method

As you see below:

Runnings test with 1.23.6

image

Runnings test with 1.24.0

image

Anything changed between the two tests, only beanie version, I read that problem can occur with race condition code, but is not the case, the exception is raised on inside the POST I save an "Machine" (my entity) instance.

On test, machine is created:

image

My API only gets the "machine" and updates a field:

image

Model is a common Document model (TimestampedDocument is just a class with updated_at and created_at fields):

image

Factory also is a common factory:

image

All stack error ============================= test session starts ============================== platform linux -- Python 3.11.5, pytest-7.4.4, pluggy-1.4.0 rootdir: /workspace/cz-coordinator-api configfile: pyproject.toml plugins: anyio-3.7.1, asyncio-0.21.1, Faker-22.6.0, cov-4.1.0, httpx-0.26.0, fastapi-deps-0.2.3, celery-0.0.0 asyncio: mode=Mode.STRICT collected 1 item

tests/drivers/test_api.py F [100%]

=================================== FAILURES =================================== ___________________ test_post_session_status_history_success ___________________

data = OrderedDict([('_id', '36'), ('revision_id', Binary(b"\xa0Q\xb1V?\xceJ\x84\x92\xd8\xf1\xd3\xfd'\xc3U", 4)), ('created_a..., ('external_id', 'kjdvqxmfejcvHlaFvhlG'), ('last_appeal_token_at', datetime.datetime(2024, 2, 22, 2, 6, 36, 767000))]) args = (), kwargs = {}

@wraps(fn)
def wrapper(data, *args, **kwargs):
    try:
      return fn(data, *args, **kwargs)

/home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/mongomock_motor/patches.py:56:


self = Collection(Database(mongomock.MongoClient('localhost', 27017), 'coordinator'), 'Machine') data = OrderedDict([('_id', '36'), ('revision_id', Binary(b"\xa0Q\xb1V?\xceJ\x84\x92\xd8\xf1\xd3\xfd'\xc3U", 4)), ('created_a..., ('external_id', 'kjdvqxmfejcvHlaFvhlG'), ('last_appeal_token_at', datetime.datetime(2024, 2, 22, 2, 6, 36, 767000))]) session = None, ordered = True

def _insert(self, data, session=None, ordered=True):
    if session:
        raise_not_implemented('session', 'Mongomock does not handle sessions yet')
    if not isinstance(data, Mapping):
        results = []
        write_errors = []
        num_inserted = 0
        for index, item in enumerate(data):
            try:
                results.append(self._insert(item))
            except WriteError as error:
                write_errors.append({
                    'index': index,
                    'code': error.code,
                    'errmsg': str(error),
                    'op': item,
                })
                if ordered:
                    break
                else:
                    continue
            num_inserted += 1
        if write_errors:
            raise BulkWriteError({
                'writeErrors': write_errors,
                'nInserted': num_inserted,
            })
        return results

    if not all(isinstance(k, str) for k in data):
        raise ValueError('Document keys must be strings')

    if BSON:
        # bson validation
        BSON.encode(data, check_keys=True)

    # Like pymongo, we should fill the _id in the inserted dict (odd behavior,
    # but we need to stick to it), so we must patch in-place the data dict
    if '_id' not in data:
        data['_id'] = ObjectId()

    object_id = data['_id']
    if isinstance(object_id, dict):
        object_id = helpers.hashdict(object_id)
    if object_id in self._store:
      raise DuplicateKeyError('E11000 Duplicate Key Error', 11000)

E pymongo.errors.DuplicateKeyError: E11000 Duplicate Key Error

/home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/mongomock/collection.py:516: DuplicateKeyError

During handling of the above exception, another exception occurred:

self = Machine(id='36', revision_id=None, created_at=datetime.datetime(2017, 3, 5, 9, 19, 7, 719000), updated_at=datetime.dat...46, 791000), external_id='kjdvqxmfejcvHlaFvhlG', last_appeal_token_at=datetime.datetime(2024, 2, 22, 2, 6, 36, 767415)) ignore_revision = False, session = None, bulk_writer = None, skip_actions = [] skip_sync = None args = ({'$set': {'_id': '36', 'revision_id': UUID('a051b156-3fce-4a84-92d8-f1d3fd27c355'), 'created_at': datetime.datetime(2...0), 'external_id': 'kjdvqxmfejcvHlaFvhlG', 'last_appeal_token_at': datetime.datetime(2024, 2, 22, 2, 6, 36, 767415)}},) pymongo_kwargs = {'upsert': True} arguments = [{'$set': {'_id': '36', 'revision_id': UUID('a051b156-3fce-4a84-92d8-f1d3fd27c355'), 'created_at': datetime.datetime(2...atetime(2024, 2, 22, 2, 6, 36, 767415)}}, <beanie.odm.operators.update.general.SetRevisionId object at 0x7f0604aebe50>] use_revision_id = True, find_query = {'_id': '36', 'revision_id': None} new_revision_id = UUID('a051b156-3fce-4a84-92d8-f1d3fd27c355')

@wrap_with_actions(EventTypes.UPDATE)
@save_state_after
async def update(
    self,
    *args,
    ignore_revision: bool = False,
    session: Optional[ClientSession] = None,
    bulk_writer: Optional[BulkWriter] = None,
    skip_actions: Optional[List[Union[ActionDirections, str]]] = None,
    skip_sync: Optional[bool] = None,
    **pymongo_kwargs,
) -> DocType:
    """
    Partially update the document in the database

    :param args: *Union[dict, Mapping] - the modifications to apply.
    :param session: ClientSession - pymongo session.
    :param ignore_revision: bool - force update. Will update even if revision id is not the same, as stored
    :param bulk_writer: "BulkWriter" - Beanie bulk writer
    :param pymongo_kwargs: pymongo native parameters for update operation
    :return: None
    """
    arguments = list(args)

    if skip_sync is not None:
        raise DeprecationWarning(
            "skip_sync parameter is not supported. The document get synced always using atomic operation."
        )
    use_revision_id = self.get_settings().use_revision

    if self.id is not None:
        find_query: Dict[str, Any] = {"_id": self.id}
    else:
        find_query = {"_id": PydanticObjectId()}

    if use_revision_id and not ignore_revision:
        find_query["revision_id"] = self.revision_id

    if use_revision_id:
        new_revision_id = uuid4()
        arguments.append(SetRevisionId(new_revision_id))
    try:
      result = await self.find_one(find_query).update(
            *arguments,
            session=session,
            response_type=UpdateResponse.NEW_DOCUMENT,
            bulk_writer=bulk_writer,
            **pymongo_kwargs,
        )

/home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/documents.py:662:


/home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/queries/update.py:351: in await update_result = yield from self._update().await() /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/queries/update.py:319: in _update result = await self.document_model.get_motor_collection().find_one_and_update( /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/mongomock_motor/init.py:31: in wrapper return getattr(proxy_source, method_name)(*args, **kwargs) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/mongomock/collection.py:1309: in find_one_and_update return self._find_and_modify(filter, projection, update, upsert, /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/mongomock/collection.py:1349: in _find_and_modify updated = self._update(query, update, upsert) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/mongomock/collection.py:892: in _update upserted_id = self._insert(existing_document)


data = OrderedDict([('_id', '36'), ('revision_id', Binary(b"\xa0Q\xb1V?\xceJ\x84\x92\xd8\xf1\xd3\xfd'\xc3U", 4)), ('created_a..., ('external_id', 'kjdvqxmfejcvHlaFvhlG'), ('last_appeal_token_at', datetime.datetime(2024, 2, 22, 2, 6, 36, 767000))]) args = (), kwargs = {}

@wraps(fn)
def wrapper(data, *args, **kwargs):
    try:
        return fn(data, *args, **kwargs)
    except DuplicateKeyError as exc:
      raise _provide_error_details(collection, data, exc)

E pymongo.errors.DuplicateKeyError: E11000 Duplicate Key Error, full error: {'keyValue': {'external_id': 'kjdvqxmfejcvHlaFvhlG'}, 'keyPattern': {'external_id': 1}}

/home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/mongomock_motor/patches.py:58: DuplicateKeyError

During handling of the above exception, another exception occurred:

auth_client_api_key = <starlette.testclient.TestClient object at 0x7f0604d04190> session = Session(id='GNfLujMGQdWngpYjtThE', revision_id=UUID('a0f34b40-24c2-4a36-8cb4-21ffc0e058b4'), created_at=datetime.datet...status_event_at=None, sync_info=None, qrcode_info=None, finish_info='a3ac571b', channel=<Channel.WHATSAPP: 'whatsapp'>) new_post_session_status_history = PostSessionStatusHistory(event_type=<SessionStatusEventType.APPEAL_TOKEN: 'appeal_token'>, event={})

async def test_post_session_status_history_success(
    auth_client_api_key: TestClient,
    session,
    new_post_session_status_history: PostSessionStatusHistory,
):
    await MachineFactory.create_async(id=session.machine_id)

    sessions_history = await SessionStatusHistory.find_all().to_list()
    assert len(sessions_history) == 0
  response = auth_client_api_key.post(
        f"/api/v1/drivers/sessions/{session.id}/status-history", json=new_post_session_status_history.model_dump()
    )

tests/drivers/test_api.py:426:


/home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/testclient.py:590: in post return super().post( /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/httpx/_client.py:1132: in post return self.request( /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/testclient.py:465: in request return super().request( /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/httpx/_client.py:814: in request return self.send(request, auth=auth, follow_redirects=follow_redirects) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/httpx/_client.py:901: in send response = self._send_handling_auth( /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/httpx/_client.py:929: in _send_handling_auth response = self._send_handling_redirects( /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/httpx/_client.py:966: in _send_handling_redirects response = self._send_single_request(request) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/httpx/_client.py:1002: in _send_single_request response = transport.handle_request(request) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/testclient.py:342: in handle_request raise exc /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/testclient.py:339: in handle_request portal.call(self.app, scope, receive, send) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/anyio/from_thread.py:277: in call return cast(T_Retval, self.start_task_soon(func, *args).result()) /home/matheus/.pyenv/versions/3.11.5/lib/python3.11/concurrent/futures/_base.py:456: in result return self.__get_result() /home/matheus/.pyenv/versions/3.11.5/lib/python3.11/concurrent/futures/_base.py:401: in __get_result raise self._exception /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/anyio/from_thread.py:217: in _call_func retval = await retval /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/fastapi/applications.py:292: in call await super().call(scope, receive, send) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/applications.py:122: in call await self.middleware_stack(scope, receive, send) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/middleware/errors.py:184: in call raise exc /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/middleware/errors.py:162: in call await self.app(scope, receive, _send) src/middlewares/correlation_id/middleware.py:91: in call await self.app(scope, receive, handle_outgoing_request) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/middleware/cors.py:83: in call await self.app(scope, receive, send) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/middleware/exceptions.py:79: in call raise exc /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/middleware/exceptions.py:68: in call await self.app(scope, receive, sender) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/fastapi/middleware/asyncexitstack.py:20: in call raise e /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/fastapi/middleware/asyncexitstack.py:17: in call await self.app(scope, receive, send) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/routing.py:718: in call await route.handle(scope, receive, send) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/routing.py:276: in handle await self.app(scope, receive, send) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/starlette/routing.py:66: in app response = await func(request) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/fastapi/routing.py:273: in app raw_response = await run_endpoint_function( /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/fastapi/routing.py:190: in run_endpoint_function return await dependant.call(**values) src/apps/drivers/api.py:251: in post_session_status_history await machine.save() /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/actions.py:219: in wrapper result = await f(self, *args, skip_actions=skip_actions, **kwargs) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/utils/state.py:66: in wrapper result = await f(self, *args, **kwargs) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/utils/self_validation.py:12: in wrapper return await f(self, *args, **kwargs) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/documents.py:545: in save return await self.update( /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/actions.py:219: in wrapper result = await f(self, *args, skip_actions=skip_actions, **kwargs) /home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/utils/state.py:66: in wrapper result = await f(self, *args, **kwargs)


self = Machine(id='36', revision_id=None, created_at=datetime.datetime(2017, 3, 5, 9, 19, 7, 719000), updated_at=datetime.dat...46, 791000), external_id='kjdvqxmfejcvHlaFvhlG', last_appeal_token_at=datetime.datetime(2024, 2, 22, 2, 6, 36, 767415)) ignore_revision = False, session = None, bulk_writer = None, skip_actions = [] skip_sync = None args = ({'$set': {'_id': '36', 'revision_id': UUID('a051b156-3fce-4a84-92d8-f1d3fd27c355'), 'created_at': datetime.datetime(2...0), 'external_id': 'kjdvqxmfejcvHlaFvhlG', 'last_appeal_token_at': datetime.datetime(2024, 2, 22, 2, 6, 36, 767415)}},) pymongo_kwargs = {'upsert': True} arguments = [{'$set': {'_id': '36', 'revision_id': UUID('a051b156-3fce-4a84-92d8-f1d3fd27c355'), 'created_at': datetime.datetime(2...atetime(2024, 2, 22, 2, 6, 36, 767415)}}, <beanie.odm.operators.update.general.SetRevisionId object at 0x7f0604aebe50>] use_revision_id = True, find_query = {'_id': '36', 'revision_id': None} new_revision_id = UUID('a051b156-3fce-4a84-92d8-f1d3fd27c355')

@wrap_with_actions(EventTypes.UPDATE)
@save_state_after
async def update(
    self,
    *args,
    ignore_revision: bool = False,
    session: Optional[ClientSession] = None,
    bulk_writer: Optional[BulkWriter] = None,
    skip_actions: Optional[List[Union[ActionDirections, str]]] = None,
    skip_sync: Optional[bool] = None,
    **pymongo_kwargs,
) -> DocType:
    """
    Partially update the document in the database

    :param args: *Union[dict, Mapping] - the modifications to apply.
    :param session: ClientSession - pymongo session.
    :param ignore_revision: bool - force update. Will update even if revision id is not the same, as stored
    :param bulk_writer: "BulkWriter" - Beanie bulk writer
    :param pymongo_kwargs: pymongo native parameters for update operation
    :return: None
    """
    arguments = list(args)

    if skip_sync is not None:
        raise DeprecationWarning(
            "skip_sync parameter is not supported. The document get synced always using atomic operation."
        )
    use_revision_id = self.get_settings().use_revision

    if self.id is not None:
        find_query: Dict[str, Any] = {"_id": self.id}
    else:
        find_query = {"_id": PydanticObjectId()}

    if use_revision_id and not ignore_revision:
        find_query["revision_id"] = self.revision_id

    if use_revision_id:
        new_revision_id = uuid4()
        arguments.append(SetRevisionId(new_revision_id))
    try:
        result = await self.find_one(find_query).update(
            *arguments,
            session=session,
            response_type=UpdateResponse.NEW_DOCUMENT,
            bulk_writer=bulk_writer,
            **pymongo_kwargs,
        )
    except DuplicateKeyError:
      raise RevisionIdWasChanged

E beanie.exceptions.RevisionIdWasChanged

/home/matheus/.cache/pypoetry/virtualenvs/cz-coordinator-api-Lp1F0DE3-py3.11/lib/python3.11/site-packages/beanie/odm/documents.py:670: RevisionIdWasChanged =========================== short test summary info ============================ FAILED tests/drivers/test_api.py::test_post_session_status_history_success - ... ============================== 1 failed in 1.34s ===============================

mamazinho avatar Feb 22 '24 02:02 mamazinho

Hi! Thank you for the catch! Could you please provide a minimal executable example module that I can run and see the problem. It will help me to fix the error much faster.

roman-right avatar Feb 26 '24 22:02 roman-right

Hi, I came here after my code raised RevisionIdWasChanged error when I tried to create a document with the same value on a unique index field. I wonder why RevisionIdWasChanged is raised upon a DuplicateKeyError. Can any of you explain this?

How should I distinct that what should I handle then?

Cheers!

martincpt avatar Mar 21 '24 11:03 martincpt

@roman-right I don't want to open another issue but could you please explain why is this behaviour implemented? Can't we just let the original DuplicateKeyError to be raised on an actual duplicate key error?

martincpt avatar Apr 18 '24 08:04 martincpt

@roman-right I don't want to open another issue but could you please explain why is this behaviour implemented? Can't we just let the original DuplicateKeyError to be raised on an actual duplicate key error?

I have the same question. Not sure if this is the intended behavior

coneillpj avatar Apr 22 '24 19:04 coneillpj

Problem:

  • When you try to create 2 documents with the same value on the unique field, beanie raises RevisionIdWasChanged exception instead of DuplicateKeyError.
  • This happens because save() was called. Since save() will try to update the document if it's already there, it will raise the RevisionIdWasChanged exception due to the unique constraint, as can be seen from the source code.

Solution:

  • Instead of using save(), use insert(), then you will get the DuplicateKeyError when the unique constraint is violated.

tdoan2010 avatar May 15 '24 14:05 tdoan2010

@tdoan2010 Interesting. However, what should we use then when we updating an entry?

martincpt avatar May 16 '24 09:05 martincpt

@martincpt in that case, just call .save(). It won't throw the error when we update a document and the unique constraint is not violated. It works as expected in my application.

tdoan2010 avatar May 17 '24 13:05 tdoan2010

@tdoan2010 .save() causes RevisionIdWasChanged exception instead of DuplicateKeyError as well, it's because, .save() uses .update() as well, but, there is another problem, I have a pre-lookup with custom conditions to check if the record exists and the update methods also does this, In this case I have two searches after the update and it is not good for performance.

RempelOliveira avatar May 17 '24 18:05 RempelOliveira

@RempelOliveira yes, but only if you call .save() to create a document.

In my case, I called .insert() for creation and .save() for update. By doing so, I didn't get the RevisionIdWasChanged exception.

tdoan2010 avatar May 21 '24 09:05 tdoan2010

@tdoan2010

For me the exception also occurs when updating. Please share your code so we can see why the exception wasn't thrown for you?!

RempelOliveira avatar Jun 23 '24 18:06 RempelOliveira

Same issue here.

https://github.com/BeanieODM/beanie/issues/833

This one has a reproducible snippet.

RamonGiovane avatar Jul 12 '24 18:07 RamonGiovane

I'm having this issue as well

trycoast avatar Jul 22 '24 10:07 trycoast