Mercurial > p > roundup > code
comparison test/test_config.py @ 8446:14c7c07b32d8
feature: add thread local trace_id and trace_reason to logging.
Added trace_id to default logging so that all logs for a given request
share the same trace_id.
This allows correlation of logs across a request.
admin_guide.txt, upgrading.txt:
add docs
update sample configs to include trace_id.
rewrite logging docs in admin_guide. Hopefully they are clearer now.
clean up some stuff in the logging config file docs.
admin.py:
add decorators to run_command to enable trace_id.
change calls to db.commit() to use run_command to get trace_id.
configuration.py:
clean up imports.
update docstrings, comments and inline docs.
add trace_id to default log format.
add function for testing decorated with trace_id.
add support for dumping stack trace in logging.
add check for pytest in sys.modules to enable log propagation when
pytest is running. Otherwise tests fail as the caplog logger doesn't
see the roundup logs.
logcontext.py:
new file to handle thread local contextvar mangement.
mailgw.py:
add decorators for trace_id etc.
scripts/roundup_xlmrpc_server.py:
add decorators for trace_id etc.
fix encoding bug turning bytes into a string.
fix command line issue where we can't set encoding. (not sure if
changing encoding via command line even works)
cgi/client.py
decorate two entry points for trace_id etc.
cgi/wsgi_handler.py:
decorate entry point for trace_id etc.
test/test_config.py:
add test for trace_id in new log format.
test various cases for sinfo and errors in formating msg.
| author | John Rouillard <rouilj@ieee.org> |
|---|---|
| date | Tue, 16 Sep 2025 22:53:00 -0400 |
| parents | 39a6825d10ca |
| children | d06be9346c68 |
comparison
equal
deleted
inserted
replaced
| 8445:4b6e9a0e13ee | 8446:14c7c07b32d8 |
|---|---|
| 416 | 416 |
| 417 | 417 |
| 418 @pytest.mark.usefixtures("save_restore_logging") | 418 @pytest.mark.usefixtures("save_restore_logging") |
| 419 class TrackerConfig(unittest.TestCase): | 419 class TrackerConfig(unittest.TestCase): |
| 420 | 420 |
| 421 @pytest.fixture(autouse=True) | |
| 422 def inject_fixtures(self, caplog): | |
| 423 self._caplog = caplog | |
| 424 | |
| 421 @pytest.fixture(scope="class") | 425 @pytest.fixture(scope="class") |
| 422 def save_restore_logging(self): | 426 def save_restore_logging(self): |
| 423 """Save logger state and try to restore it after all tests in | 427 """Save logger state and try to restore it after all tests in |
| 424 this class have finished. | 428 this class have finished. |
| 425 | 429 |
| 1007 config.load(self.dirname) | 1011 config.load(self.dirname) |
| 1008 | 1012 |
| 1009 print(cm.exception) | 1013 print(cm.exception) |
| 1010 self.assertEqual(cm.exception.args[0], self.dirname) | 1014 self.assertEqual(cm.exception.args[0], self.dirname) |
| 1011 | 1015 |
| 1012 | 1016 def testFormattedLogging(self): |
| 1017 """Depends on using default logging format with %(trace_id)""" | |
| 1018 | |
| 1019 def find_file_occurances(string): | |
| 1020 return len(re.findall(r'\bFile\b', string)) | |
| 1021 | |
| 1022 config = configuration.CoreConfig() | |
| 1023 | |
| 1024 config.LOGGING_LEVEL = "DEBUG" | |
| 1025 config.init_logging() | |
| 1026 | |
| 1027 | |
| 1028 # format the record and verify the logformat/trace_id. | |
| 1029 config._logging_test(None, msg="message") | |
| 1030 tuple = self._caplog.record_tuples[0] | |
| 1031 self.assertEqual(tuple[1], 20) | |
| 1032 self.assertEqual("message", tuple[2]) | |
| 1033 logger = logging.getLogger('roundup') | |
| 1034 hdlr = logger.handlers[0] | |
| 1035 log = hdlr.format(self._caplog.records[0]) | |
| 1036 # verify that %(trace_id) was set and substituted | |
| 1037 # Note: trace_id is not initialized in this test case | |
| 1038 log_parts = log.split() | |
| 1039 self.assertRegex(log_parts[2], r'^[A-Za-z0-9]{22}') | |
| 1040 self._caplog.clear() | |
| 1041 | |
| 1042 # the rest check various values of sinfo and msg formating. | |
| 1043 | |
| 1044 # sinfo = 1 - one line of stack starting with log call | |
| 1045 config._logging_test(1) | |
| 1046 tuple = self._caplog.record_tuples[0] | |
| 1047 self.assertEqual(tuple[1], 20) | |
| 1048 self.assertIn("test a_var\n File", tuple[2]) | |
| 1049 self.assertIn("in _logging_test", tuple[2]) | |
| 1050 self.assertIn("logger.info(msg, extra=", tuple[2]) | |
| 1051 self.assertEqual(find_file_occurances(tuple[2]), 1) | |
| 1052 self._caplog.clear() | |
| 1053 | |
| 1054 # sinfo = None - 5 lines of stack starting with log call | |
| 1055 config._logging_test(None) | |
| 1056 tuple = self._caplog.record_tuples[0] | |
| 1057 self.assertEqual(tuple[1], 20) | |
| 1058 self.assertIn("test a_var\n File", tuple[2]) | |
| 1059 self.assertIn("in _logging_test", tuple[2]) | |
| 1060 self.assertIn("logger.info(msg, extra=", tuple[2]) | |
| 1061 self.assertEqual(find_file_occurances(tuple[2]), 5) | |
| 1062 self._caplog.clear() | |
| 1063 | |
| 1064 # sinfo = 0 - whole stack starting with log call | |
| 1065 config._logging_test(0) | |
| 1066 tuple = self._caplog.record_tuples[0] | |
| 1067 self.assertEqual(tuple[1], 20) | |
| 1068 self.assertIn("test a_var\n File", tuple[2]) | |
| 1069 self.assertIn("in _logging_test", tuple[2]) | |
| 1070 self.assertIn("logger.info(msg, extra=", tuple[2]) | |
| 1071 # A file in 'pytest' directory should be at the top of stack. | |
| 1072 self.assertIn("pytest", tuple[2]) | |
| 1073 # no idea how deep the actual stack is, could change with python | |
| 1074 # versions, but 3.12 is 33 so .... | |
| 1075 self.assertTrue(find_file_occurances(tuple[2]) > 10) | |
| 1076 self._caplog.clear() | |
| 1077 | |
| 1078 # sinfo = -1 - one line of stack starting with extract_stack() | |
| 1079 config._logging_test(-1) | |
| 1080 tuple = self._caplog.record_tuples[0] | |
| 1081 self.assertEqual(tuple[1], 20) | |
| 1082 self.assertIn("test a_var\n File", tuple[2]) | |
| 1083 # The call to extract_stack should be included as the frame | |
| 1084 # at bottom of stack. | |
| 1085 self.assertIn("extract_stack()", tuple[2]) | |
| 1086 # only one frame included | |
| 1087 self.assertEqual(find_file_occurances(tuple[2]), 1) | |
| 1088 self._caplog.clear() | |
| 1089 | |
| 1090 # sinfo = 1000 - whole stack starting with log call 1000>stack size | |
| 1091 config._logging_test(1000) | |
| 1092 tuple = self._caplog.record_tuples[0] | |
| 1093 self.assertEqual(tuple[1], 20) | |
| 1094 self.assertIn("test a_var\n File", tuple[2]) | |
| 1095 self.assertIn("in _logging_test", tuple[2]) | |
| 1096 self.assertIn("logger.info(msg, extra=", tuple[2]) | |
| 1097 # A file in 'pytest' directory should be at the top of stack. | |
| 1098 self.assertIn("pytest", tuple[2]) | |
| 1099 # no idea how deep the actual stack is, could change with python | |
| 1100 # versions, but 3.12 is 33 so .... | |
| 1101 self.assertTrue(find_file_occurances(tuple[2]) > 10) | |
| 1102 self._caplog.clear() | |
| 1103 | |
| 1104 # sinfo = -1000 - whole stack starting with extract_stack | |
| 1105 config._logging_test(-1000) | |
| 1106 tuple = self._caplog.record_tuples[0] | |
| 1107 self.assertEqual(tuple[1], 20) | |
| 1108 self.assertIn("test a_var\n File", tuple[2]) | |
| 1109 self.assertIn("in _logging_test", tuple[2]) | |
| 1110 self.assertIn("logger.info(msg, extra=", tuple[2]) | |
| 1111 # The call to extract_stack should be included as the frame | |
| 1112 # at bottom of stack. | |
| 1113 self.assertIn("extract_stack()", tuple[2]) | |
| 1114 # A file in 'pytest' directory should be at the top of stack. | |
| 1115 # no idea how deep the actual stack is, could change with python | |
| 1116 # versions, but 3.12 is 33 so .... | |
| 1117 self.assertTrue(find_file_occurances(tuple[2]) > 10) | |
| 1118 self.assertIn("pytest", tuple[2]) | |
| 1119 self._caplog.clear() | |
| 1120 | |
| 1121 # pass args and compatible message | |
| 1122 config._logging_test(None, args=(1,2,3), | |
| 1123 msg="one: %s, two: %s, three: %s" | |
| 1124 ) | |
| 1125 tuple = self._caplog.record_tuples[0] | |
| 1126 self.assertEqual(tuple[1], 20) | |
| 1127 self.assertEqual('one: 1, two: 2, three: 3', tuple[2]) | |
| 1128 self._caplog.clear() | |
| 1129 | |
| 1130 # error case for incorrect placeholder | |
| 1131 config._logging_test(None, msg="%(a)") | |
| 1132 tuple = self._caplog.record_tuples[0] | |
| 1133 self.assertEqual(tuple[1], 20) | |
| 1134 self.assertEqual("%(a)", tuple[2]) | |
| 1135 self._caplog.clear() | |
| 1136 | |
| 1137 # error case for incompatible format record is the first argument | |
| 1138 # and it can't be turned into floating point. | |
| 1139 config._logging_test(None, msg="%f") | |
| 1140 tuple = self._caplog.record_tuples[0] | |
| 1141 self.assertEqual(tuple[1], 20) | |
| 1142 self.assertEqual("%f", tuple[2]) | |
| 1143 self._caplog.clear() | |
| 1144 | |
| 1145 | |
| 1013 def testXhtmlRaisesOptionError(self): | 1146 def testXhtmlRaisesOptionError(self): |
| 1014 self.munge_configini(mods=[ ("html_version = ", "xhtml") ]) | 1147 self.munge_configini(mods=[ ("html_version = ", "xhtml") ]) |
| 1015 | 1148 |
| 1016 config = configuration.CoreConfig() | 1149 config = configuration.CoreConfig() |
| 1017 | 1150 |