Uploaded image for project: 'Python Driver'
  1. Python Driver
  2. PYTHON-4303

[Build Failure] test_withTransaction_commits_after_callback_returns

XMLWordPrintableJSON

    • Type: Icon: Build Failure Build Failure
    • Resolution: Duplicate
    • Priority: Icon: Unknown Unknown
    • None
    • Affects Version/s: None
    • Component/s: None
    • None
    • Python Drivers
    • Hide

      1. What would you like to communicate to the user about this feature?
      2. Would you like the user to see examples of the syntax and/or executable code and its output?
      3. Which versions of the driver/connector does this apply to?

      Show
      1. What would you like to communicate to the user about this feature? 2. Would you like the user to see examples of the syntax and/or executable code and its output? 3. Which versions of the driver/connector does this apply to?

      Name of Failure:

      test.test_transactions_unified.TestUnifiedCommit.test_withTransaction_commits_after_callback_returns
      test.test_transactions_unified.TestUnifiedMongosUnpin.test_unpin_on_successful_abort

      Link to task:

      https://spruce.mongodb.com/task/mongo_python_driver_tests_python_version_rhel8_test_ssl__platform~rhel8_auth_ssl~auth_ssl_python_version~3.10_coverage~coverage_test_4.4_sharded_cluster_patch_e37394d4029d61f72a02dc465fbfc9afe35a5701_6603f6f01bb01200075356ba_24_03_27_10_37_38?execution=1&sortBy=STATUS&sortDir=ASC

      https://spruce.mongodb.com/task/mongo_python_driver_tests_python_version_rhel8_test_ssl__platform~rhel8_auth_ssl~auth_ssl_python_version~3.10_coverage~coverage_test_latest_sharded_cluster_patch_e37394d4029d61f72a02dc465fbfc9afe35a5701_6603f6f01bb01200075356ba_24_03_27_10_37_38?execution=1&sortBy=STATUS&sortDir=ASC

      Context of when and why the failure occurred:

      PYTHON-2723

      Stack trace:

       [2024/03/27 06:32:48.309] FAILURE: AssertionError: 5 != 3 : [<CommandStartedEvent ('localhost', 27018) db: 'withTransaction-tests', command: 'insert', operation_id: 784405532, service_id: None, server_connection_id: 479>, <CommandStartedEvent ('localhost', 27017) db: 'admin', command: 'abortTransaction', operation_id: 1124368918, service_id: None, server_connection_id: 6472>, <CommandStartedEvent ('localhost', 27017) db: 'withTransaction-tests', command: 'insert', operation_id: 26215234, service_id: None, server_connection_id: 6472>, <CommandStartedEvent ('localhost', 27017) db: 'withTransaction-tests', command: 'insert', operation_id: 1826099754, service_id: None, server_connection_id: 6472>, <CommandStartedEvent ('localhost', 27017) db: 'admin', command: 'commitTransaction', operation_id: 2147054674, service_id: None, server_connection_id: 6472>] ()
 [2024/03/27 06:32:48.309] self = <test.test_transactions_unified.TestUnifiedCommit testMethod=test_withTransaction_commits_after_callback_returns>
 [2024/03/27 06:32:48.309]     def test_case(self):
 [2024/03/27 06:32:48.309] >       self.run_scenario(spec)
 [2024/03/27 06:32:48.309] test/unified_format.py:1909: 
 [2024/03/27 06:32:48.309] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
 [2024/03/27 06:32:48.309] test/unified_format.py:1856: in run_scenario
 [2024/03/27 06:32:48.309]     self._run_scenario(spec, uri)
 [2024/03/27 06:32:48.309] test/unified_format.py:1892: in _run_scenario
 [2024/03/27 06:32:48.309]     self.check_events(expect_events)
 [2024/03/27 06:32:48.309] test/unified_format.py:1761: in check_events
 [2024/03/27 06:32:48.309]     self.assertEqual(len(actual_events), len(events), actual_events)
 [2024/03/27 06:32:48.309] E   AssertionError: 5 != 3 : [<CommandStartedEvent ('localhost', 27018) db: 'withTransaction-tests', command: 'insert', operation_id: 784405532, service_id: None, server_connection_id: 479>, <CommandStartedEvent ('localhost', 27017) db: 'admin', command: 'abortTransaction', operation_id: 1124368918, service_id: None, server_connection_id: 6472>, <CommandStartedEvent ('localhost', 27017) db: 'withTransaction-tests', command: 'insert', operation_id: 26215234, service_id: None, server_connection_id: 6472>, <CommandStartedEvent ('localhost', 27017) db: 'withTransaction-tests', command: 'insert', operation_id: 1826099754, service_id: None, server_connection_id: 6472>, <CommandStartedEvent ('localhost', 27017) db: 'admin', command: 'commitTransaction', operation_id: 2147054674, service_id: None, server_connection_id: 6472>]

       [2024/03/27 06:37:03.212] FAILURE: pymongo.errors.OperationFailure: Transaction 48c13666-d7a2-442b-a7c9-18848b93a4d8 - Il1bctjvfYRA0JpLUY4Xle2E6bw+KM1YpMr4x52qGgE= -  - :1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27217 during a transaction :: caused by :: Database mongos-unpin-db has undergone a catalog change operation at time Timestamp(1711539054, 147) and no longer satisfies the requirements for the current transaction which requires Timestamp(1711539054, 146). Transaction will be aborted., full error: {'ok': 0.0, 'errmsg': 'Transaction 48c13666-d7a2-442b-a7c9-18848b93a4d8 - Il1bctjvfYRA0JpLUY4Xle2E6bw+KM1YpMr4x52qGgE= -  - :1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27217 during a transaction :: caused by :: Database mongos-unpin-db has undergone a catalog change operation at time Timestamp(1711539054, 147) and no longer satisfies the requirements for the current transaction which requires Timestamp(1711539054, 146). Transaction will be aborted.', 'code': 272, 'codeName': 'MigrationConflict', '$clusterTime': {'clusterTime': Timestamp(1711539054, 156), 'signature': {'hash': b'\x15$i\xc1\xa0v\xb8:\x04T\xe5\xa4@:\xd7\xedFx`s', 'keyId': 7351000027919024152}}, 'operationTime': Timestamp(1711539054, 156), 'errorLabels': ['TransientTransactionError']} ()
 [2024/03/27 06:37:03.212] self = <test.test_transactions_unified.TestUnifiedMongosUnpin testMethod=test_unpin_on_successful_abort>
 [2024/03/27 06:37:03.212]     def test_case(self):
 [2024/03/27 06:37:03.212] >       self.run_scenario(spec)
 [2024/03/27 06:37:03.212] test/unified_format.py:1909: 
 [2024/03/27 06:37:03.212] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
 [2024/03/27 06:37:03.212] test/unified_format.py:1856: in run_scenario
 [2024/03/27 06:37:03.212]     self._run_scenario(spec, uri)
 [2024/03/27 06:37:03.212] test/unified_format.py:1886: in _run_scenario
 [2024/03/27 06:37:03.212]     self.run_operations(spec["operations"])
 [2024/03/27 06:37:03.212] test/unified_format.py:1733: in run_operations
 [2024/03/27 06:37:03.212]     self.run_entity_operation(op)
 [2024/03/27 06:37:03.212] test/unified_format.py:1475: in run_entity_operation
 [2024/03/27 06:37:03.212]     result = cmd(**dict(arguments))
 [2024/03/27 06:37:03.212] pymongo/collection.py:659: in insert_one
 [2024/03/27 06:37:03.212]     self._insert_one(
 [2024/03/27 06:37:03.212] pymongo/collection.py:599: in _insert_one
 [2024/03/27 06:37:03.212]     self.__database.client._retryable_write(
 [2024/03/27 06:37:03.212] pymongo/mongo_client.py:1564: in _retryable_write
 [2024/03/27 06:37:03.212]     return self._retry_with_session(retryable, func, s, bulk, operation, operation_id)
 [2024/03/27 06:37:03.212] pymongo/mongo_client.py:1450: in _retry_with_session
 [2024/03/27 06:37:03.212]     return self._retry_internal(
 [2024/03/27 06:37:03.212] pymongo/_csot.py:108: in csot_wrapper
 [2024/03/27 06:37:03.212]     return func(self, *args, **kwargs)
 [2024/03/27 06:37:03.212] pymongo/mongo_client.py:1496: in _retry_internal
 [2024/03/27 06:37:03.212]     ).run()
 [2024/03/27 06:37:03.212] pymongo/mongo_client.py:2342: in run
 [2024/03/27 06:37:03.212]     return self._read() if self._is_read else self._write()
 [2024/03/27 06:37:03.212] pymongo/mongo_client.py:2459: in _write
 [2024/03/27 06:37:03.212]     return self._func(self._session, conn, self._retryable)  # type: ignore
 [2024/03/27 06:37:03.212] pymongo/collection.py:587: in _insert_command
 [2024/03/27 06:37:03.212]     result = conn.command(
 [2024/03/27 06:37:03.212] pymongo/helpers.py:324: in inner
 [2024/03/27 06:37:03.212]     return func(*args, **kwargs)
 [2024/03/27 06:37:03.212] pymongo/pool.py:985: in command
 [2024/03/27 06:37:03.212]     return command(
 [2024/03/27 06:37:03.212] pymongo/network.py:212: in command
 [2024/03/27 06:37:03.212]     helpers._check_command_response(
 [2024/03/27 06:37:03.212] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
 [2024/03/27 06:37:03.212] response = {'$clusterTime': {'clusterTime': Timestamp(1711539054, 156), 'signature': {'hash': b'\x15$i\xc1\xa0v\xb8:\x04T\xe5\xa4...requirements for the current transaction which requires Timestamp(1711539054, 146). Transaction will be aborted.', ...}
 [2024/03/27 06:37:03.212] max_wire_version = 25, allowable_errors = None
 [2024/03/27 06:37:03.212] parse_write_concern_error = False
 [2024/03/27 06:37:03.212]     def _check_command_response(
 [2024/03/27 06:37:03.212]         response: _DocumentOut,
 [2024/03/27 06:37:03.212]         max_wire_version: Optional[int],
 [2024/03/27 06:37:03.212]         allowable_errors: Optional[Container[Union[int, str]]] = None,
 [2024/03/27 06:37:03.212]         parse_write_concern_error: bool = False,
 [2024/03/27 06:37:03.212]     ) -> None:
 [2024/03/27 06:37:03.212]         """Check the response to a command for errors."""
 [2024/03/27 06:37:03.212]         if "ok" not in response:
 [2024/03/27 06:37:03.212]             # Server didn't recognize our message as a command.
 [2024/03/27 06:37:03.212]             raise OperationFailure(
 [2024/03/27 06:37:03.212]                 response.get("$err"),  # type: ignore[arg-type]
 [2024/03/27 06:37:03.212]                 response.get("code"),
 [2024/03/27 06:37:03.212]                 response,
 [2024/03/27 06:37:03.212]                 max_wire_version,
 [2024/03/27 06:37:03.212]             )
 [2024/03/27 06:37:03.212]     
 [2024/03/27 06:37:03.212]         if parse_write_concern_error and "writeConcernError" in response:
 [2024/03/27 06:37:03.212]             _error = response["writeConcernError"]
 [2024/03/27 06:37:03.212]             _labels = response.get("errorLabels")
 [2024/03/27 06:37:03.212]             if _labels:
 [2024/03/27 06:37:03.212]                 _error.update({"errorLabels": _labels})
 [2024/03/27 06:37:03.212]             _raise_write_concern_error(_error)
 [2024/03/27 06:37:03.212]     
 [2024/03/27 06:37:03.212]         if response["ok"]:
 [2024/03/27 06:37:03.212]             return
 [2024/03/27 06:37:03.212]     
 [2024/03/27 06:37:03.212]         details = response
 [2024/03/27 06:37:03.212]         # Mongos returns the error details in a 'raw' object
 [2024/03/27 06:37:03.212]         # for some errors.
 [2024/03/27 06:37:03.212]         if "raw" in response:
 [2024/03/27 06:37:03.212]             for shard in response["raw"].values():
 [2024/03/27 06:37:03.212]                 # Grab the first non-empty raw error from a shard.
 [2024/03/27 06:37:03.212]                 if shard.get("errmsg") and not shard.get("ok"):
 [2024/03/27 06:37:03.212]                     details = shard
 [2024/03/27 06:37:03.212]                     break
 [2024/03/27 06:37:03.212]     
 [2024/03/27 06:37:03.212]         errmsg = details["errmsg"]
 [2024/03/27 06:37:03.212]         code = details.get("code")
 [2024/03/27 06:37:03.212]     
 [2024/03/27 06:37:03.212]         # For allowable errors, only check for error messages when the code is not
 [2024/03/27 06:37:03.212]         # included.
 [2024/03/27 06:37:03.212]         if allowable_errors:
 [2024/03/27 06:37:03.212]             if code is not None:
 [2024/03/27 06:37:03.212]                 if code in allowable_errors:
 [2024/03/27 06:37:03.212]                     return
 [2024/03/27 06:37:03.212]             elif errmsg in allowable_errors:
 [2024/03/27 06:37:03.212]                 return
 [2024/03/27 06:37:03.212]     
 [2024/03/27 06:37:03.212]         # Server is "not primary" or "recovering"
 [2024/03/27 06:37:03.212]         if code is not None:
 [2024/03/27 06:37:03.212]             if code in _NOT_PRIMARY_CODES:
 [2024/03/27 06:37:03.212]                 raise NotPrimaryError(errmsg, response)
 [2024/03/27 06:37:03.212]         elif HelloCompat.LEGACY_ERROR in errmsg or "node is recovering" in errmsg:
 [2024/03/27 06:37:03.212]             raise NotPrimaryError(errmsg, response)
 [2024/03/27 06:37:03.212]     
 [2024/03/27 06:37:03.212]         # Other errors
 [2024/03/27 06:37:03.212]         # findAndModify with upsert can raise duplicate key error
 [2024/03/27 06:37:03.212]         if code in (11000, 11001, 12582):
 [2024/03/27 06:37:03.212]             raise DuplicateKeyError(errmsg, code, response, max_wire_version)
 [2024/03/27 06:37:03.212]         elif code == 50:
 [2024/03/27 06:37:03.212]             raise ExecutionTimeout(errmsg, code, response, max_wire_version)
 [2024/03/27 06:37:03.212]         elif code == 43:
 [2024/03/27 06:37:03.212]             raise CursorNotFound(errmsg, code, response, max_wire_version)
 [2024/03/27 06:37:03.212]     
 [2024/03/27 06:37:03.212] >       raise OperationFailure(errmsg, code, response, max_wire_version)
 [2024/03/27 06:37:03.212] E       pymongo.errors.OperationFailure: Transaction 48c13666-d7a2-442b-a7c9-18848b93a4d8 - Il1bctjvfYRA0JpLUY4Xle2E6bw+KM1YpMr4x52qGgE= -  - :1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27217 during a transaction :: caused by :: Database mongos-unpin-db has undergone a catalog change operation at time Timestamp(1711539054, 147) and no longer satisfies the requirements for the current transaction which requires Timestamp(1711539054, 146). Transaction will be aborted., full error: {'ok': 0.0, 'errmsg': 'Transaction 48c13666-d7a2-442b-a7c9-18848b93a4d8 - Il1bctjvfYRA0JpLUY4Xle2E6bw+KM1YpMr4x52qGgE= -  - :1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27217 during a transaction :: caused by :: Database mongos-unpin-db has undergone a catalog change operation at time Timestamp(1711539054, 147) and no longer satisfies the requirements for the current transaction which requires Timestamp(1711539054, 146). Transaction will be aborted.', 'code': 272, 'codeName': 'MigrationConflict', '$clusterTime': {'clusterTime': Timestamp(1711539054, 156), 'signature': {'hash': b'\x15$i\xc1\xa0v\xb8:\x04T\xe5\xa4@:\xd7\xedFx`s', 'keyId': 7351000027919024152}}, 'operationTime': Timestamp(1711539054, 156), 'errorLabels': ['TransientTransactionError']}
 [2024/03/27 06:37:03.212] pymongo/helpers.py:230: OperationFailure

            Assignee:
            casey.clements@mongodb.com Casey Clements
            Reporter:
            steve.silvester@mongodb.com Steve Silvester
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: