diff --git a/test/asynchronous/test_logger.py b/test/asynchronous/test_logger.py index 55379a9faa..94a78b5170 100644 --- a/test/asynchronous/test_logger.py +++ b/test/asynchronous/test_logger.py @@ -18,7 +18,7 @@ from bson import json_util from pymongo.errors import OperationFailure -from pymongo.logger import _DEFAULT_DOCUMENT_LENGTH +from pymongo.logger import _DEFAULT_DOCUMENT_LENGTH, _CommandStatusMessage from test import unittest from test.asynchronous import AsyncIntegrationTest, async_client_context @@ -27,6 +27,15 @@ # https://github.com/mongodb/specifications/tree/master/source/command-logging-and-monitoring/tests#prose-tests class TestLogger(AsyncIntegrationTest): + def _get_command_log(self, records, command_name, status): + # PyPy's GC is non-deterministic, so cleanup commands from earlier tests can pollute the logs, + # filter for the specific command and status we want + for record in records: + log = json_util.loads(record.getMessage()) + if log.get("commandName") == command_name and log.get("message") == status: + return log + self.fail(f"no {status!r} log found for command {command_name!r}") + async def test_default_truncation_limit(self): docs = [{"x": "y"} for _ in range(100)] db = self.db @@ -36,15 +45,21 @@ async def test_default_truncation_limit(self): with self.assertLogs("pymongo.command", level="DEBUG") as cm: await db.test.insert_many(docs) - cmd_started_log = json_util.loads(cm.records[0].getMessage()) + cmd_started_log = self._get_command_log( + cm.records, "insert", _CommandStatusMessage.STARTED + ) self.assertEqual(len(cmd_started_log["command"]), _DEFAULT_DOCUMENT_LENGTH + 3) - cmd_succeeded_log = json_util.loads(cm.records[1].getMessage()) + cmd_succeeded_log = self._get_command_log( + cm.records, "insert", _CommandStatusMessage.SUCCEEDED + ) self.assertLessEqual(len(cmd_succeeded_log["reply"]), _DEFAULT_DOCUMENT_LENGTH + 3) with self.assertLogs("pymongo.command", level="DEBUG") as cm: await db.test.find({}).to_list() - cmd_succeeded_log = json_util.loads(cm.records[1].getMessage()) + cmd_succeeded_log = self._get_command_log( + cm.records, "find", _CommandStatusMessage.SUCCEEDED + ) self.assertEqual(len(cmd_succeeded_log["reply"]), _DEFAULT_DOCUMENT_LENGTH + 3) async def test_configured_truncation_limit(self): @@ -54,14 +69,20 @@ async def test_configured_truncation_limit(self): with self.assertLogs("pymongo.command", level="DEBUG") as cm: await db.command(cmd) - cmd_started_log = json_util.loads(cm.records[0].getMessage()) + cmd_started_log = self._get_command_log( + cm.records, "hello", _CommandStatusMessage.STARTED + ) self.assertEqual(len(cmd_started_log["command"]), 5 + 3) - cmd_succeeded_log = json_util.loads(cm.records[1].getMessage()) + cmd_succeeded_log = self._get_command_log( + cm.records, "hello", _CommandStatusMessage.SUCCEEDED + ) self.assertLessEqual(len(cmd_succeeded_log["reply"]), 5 + 3) with self.assertRaises(OperationFailure): await db.command({"notARealCommand": True}) - cmd_failed_log = json_util.loads(cm.records[-1].getMessage()) + cmd_failed_log = self._get_command_log( + cm.records, "notARealCommand", _CommandStatusMessage.FAILED + ) self.assertEqual(len(cmd_failed_log["failure"]), 5 + 3) async def test_truncation_multi_byte_codepoints(self): @@ -77,7 +98,9 @@ async def test_truncation_multi_byte_codepoints(self): with patch.dict("os.environ", {"MONGOB_LOG_MAX_DOCUMENT_LENGTH": length}): with self.assertLogs("pymongo.command", level="DEBUG") as cm: await self.db.test.insert_one({"x": multi_byte_char_str}) - cmd_started_log = json_util.loads(cm.records[0].getMessage())["command"] + cmd_started_log = self._get_command_log( + cm.records, "insert", _CommandStatusMessage.STARTED + )["command"] cmd_started_log = cmd_started_log[:-3] last_3_bytes = cmd_started_log.encode()[-3:].decode() diff --git a/test/test_logger.py b/test/test_logger.py index aec1167c26..c7a4058d7b 100644 --- a/test/test_logger.py +++ b/test/test_logger.py @@ -18,7 +18,7 @@ from bson import json_util from pymongo.errors import OperationFailure -from pymongo.logger import _DEFAULT_DOCUMENT_LENGTH +from pymongo.logger import _DEFAULT_DOCUMENT_LENGTH, _CommandStatusMessage from test import IntegrationTest, client_context, unittest _IS_SYNC = True @@ -26,6 +26,15 @@ # https://github.com/mongodb/specifications/tree/master/source/command-logging-and-monitoring/tests#prose-tests class TestLogger(IntegrationTest): + def _get_command_log(self, records, command_name, status): + # PyPy's GC is non-deterministic, so cleanup commands from earlier tests can pollute the logs, + # filter for the specific command and status we want + for record in records: + log = json_util.loads(record.getMessage()) + if log.get("commandName") == command_name and log.get("message") == status: + return log + self.fail(f"no {status!r} log found for command {command_name!r}") + def test_default_truncation_limit(self): docs = [{"x": "y"} for _ in range(100)] db = self.db @@ -35,15 +44,21 @@ def test_default_truncation_limit(self): with self.assertLogs("pymongo.command", level="DEBUG") as cm: db.test.insert_many(docs) - cmd_started_log = json_util.loads(cm.records[0].getMessage()) + cmd_started_log = self._get_command_log( + cm.records, "insert", _CommandStatusMessage.STARTED + ) self.assertEqual(len(cmd_started_log["command"]), _DEFAULT_DOCUMENT_LENGTH + 3) - cmd_succeeded_log = json_util.loads(cm.records[1].getMessage()) + cmd_succeeded_log = self._get_command_log( + cm.records, "insert", _CommandStatusMessage.SUCCEEDED + ) self.assertLessEqual(len(cmd_succeeded_log["reply"]), _DEFAULT_DOCUMENT_LENGTH + 3) with self.assertLogs("pymongo.command", level="DEBUG") as cm: db.test.find({}).to_list() - cmd_succeeded_log = json_util.loads(cm.records[1].getMessage()) + cmd_succeeded_log = self._get_command_log( + cm.records, "find", _CommandStatusMessage.SUCCEEDED + ) self.assertEqual(len(cmd_succeeded_log["reply"]), _DEFAULT_DOCUMENT_LENGTH + 3) def test_configured_truncation_limit(self): @@ -53,14 +68,20 @@ def test_configured_truncation_limit(self): with self.assertLogs("pymongo.command", level="DEBUG") as cm: db.command(cmd) - cmd_started_log = json_util.loads(cm.records[0].getMessage()) + cmd_started_log = self._get_command_log( + cm.records, "hello", _CommandStatusMessage.STARTED + ) self.assertEqual(len(cmd_started_log["command"]), 5 + 3) - cmd_succeeded_log = json_util.loads(cm.records[1].getMessage()) + cmd_succeeded_log = self._get_command_log( + cm.records, "hello", _CommandStatusMessage.SUCCEEDED + ) self.assertLessEqual(len(cmd_succeeded_log["reply"]), 5 + 3) with self.assertRaises(OperationFailure): db.command({"notARealCommand": True}) - cmd_failed_log = json_util.loads(cm.records[-1].getMessage()) + cmd_failed_log = self._get_command_log( + cm.records, "notARealCommand", _CommandStatusMessage.FAILED + ) self.assertEqual(len(cmd_failed_log["failure"]), 5 + 3) def test_truncation_multi_byte_codepoints(self): @@ -76,7 +97,9 @@ def test_truncation_multi_byte_codepoints(self): with patch.dict("os.environ", {"MONGOB_LOG_MAX_DOCUMENT_LENGTH": length}): with self.assertLogs("pymongo.command", level="DEBUG") as cm: self.db.test.insert_one({"x": multi_byte_char_str}) - cmd_started_log = json_util.loads(cm.records[0].getMessage())["command"] + cmd_started_log = self._get_command_log( + cm.records, "insert", _CommandStatusMessage.STARTED + )["command"] cmd_started_log = cmd_started_log[:-3] last_3_bytes = cmd_started_log.encode()[-3:].decode()