Coverage for tests / test_logging.py: 8%
221 statements
« prev ^ index » next coverage.py v7.13.5, created at 2026-04-22 08:55 +0000
1# This file is part of daf_butler.
2#
3# Developed for the LSST Data Management System.
4# This product includes software developed by the LSST Project
5# (http://www.lsst.org).
6# See the COPYRIGHT file at the top-level directory of this distribution
7# for details of code ownership.
8#
9# This software is dual licensed under the GNU General Public License and also
10# under a 3-clause BSD license. Recipients may choose which of these licenses
11# to use; please see the files gpl-3.0.txt and/or bsd_license.txt,
12# respectively. If you choose the GPL option then the following text applies
13# (but note that there is still no warranty even if you opt for BSD instead):
14#
15# This program is free software: you can redistribute it and/or modify
16# it under the terms of the GNU General Public License as published by
17# the Free Software Foundation, either version 3 of the License, or
18# (at your option) any later version.
19#
20# This program is distributed in the hope that it will be useful,
21# but WITHOUT ANY WARRANTY; without even the implied warranty of
22# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
23# GNU General Public License for more details.
24#
25# You should have received a copy of the GNU General Public License
26# along with this program. If not, see <http://www.gnu.org/licenses/>.
28import io
29import logging
30import tempfile
31import unittest
32from logging import FileHandler, StreamHandler
34import lsst.utils.logging
35from lsst.daf.butler.logging import (
36 ButlerLogRecord,
37 ButlerLogRecordHandler,
38 ButlerLogRecords,
39 ButlerMDC,
40 JsonLogFormatter,
41)
42from lsst.utils.logging import VERBOSE
45class LoggingTestCase(unittest.TestCase):
46 """Test we can capture log messages."""
48 def setUp(self):
49 self.handler = ButlerLogRecordHandler()
51 self.log = lsst.utils.logging.getLogger(self.id())
52 self.log.addHandler(self.handler)
54 def tearDown(self):
55 if self.handler and self.log:
56 self.log.removeHandler(self.handler)
57 ButlerMDC.restore_log_record_factory()
58 ButlerMDC.clear_mdc()
60 def testRecordCapture(self):
61 """Test basic log capture and serialization."""
62 self.log.setLevel(VERBOSE)
64 test_messages = (
65 (logging.INFO, "This is a log message", True),
66 (logging.WARNING, "This is a warning message", True),
67 (logging.DEBUG, "This debug message should not be stored", False),
68 (VERBOSE, "A verbose message should appear", True),
69 )
71 for level, message, _ in test_messages:
72 self.log.log(level, message)
74 expected = [info for info in test_messages if info[2]]
76 self.assertEqual(len(self.handler.records), len(expected))
78 for given, record in zip(expected, self.handler.records, strict=True):
79 self.assertEqual(given[0], record.levelno)
80 self.assertEqual(given[1], record.message)
82 # Check that we can serialize the records
83 json = self.handler.records.to_json_data()
85 records = ButlerLogRecords.from_raw(json)
86 for original_record, new_record in zip(self.handler.records, records, strict=True):
87 self.assertEqual(new_record, original_record)
88 self.assertEqual(str(records), str(self.handler.records))
90 # Create stream form of serialization.
91 json_stream = "\n".join(record.model_dump_json() for record in records)
93 # Also check we can autodetect the format.
94 for raw in (json, json.encode(), json_stream, json_stream.encode()):
95 records = ButlerLogRecords.from_raw(raw)
96 self.assertEqual(records, self.handler.records)
98 for raw in ("", b""):
99 self.assertEqual(len(ButlerLogRecords.from_raw(raw)), 0)
100 self.assertEqual(len(ButlerLogRecords.from_stream(io.StringIO())), 0)
102 # Send bad text to the parser and it should fail (both bytes and str).
103 bad_text = "x" * 100
105 # Include short and long values to trigger different code paths
106 # in error message creation.
107 for trim in (True, False):
108 for bad in (bad_text, bad_text.encode()):
109 bad = bad[:10] if trim else bad
110 with self.assertRaises(ValueError) as cm:
111 ButlerLogRecords.from_raw(bad)
112 if not trim:
113 self.assertIn("...", str(cm.exception))
115 def testRecordsFormatting(self):
116 self.log.setLevel(logging.DEBUG)
117 self.log.debug("debug message")
118 self.log.warning("warning message")
119 self.log.critical("critical message")
120 self.log.verbose("verbose message")
121 self.log.error("error message")
122 try:
123 raise RuntimeError("An error has occurred")
124 except RuntimeError:
125 self.log.exception("exception message")
127 self.assertEqual(len(self.handler.records), 6)
129 format_default = str(self.handler.records)
131 # Set the format for these records.
132 self.handler.records.set_log_format("{levelname}")
133 format_override = str(self.handler.records)
135 self.assertNotEqual(format_default, format_override)
136 self.assertEqual(format_override, "DEBUG\nWARNING\nCRITICAL\nVERBOSE\nERROR\nERROR")
138 # Reset the log format and it should match the original text.
139 self.handler.records.set_log_format(None)
140 self.assertEqual(str(self.handler.records), format_default)
142 def testButlerLogRecords(self):
143 """Test the list-like methods of ButlerLogRecords."""
144 self.log.setLevel(logging.INFO)
146 n_messages = 10
147 message = "Message #%d"
148 for counter in range(n_messages):
149 self.log.info(message, counter)
151 records = self.handler.records
152 self.assertEqual(len(records), n_messages)
154 # Test slicing.
155 start = 2
156 end = 6
157 subset = records[start:end]
158 self.assertIsInstance(subset, ButlerLogRecords)
159 self.assertEqual(len(subset), end - start)
160 self.assertIn(f"#{start}", subset[0].message)
162 # Reverse the collection.
163 backwards = list(reversed(records))
164 self.assertEqual(len(backwards), len(records))
165 self.assertEqual(records[0], backwards[-1])
167 # Test some of the collection manipulation methods.
168 record_0 = records[0]
169 records.reverse()
170 self.assertEqual(records[-1], record_0)
171 self.assertEqual(records.pop(), record_0)
172 records[0] = record_0
173 self.assertEqual(records[0], record_0)
174 len_records = len(records)
175 records.insert(2, record_0)
176 self.assertEqual(len(records), len_records + 1)
177 self.assertEqual(records[0], records[2])
179 # Put the subset records back onto the end of the original.
180 records.extend(subset)
181 self.assertEqual(len(records), n_messages + len(subset))
183 # Test slice for deleting
184 initial_length = len(records)
185 start_del = 1
186 end_del = 3
187 del records[start_del:end_del]
188 self.assertEqual(len(records), initial_length - (end_del - start_del))
190 records.clear()
191 self.assertEqual(len(records), 0)
193 with self.assertRaises(ValueError):
194 records.append({})
196 def testExceptionInfo(self):
197 self.log.setLevel(logging.DEBUG)
198 try:
199 raise RuntimeError("A problem has been encountered.")
200 except RuntimeError:
201 self.log.exception("Caught")
203 self.assertIn("A problem has been encountered", self.handler.records[0].exc_info)
205 self.log.warning("No exc_info")
206 self.assertIsNone(self.handler.records[-1].exc_info)
208 try:
209 raise RuntimeError("Debug exception log")
210 except RuntimeError:
211 self.log.debug("A problem", exc_info=1)
213 self.assertIn("Debug exception", self.handler.records[-1].exc_info)
215 def testMDC(self):
216 """Test that MDC information appears in messages."""
217 self.log.setLevel(logging.INFO)
219 i = 0
220 self.log.info("Message %d", i)
221 i += 1
222 self.assertEqual(self.handler.records[-1].MDC, {})
224 ButlerMDC.add_mdc_log_record_factory()
225 label = "MDC value"
226 ButlerMDC.MDC("LABEL", label)
227 self.log.info("Message %d", i)
228 self.assertEqual(self.handler.records[-1].MDC["LABEL"], label)
230 # Change the label and check that the previous record does not
231 # itself change.
232 ButlerMDC.MDC("LABEL", "dataId")
233 self.assertEqual(self.handler.records[-1].MDC["LABEL"], label)
235 # Format a record with MDC.
236 record = self.handler.records[-1]
238 # By default the MDC label should not be involved.
239 self.assertNotIn(label, str(record))
241 # But it can be included.
242 fmt = "x{MDC[LABEL]}"
243 self.assertEqual(record.format(fmt), "x" + label)
245 # But can be optional on a record that didn't set it.
246 self.assertEqual(self.handler.records[0].format(fmt), "x")
248 # Set an extra MDC entry and include all content.
249 extra = "extra"
250 ButlerMDC.MDC("EXTRA", extra)
252 i += 1
253 self.log.info("Message %d", i)
254 formatted = self.handler.records[-1].format("x{MDC} - {message}")
255 self.assertIn(f"EXTRA={extra}", formatted)
256 self.assertIn("LABEL=dataId", formatted)
257 self.assertIn(f"Message {i}", formatted)
259 # Clear the MDC and ensure that it does not continue to appear
260 # in messages.
261 ButlerMDC.MDCRemove("LABEL")
262 i += 1
263 self.log.info("Message %d", i)
264 self.assertEqual(self.handler.records[-1].format(fmt), "x")
265 self.assertEqual(self.handler.records[-1].format("{message}"), f"Message {i}")
267 # MDC context manager
268 fmt = "x{MDC[LABEL]} - {message}"
269 ButlerMDC.MDC("LABEL", "original")
270 with ButlerMDC.set_mdc({"LABEL": "test"}):
271 i += 1
272 self.log.info("Message %d", i)
273 self.assertEqual(self.handler.records[-1].format(fmt), f"xtest - Message {i}")
274 i += 1
275 self.log.info("Message %d", i)
276 self.assertEqual(self.handler.records[-1].format(fmt), f"xoriginal - Message {i}")
278 def testMDC_exception(self):
279 """Test that exceptions preserve MDC from the point of raising."""
280 ButlerMDC.add_mdc_log_record_factory()
282 ButlerMDC.MDC("foo", "bar")
283 try:
284 with ButlerMDC.set_mdc({"foo": "fum", "answer": "42"}):
285 raise RuntimeError("I take exception to that!")
286 except RuntimeError as e:
287 self.assertEqual(e.mdc, {"foo": "fum", "answer": "42"})
288 # Exception should hang on to old state
289 self.log.exception("Exception raised:")
290 self.log.warning("Implied exception", exc_info=True)
291 self.log.critical("Explicit exception", exc_info=e)
292 self.log.error("Explicit exception info", exc_info=(Exception, e, e.__traceback__))
293 # Is original context used *only* when logging the exception?
294 self.log.error("Something went wrong")
295 self.log.error("Boolean disabled exc info", exc_info=False)
296 for i in [-6, -5, -4, -3]:
297 self.assertEqual(self.handler.records[i].MDC, {"foo": "fum", "answer": "42"})
298 for i in [-2, -1]:
299 self.assertEqual(self.handler.records[i].MDC, {"foo": "bar"})
301 self.log.setLevel(logging.INFO)
302 self.log.info("Normal log")
303 self.assertEqual(self.handler.records[-1].MDC, {"foo": "bar"})
306class TestJsonLogging(unittest.TestCase):
307 """Test logging using JSON."""
309 def testJsonLogStream(self):
310 log = logging.getLogger(self.id())
311 log.setLevel(logging.INFO)
313 # Log to a stream and also to a file.
314 formatter = JsonLogFormatter()
316 stream = io.StringIO()
317 stream_handler = StreamHandler(stream)
318 stream_handler.setFormatter(formatter)
319 log.addHandler(stream_handler)
321 file = tempfile.NamedTemporaryFile(suffix=".json")
322 filename = file.name
323 file.close()
325 file_handler = FileHandler(filename)
326 file_handler.setFormatter(formatter)
327 log.addHandler(file_handler)
329 log.info("A message")
330 log.warning("A warning")
332 # Add a blank line to the stream to check the parser ignores it.
333 print(file=stream)
335 # Rewind the stream and pull messages out of it.
336 stream.seek(0)
337 records = ButlerLogRecords.from_stream(stream)
338 self.assertIsInstance(records[0], ButlerLogRecord)
339 self.assertEqual(records[0].message, "A message")
340 self.assertEqual(records[1].levelname, "WARNING")
342 # Now read from the file. Add two blank lines to test the parser
343 # will filter them out.
344 file_handler.close()
346 with open(filename, "a") as fd:
347 print(file=fd)
348 print(file=fd)
350 file_records = ButlerLogRecords.from_file(filename)
351 self.assertEqual(file_records, records)
353 # And read the file again in bytes and text.
354 for mode in ("rb", "r"):
355 with open(filename, mode) as fd:
356 file_records = ButlerLogRecords.from_stream(fd)
357 self.assertEqual(file_records, records)
358 fd.seek(0)
359 file_records = ButlerLogRecords.from_raw(fd.read())
360 self.assertEqual(file_records, records)
362 # Serialize this model to stream.
363 stream2 = io.StringIO()
364 print(records.to_json_data(), file=stream2)
365 stream2.seek(0)
366 stream_records = ButlerLogRecords.from_stream(stream2)
367 self.assertEqual(stream_records, records)
370if __name__ == "__main__":
371 unittest.main()