Skip to content

Commit c1748a9

Browse files
NoahStappNoahStapp
authored
PYTHON-5905 - Make logging tests not fail due to PyPy GC issues (#2934)
1 parent c1e9937 commit c1748a9

2 files changed

Lines changed: 62 additions & 16 deletions

File tree

‎test/asynchronous/test_logger.py‎

Lines changed: 31 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -18,7 +18,7 @@
1818

1919
from bson import json_util
2020
from pymongo.errors import OperationFailure
21-
from pymongo.logger import _DEFAULT_DOCUMENT_LENGTH
21+
from pymongo.logger import _DEFAULT_DOCUMENT_LENGTH, _CommandStatusMessage
2222
from test import unittest
2323
from test.asynchronous import AsyncIntegrationTest, async_client_context
2424

@@ -27,6 +27,15 @@
2727

2828
# https://github.com/mongodb/specifications/tree/master/source/command-logging-and-monitoring/tests#prose-tests
2929
class TestLogger(AsyncIntegrationTest):
30+
def _get_command_log(self, records, command_name, status):
31+
# PyPy's GC is non-deterministic, so cleanup commands from earlier tests can pollute the logs,
32+
# filter for the specific command and status we want
33+
for record in records:
34+
log = json_util.loads(record.getMessage())
35+
if log.get("commandName") == command_name and log.get("message") == status:
36+
return log
37+
self.fail(f"no {status!r} log found for command {command_name!r}")
38+
3039
async def test_default_truncation_limit(self):
3140
docs = [{"x": "y"} for _ in range(100)]
3241
db = self.db
@@ -36,15 +45,21 @@ async def test_default_truncation_limit(self):
3645
with self.assertLogs("pymongo.command", level="DEBUG") as cm:
3746
await db.test.insert_many(docs)
3847

39-
cmd_started_log = json_util.loads(cm.records[0].getMessage())
48+
cmd_started_log = self._get_command_log(
49+
cm.records, "insert", _CommandStatusMessage.STARTED
50+
)
4051
self.assertEqual(len(cmd_started_log["command"]), _DEFAULT_DOCUMENT_LENGTH + 3)
4152

42-
cmd_succeeded_log = json_util.loads(cm.records[1].getMessage())
53+
cmd_succeeded_log = self._get_command_log(
54+
cm.records, "insert", _CommandStatusMessage.SUCCEEDED
55+
)
4356
self.assertLessEqual(len(cmd_succeeded_log["reply"]), _DEFAULT_DOCUMENT_LENGTH + 3)
4457

4558
with self.assertLogs("pymongo.command", level="DEBUG") as cm:
4659
await db.test.find({}).to_list()
47-
cmd_succeeded_log = json_util.loads(cm.records[1].getMessage())
60+
cmd_succeeded_log = self._get_command_log(
61+
cm.records, "find", _CommandStatusMessage.SUCCEEDED
62+
)
4863
self.assertEqual(len(cmd_succeeded_log["reply"]), _DEFAULT_DOCUMENT_LENGTH + 3)
4964

5065
async def test_configured_truncation_limit(self):
@@ -54,14 +69,20 @@ async def test_configured_truncation_limit(self):
5469
with self.assertLogs("pymongo.command", level="DEBUG") as cm:
5570
await db.command(cmd)
5671

57-
cmd_started_log = json_util.loads(cm.records[0].getMessage())
72+
cmd_started_log = self._get_command_log(
73+
cm.records, "hello", _CommandStatusMessage.STARTED
74+
)
5875
self.assertEqual(len(cmd_started_log["command"]), 5 + 3)
5976

60-
cmd_succeeded_log = json_util.loads(cm.records[1].getMessage())
77+
cmd_succeeded_log = self._get_command_log(
78+
cm.records, "hello", _CommandStatusMessage.SUCCEEDED
79+
)
6180
self.assertLessEqual(len(cmd_succeeded_log["reply"]), 5 + 3)
6281
with self.assertRaises(OperationFailure):
6382
await db.command({"notARealCommand": True})
64-
cmd_failed_log = json_util.loads(cm.records[-1].getMessage())
83+
cmd_failed_log = self._get_command_log(
84+
cm.records, "notARealCommand", _CommandStatusMessage.FAILED
85+
)
6586
self.assertEqual(len(cmd_failed_log["failure"]), 5 + 3)
6687

6788
async def test_truncation_multi_byte_codepoints(self):
@@ -77,7 +98,9 @@ async def test_truncation_multi_byte_codepoints(self):
7798
with patch.dict("os.environ", {"MONGOB_LOG_MAX_DOCUMENT_LENGTH": length}):
7899
with self.assertLogs("pymongo.command", level="DEBUG") as cm:
79100
await self.db.test.insert_one({"x": multi_byte_char_str})
80-
cmd_started_log = json_util.loads(cm.records[0].getMessage())["command"]
101+
cmd_started_log = self._get_command_log(
102+
cm.records, "insert", _CommandStatusMessage.STARTED
103+
)["command"]
81104

82105
cmd_started_log = cmd_started_log[:-3]
83106
last_3_bytes = cmd_started_log.encode()[-3:].decode()

‎test/test_logger.py‎

Lines changed: 31 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -18,14 +18,23 @@
1818

1919
from bson import json_util
2020
from pymongo.errors import OperationFailure
21-
from pymongo.logger import _DEFAULT_DOCUMENT_LENGTH
21+
from pymongo.logger import _DEFAULT_DOCUMENT_LENGTH, _CommandStatusMessage
2222
from test import IntegrationTest, client_context, unittest
2323

2424
_IS_SYNC = True
2525

2626

2727
# https://github.com/mongodb/specifications/tree/master/source/command-logging-and-monitoring/tests#prose-tests
2828
class TestLogger(IntegrationTest):
29+
def _get_command_log(self, records, command_name, status):
30+
# PyPy's GC is non-deterministic, so cleanup commands from earlier tests can pollute the logs,
31+
# filter for the specific command and status we want
32+
for record in records:
33+
log = json_util.loads(record.getMessage())
34+
if log.get("commandName") == command_name and log.get("message") == status:
35+
return log
36+
self.fail(f"no {status!r} log found for command {command_name!r}")
37+
2938
def test_default_truncation_limit(self):
3039
docs = [{"x": "y"} for _ in range(100)]
3140
db = self.db
@@ -35,15 +44,21 @@ def test_default_truncation_limit(self):
3544
with self.assertLogs("pymongo.command", level="DEBUG") as cm:
3645
db.test.insert_many(docs)
3746

38-
cmd_started_log = json_util.loads(cm.records[0].getMessage())
47+
cmd_started_log = self._get_command_log(
48+
cm.records, "insert", _CommandStatusMessage.STARTED
49+
)
3950
self.assertEqual(len(cmd_started_log["command"]), _DEFAULT_DOCUMENT_LENGTH + 3)
4051

41-
cmd_succeeded_log = json_util.loads(cm.records[1].getMessage())
52+
cmd_succeeded_log = self._get_command_log(
53+
cm.records, "insert", _CommandStatusMessage.SUCCEEDED
54+
)
4255
self.assertLessEqual(len(cmd_succeeded_log["reply"]), _DEFAULT_DOCUMENT_LENGTH + 3)
4356

4457
with self.assertLogs("pymongo.command", level="DEBUG") as cm:
4558
db.test.find({}).to_list()
46-
cmd_succeeded_log = json_util.loads(cm.records[1].getMessage())
59+
cmd_succeeded_log = self._get_command_log(
60+
cm.records, "find", _CommandStatusMessage.SUCCEEDED
61+
)
4762
self.assertEqual(len(cmd_succeeded_log["reply"]), _DEFAULT_DOCUMENT_LENGTH + 3)
4863

4964
def test_configured_truncation_limit(self):
@@ -53,14 +68,20 @@ def test_configured_truncation_limit(self):
5368
with self.assertLogs("pymongo.command", level="DEBUG") as cm:
5469
db.command(cmd)
5570

56-
cmd_started_log = json_util.loads(cm.records[0].getMessage())
71+
cmd_started_log = self._get_command_log(
72+
cm.records, "hello", _CommandStatusMessage.STARTED
73+
)
5774
self.assertEqual(len(cmd_started_log["command"]), 5 + 3)
5875

59-
cmd_succeeded_log = json_util.loads(cm.records[1].getMessage())
76+
cmd_succeeded_log = self._get_command_log(
77+
cm.records, "hello", _CommandStatusMessage.SUCCEEDED
78+
)
6079
self.assertLessEqual(len(cmd_succeeded_log["reply"]), 5 + 3)
6180
with self.assertRaises(OperationFailure):
6281
db.command({"notARealCommand": True})
63-
cmd_failed_log = json_util.loads(cm.records[-1].getMessage())
82+
cmd_failed_log = self._get_command_log(
83+
cm.records, "notARealCommand", _CommandStatusMessage.FAILED
84+
)
6485
self.assertEqual(len(cmd_failed_log["failure"]), 5 + 3)
6586

6687
def test_truncation_multi_byte_codepoints(self):
@@ -76,7 +97,9 @@ def test_truncation_multi_byte_codepoints(self):
7697
with patch.dict("os.environ", {"MONGOB_LOG_MAX_DOCUMENT_LENGTH": length}):
7798
with self.assertLogs("pymongo.command", level="DEBUG") as cm:
7899
self.db.test.insert_one({"x": multi_byte_char_str})
79-
cmd_started_log = json_util.loads(cm.records[0].getMessage())["command"]
100+
cmd_started_log = self._get_command_log(
101+
cm.records, "insert", _CommandStatusMessage.STARTED
102+
)["command"]
80103

81104
cmd_started_log = cmd_started_log[:-3]
82105
last_3_bytes = cmd_started_log.encode()[-3:].decode()

0 commit comments

Comments
 (0)