Coverage for python/lsst/daf/butler/logging.py: 38%

1# This file is part of daf_butler.

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.

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/>.

28from __future__ import annotations

30__all__ = (

31 "ButlerLogRecord",

32 "ButlerLogRecordHandler",

33 "ButlerLogRecords",

34 "ButlerMDC",

35 "JsonLogFormatter",

36)

38import datetime

39import io

40import logging

41import traceback

42from collections.abc import Callable, Generator, Iterable, Iterator, MutableSequence

43from contextlib import contextmanager

44from logging import Formatter, LogRecord, StreamHandler

45from types import TracebackType

46from typing import IO, Any, ClassVar, Literal, Self, TypeVar, cast, overload

48import pydantic_core

49from pydantic import BaseModel, ConfigDict, Field, RootModel

51_LONG_LOG_FORMAT = "{levelname} {asctime} {name} {filename}:{lineno} - {message}"

52"""Default format for log records."""

55class MDCDict(dict):

56 """Dictionary for MDC data.

58 This is internal class used for better formatting of MDC in Python logging

59 output. It behaves like `defaultdict(str)` but overrides ``__str__`` and

60 ``__repr__`` method to produce output better suited for logging records.

61 """

63 def __getitem__(self, name: str) -> str:

64 """Return value for a given key or empty string for missing key."""

65 return self.get(name, "")

67 def __str__(self) -> str:

68 """Return string representation, strings are interpolated without

69 quotes.

70 """

71 items = (f"{k}={self[k]}" for k in sorted(self))

72 return "{" + ", ".join(items) + "}"

74 def __repr__(self) -> str:

75 return str(self)

78class ButlerMDC:

79 """Handle setting and unsetting of global MDC records.

81 The Mapped Diagnostic Context (MDC) can be used to set context

82 for log messages.

84 Currently there is one global MDC dict. Per-thread MDC is not

85 yet supported.

86 """

88 _MDC = MDCDict()

90 _old_factory: Callable[..., logging.LogRecord] | None = None

91 """Old log record factory."""

93 @classmethod

94 def MDC(cls, key: str, value: str) -> str:

95 """Set MDC for this key to the supplied value.

97 Parameters

98 ----------

99 key : `str`

100 Key to modify.

101 value : `str`

102 New value to use.

103

104 Returns

105 -------

106 old : `str`

107 The previous value for this key.

108 """

109 old_value = cls._MDC[key]

110 cls._MDC[key] = value

111 return old_value

112

113 @classmethod

114 def MDCRemove(cls, key: str) -> None:

115 """Clear the MDC value associated with this key.

116

117 Can be called even if the key is not known to MDC.

118

119 Parameters

120 ----------

121 key : `str`

122 Key for which the MDC value should be removed.

123 """

124 cls._MDC.pop(key, None)

125

126 @classmethod

127 def clear_mdc(cls) -> None:

128 """Clear all MDC entries."""

129 cls._MDC.clear()

130

131 @classmethod

132 @contextmanager

133 def set_mdc(cls, mdc: dict[str, str]) -> Generator[None, None, None]:

134 """Set the MDC key for this context.

135

136 This context manager also adds a mapping named ``mdc`` to any

137 exceptions that escape it.

138

139 Parameters

140 ----------

141 mdc : `dict` of `str`, `str`

142 MDC keys to update temporarily.

143

144 Notes

145 -----

146 Other MDC keys are not modified. The previous values are restored

147 on exit (removing them if the were unset previously).

148 """

149 previous = {}

150 for k, v in mdc.items():

151 previous[k] = cls.MDC(k, v)

152

153 try:

154 yield

155 except BaseException as e:

156 # In logging, inner context overrules outer context. Need the same

157 # for exceptions.

158 inner_context: MDCDict = e.mdc if hasattr(e, "mdc") else MDCDict()

159 e.mdc = cls._MDC.copy() | inner_context # type: ignore[attr-defined]

160 raise

161 finally:

162 for k, v in previous.items():

163 if not v:

164 cls.MDCRemove(k)

165 else:

166 cls.MDC(k, v)

167

168 @classmethod

169 def add_mdc_log_record_factory(cls) -> None:

170 """Add a log record factory that adds a MDC record to `LogRecord`."""

171 old_factory = logging.getLogRecordFactory()

172

173 # Need explicit args in case exc_info is called as an arg (and because

174 # the factory API has a parameter literally called `args`).

175 def record_factory(

176 name: str,

177 level: int,

178 fn: str,

179 lno: int,

180 msg: str,

181 args: tuple,

182 exc_info: tuple | None | Literal[False],

183 func: str | None = None,

184 sinfo: TracebackType | None = None,

185 **kwargs: Any,

186 ) -> LogRecord:

187 record = old_factory(name, level, fn, lno, msg, args, exc_info, func, sinfo, **kwargs)

188 # Make sure we send a copy of the global dict in the record.

189 mdc = MDCDict(cls._MDC)

190 if exc_info is not None and exc_info is not False:

191 _, ex, _ = exc_info

192 # TODO: this doesn't handle chained exceptions, fix on DM-47546

193 if hasattr(ex, "mdc"):

194 # Context at the point where the exception was raised

195 # takes precedence.

196 mdc.update(ex.mdc)

197 record.MDC = mdc

198 return record

199

200 cls._old_factory = old_factory

201 logging.setLogRecordFactory(record_factory)

202

203 @classmethod

204 def restore_log_record_factory(cls) -> None:

205 """Restores the log record factory to the original form.

206

207 Does nothing if there has not been a call to

208 `add_mdc_log_record_factory`.

209 """

210 if cls._old_factory:

211 logging.setLogRecordFactory(cls._old_factory)

212

213

214class ButlerLogRecord(BaseModel):

215 """A model representing a `logging.LogRecord`.

216

217 A `~logging.LogRecord` always uses the current time in its record

218 when recreated and that makes it impossible to use it as a

219 serialization format. Instead have a local representation of a

220 `~logging.LogRecord` that matches Butler needs.

221 """

222

223 _log_format: ClassVar[str] = _LONG_LOG_FORMAT

224

225 name: str

226 asctime: datetime.datetime

227 message: str

228 levelno: int

229 levelname: str

230 filename: str

231 pathname: str

232 lineno: int

233 funcName: str | None = None

234 process: int

235 processName: str

236 exc_info: str | None = None

237 MDC: dict[str, str]

238

239 model_config = ConfigDict(frozen=True)

240

241 @classmethod

242 def from_record(cls, record: LogRecord) -> ButlerLogRecord:

243 """Create a new instance from a `~logging.LogRecord`.

244

245 Parameters

246 ----------

247 record : `logging.LogRecord`

248 The record from which to extract the relevant information.

249 """

250 # The properties that are one-to-one mapping.

251 simple = (

252 "name",

253 "levelno",

254 "levelname",

255 "filename",

256 "pathname",

257 "lineno",

258 "funcName",

259 "process",

260 "processName",

261 )

262

263 record_dict = {k: getattr(record, k) for k in simple}

264

265 record_dict["message"] = record.getMessage()

266

267 # MDC -- ensure the contents are copied to prevent any confusion

268 # over the MDC global being updated later.

269 record_dict["MDC"] = dict(getattr(record, "MDC", {}))

270

271 # Always use UTC because in distributed systems we can't be sure

272 # what timezone localtime is and it's easier to compare logs if

273 # every system is using the same time.

274 record_dict["asctime"] = datetime.datetime.fromtimestamp(record.created, tz=datetime.UTC)

275

276 # Sometimes exception information is included so must be

277 # extracted.

278 if record.exc_info:

279 etype = record.exc_info[0]

280 evalue = record.exc_info[1]

281 tb = record.exc_info[2]

282 record_dict["exc_info"] = "\n".join(traceback.format_exception(etype, evalue, tb))

283

284 return cls(**record_dict)

285

286 def format(self, log_format: str | None = None) -> str:

287 """Format this record.

288

289 Parameters

290 ----------

291 log_format : `str`, optional

292 The format string to use. This string follows the standard

293 f-style use for formatting log messages. If `None`

294 the class default will be used.

295

296 Returns

297 -------

298 text : `str`

299 The formatted log message.

300 """

301 if log_format is None:

302 log_format = self._log_format

303

304 as_dict = self.model_dump()

305

306 # Special case MDC content. Convert it to an MDCDict

307 # so that missing items do not break formatting.

308 as_dict["MDC"] = MDCDict(as_dict["MDC"])

309

310 as_dict["asctime"] = as_dict["asctime"].isoformat()

311 formatted = log_format.format(**as_dict)

312 return formatted

313

314 def __str__(self) -> str:

315 return self.format()

316

317

318# The class below can convert LogRecord to ButlerLogRecord if needed.

319Record = LogRecord | ButlerLogRecord

320

321

322_T = TypeVar("_T", bound="ButlerLogRecords")

323

324

325class _ButlerLogRecordsModelV1(RootModel):

326 """Pydantic model used for version 1 JSON log files: a simple list of

327 `ButlerLogRecord` instances.

328 """

329

330 root: list[ButlerLogRecord]

331

332 def wrap(self, container_type: type[_T]) -> _T:

333 """Convert this model into a `ButlerLogRecords` instance.

334

335 Parameters

336 ----------

337 container_type : `type`

338 `ButlerLogRecords` subclass to use.

339

340 Returns

341 -------

342 container : `ButlerLogRecords`

343 Container for log records.

344 """

345 return container_type.from_records(self.root)

346

347

348class _ButlerLogRecordsModel(BaseModel):

349 """Pydantic model used for version 2(+) JSON log files: a struct with a

350 `records` attribute.

351 """

352

353 CURRENT_VERSION: ClassVar[int] = 2

354 """File format version written by this module."""

355

356 extended: Literal[True]

357 """Constant field that appears at the beginning of every version 2+ JSON

358 log file.

359

360 This field must be initialized directly when the model is constructed,

361 because using a default causes it to be omitted by Pydantic when

362 serializing with ``exclude_unset`` or ``exclude_default`` (both of which

363 are used in serializing logs).

364 """

365

366 version: int

367 """File format version for this file.

368

369 This field must be initialized directly when the model is constructed,

370 because using a default causes it to be omitted by Pydantic when

371 serializing with ``exclude_unset`` or ``exclude_default`` (both of which

372 are used in serializing logs).

373 """

374

375 records: list[ButlerLogRecord] = Field(default_factory=list)

376 """The actual log records."""

377

378 model_config = ConfigDict(extra="allow")

379

380 def wrap(self, container_type: type[_T]) -> _T:

381 """Convert this model into a `ButlerLogRecords` instance.

382

383 Parameters

384 ----------

385 container_type : `type`

386 `ButlerLogRecords` subclass to use.

387

388 Returns

389 -------

390 container : `ButlerLogRecords`

391 Container for log records.

392 """

393 return container_type.from_records(self.records, extra=self.__pydantic_extra__)

394

395

396class ButlerLogRecords(MutableSequence[ButlerLogRecord]):

397 """A container class for `ButlerLogRecord` objects.

398

399 Parameters

400 ----------

401 records : `list` [`ButlerLogRecord`]

402 List of records to use directly as the backing store for the container.

403 extra : `dict`, optional

404 Additional JSON data included with the log records. Subclasses may

405 interpret structured information, but the base class just sets this as

406 the `extra` attribute.

407

408 Notes

409 -----

410 ButlerLogRecords supports two different file formats:

411

412 - Full-container serialization to JSON, in which records are stored in a

413 ``records`` array and extra fields may be present (for backwards

414 compatibility, *reading* records directly from a JSON list is also

415 supported).

416

417 - Streaming serialization, in which each each line is a one-line JSON

418 representation of a single `ButlerLogRecord`. Extra fields may be added

419 included to this format by appending a single line with the value given

420 by `STREAMING_EXTRA_DELIMITER`, which indicates that the remainder of the

421 file is a single JSON block.

422

423 Subclasses of `ButlerLogRecords` are expected to support these formats by

424 using the "extra" JSON fields to hold any additional state. If subclasses

425 intercept `extra` at construction in a way that prevents that information

426 from being held in the base class `extra` field, they must override

427 `_from_record_subset` and `to_json_data` to pass that state to slices and

428 save it, respectively.

429 """

430

431 def __init__(self, records: list[ButlerLogRecord], extra: dict[str, object] | None = None):

432 self._records = records

433 self._log_format: str | None = None

434 self.extra = extra if extra is not None else {}

435

436 STREAMING_EXTRA_DELIMITER: ClassVar[str] = "###EXTRA###"

437 """Special string written (on its own line) after streamed log records to

438 indicate that the rest of the file is a JSON blob of "extra" data.

439 """

440

441 @classmethod

442 def from_records(cls, records: Iterable[ButlerLogRecord], extra: dict[str, object] | None = None) -> Self:

443 """Create collection from iterable.

444

445 Parameters

446 ----------

447 records : iterable of `ButlerLogRecord` or `LogRecord`

448 The records to seed this class with.

449 extra : `dict`, optional

450 Additional JSON data included with the log records. Subclasses may

451 interpret structured information, but the base class just sets this

452 as the `extra` attribute.

453

454 Returns

455 -------

456 container : `ButlerLogRecords`

457 New log record container.

458 """

459 return cls(list(records), extra=extra)

460

461 @classmethod

462 def from_file(cls, filename: str) -> Self:

463 """Read records from file.

464

465 Parameters

466 ----------

467 filename : `str`

468 Name of file containing the JSON records.

469

470 Notes

471 -----

472 Works with one-record-per-line format JSON files and a direct

473 serialization of the Pydantic model.

474 """

475 with open(filename) as fd:

476 return cls.from_stream(fd)

477

478 def _from_record_subset(self, records: list[ButlerLogRecord]) -> Self:

479 """Return a new instance with a subset of the original's records.

480

481 Parameters

482 ----------

483 records : `list` [`ButlerLogRecord`]

484 New list of records.

485

486 Returns

487 -------

488 copy : `ButlerLogRecords`

489 New instance of this type.

490

491 Notes

492 -----

493 This is a hook provided to allow subclasses to transfer extra state

494 when the container is sliced.

495 """

496 return self.from_records(records, extra=self.extra)

497

498 @staticmethod

499 def _generic_startswith(startdata: str | bytes, prefix: str) -> bool:

500 # A type-safe wrapper for `str.startswith` and `bytes.startswith` that

501 # avoids converting 'startdata', as it might be big.

502 if isinstance(startdata, str):

503 return startdata.startswith(prefix)

504 else:

505 return startdata.startswith(prefix.encode())

506

507 @classmethod

508 def _detect_model(

509 cls,

510 startdata: str | bytes,

511 ) -> type[_ButlerLogRecordsModelV1] | type[_ButlerLogRecordsModel] | None:

512 """Given some representative data, determine if this is a serialized

513 model or a streaming format.

514

515 Parameters

516 ----------

517 startdata : `bytes` or `str`

518 Representative characters or bytes from the start of a serialized

519 collection of log records.

520

521 Returns

522 -------

523 model_type : `type` or `None`

524 If the data looks like either the `_ButlerLogRecords` or

525 `_ExtendedButlerLogRecords` models, that model type.

526 Otherwise (streaming records, or an empty string `None`).

527

528 Raises

529 ------

530 ValueError

531 Raised if the sentinel doesn't look like either of the supported

532 log record formats.

533 """

534 if not startdata:

535 return None

536

537 if cls._generic_startswith(startdata, "["):

538 # This is a JSON array of records.

539 return _ButlerLogRecordsModelV1

540 elif not cls._generic_startswith(startdata, "{"):

541 # Limit the length of string reported in error message in case

542 # this is an enormous file.

543 max = 32

544 if len(startdata) > max:

545 msg = f"{startdata[:max]!r}..."

546 else:

547 msg = repr(startdata)

548 raise ValueError(

549 f"Unrecognized JSON log format. Expected '{{' or '[' but got {startdata[0]!r} from {msg}."

550 )

551 elif cls._generic_startswith(startdata, '{"extended":true'):

552 # This is a JSON model with a field for records.

553 return _ButlerLogRecordsModel

554 # Assume a record per line.

555 return None

556

557 @classmethod

558 def from_stream(cls, stream: IO) -> Self:

559 """Read records from I/O stream.

560

561 Parameters

562 ----------

563 stream : `typing.IO`

564 Stream from which to read JSON records.

565

566 Returns

567 -------

568 container : `ButlerLogRecords`

569 New log record container.

570 """

571 first_line = stream.readline()

572

573 if not first_line:

574 # Empty file, return zero records.

575 return cls.from_records([])

576

577 model_type = cls._detect_model(first_line)

578

579 if model_type:

580 # This is a ButlerLogRecords model serialization so all the

581 # content must be read first.

582 all = first_line + stream.read()

583 return model_type.model_validate_json(all).wrap(cls)

584

585 # A stream of records with one record per line.

586 records = [ButlerLogRecord.model_validate_json(first_line)]

587 for line in stream:

588 line = line.rstrip()

589 if cls._generic_startswith(line, "###EXTRA###"):

590 break

591 elif line: # skip blank lines

592 records.append(ButlerLogRecord.model_validate_json(line))

593 extra_data = stream.read()

594 if extra_data:

595 extra = pydantic_core.from_json(extra_data)

596 else:

597 extra = {}

598 return cls.from_records(records, extra=extra)

599

600 @classmethod

601 def from_raw(cls, serialized: str | bytes) -> ButlerLogRecords:

602 """Parse raw serialized form and return records.

603

604 Parameters

605 ----------

606 serialized : `bytes` or `str`

607 Either the serialized JSON of the model created using

608 `write` or a streaming format of one JSON `ButlerLogRecord` per

609 line. This can also support a zero-length string.

610

611 Returns

612 -------

613 container : `ButlerLogRecords`

614 New log record container.

615 """

616 if isinstance(serialized, str):

617 return cls.from_stream(io.StringIO(serialized))

618 else:

619 return cls.from_stream(io.BytesIO(serialized))

620

621 def to_json_data(self) -> str:

622 """Serialize to a JSON string.

623

624 Returns

625 -------

626 data : `str`

627 String containing JSON data.

628 """

629 if self.extra:

630 # There's no way to tell Pydantic to add extra fields back in

631 # when serializing directly to JSON; we have to convert to a dict

632 # first and then to JSON.

633 py_data = _ButlerLogRecordsModel(

634 extended=True, version=_ButlerLogRecordsModel.CURRENT_VERSION, records=self._records

635 ).model_dump(exclude_unset=True, exclude_defaults=True)

636 py_data.update(self.extra)

637 return pydantic_core.to_json(py_data).decode()

638 else:

639 return _ButlerLogRecordsModel(

640 extended=True, version=_ButlerLogRecordsModel.CURRENT_VERSION, records=self._records

641 ).model_dump_json(exclude_unset=True, exclude_defaults=True)

642

643 @property

644 def log_format(self) -> str:

645 """The log format string for these records."""

646 if self._log_format is None:

647 return _LONG_LOG_FORMAT

648 return self._log_format

649

650 @log_format.setter

651 def log_format(self, format: str | None) -> None:

652 self.set_log_format(format)

653

654 def set_log_format(self, format: str | None) -> str | None:

655 """Set the log format string for these records.

656

657 This may also be set via the property; method is provided for

658 backwards compatibility.

659

660 Parameters

661 ----------

662 format : `str`, optional

663 The new format string to use for converting this collection

664 of records into a string. If `None` the default format will be

665 used.

666

667 Returns

668 -------

669 old_format : `str`, optional

670 The previous log format.

671 """

672 previous = self._log_format

673 self._log_format = format

674 return previous

675

676 def __len__(self) -> int:

677 return len(self._records)

678

679 def __iter__(self) -> Iterator[ButlerLogRecord]:

680 return iter(self._records)

681

682 @overload

683 def __setitem__(self, index: int, value: Record) -> None: ... 683 ↛ exitline 683 didn't return from function '__setitem__' because

684

685 @overload

686 def __setitem__(self, index: slice, value: Iterable[Record]) -> None: ... 686 ↛ exitline 686 didn't return from function '__setitem__' because

687

688 def __setitem__(self, index: slice | int, value: Record | Iterable[Record]) -> None:

689 if isinstance(index, slice):

690 self._records[index] = [self._validate_record(v) for v in cast(Iterable[Record], value)]

691 else:

692 self._records[index] = self._validate_record(cast(Record, value))

693

694 @overload

695 def __getitem__(self, index: int) -> ButlerLogRecord: ... 695 ↛ exitline 695 didn't return from function '__getitem__' because

696

697 @overload

698 def __getitem__(self, index: slice) -> Self: ... 698 ↛ exitline 698 didn't return from function '__getitem__' because

699

700 def __getitem__(self, index: slice | int) -> Self | ButlerLogRecord:

701 # Handles slices and returns a new collection in that

702 # case.

703 item = self._records[index]

704 if isinstance(item, list):

705 return self._from_record_subset(item)

706 else:

707 return item

708

709 def __delitem__(self, index: slice | int) -> None:

710 del self._records[index]

711

712 def __eq__(self, other: object) -> bool:

713 if isinstance(other, ButlerLogRecords):

714 return self._records == other._records and self.extra == other.extra

715 return NotImplemented

716

717 def __str__(self) -> str:

718 # Ensure that every record uses the same format string.

719 return "\n".join(record.format(self.log_format) for record in self)

720

721 def _validate_record(self, record: Record) -> ButlerLogRecord:

722 if isinstance(record, ButlerLogRecord):

723 pass

724 elif isinstance(record, LogRecord):

725 record = ButlerLogRecord.from_record(record)

726 else:

727 raise ValueError(f"Can only append item of type {type(record)}")

728 return record

729

730 def insert(self, index: int, value: Record) -> None:

731 # Docstring provided by ABC.

732 self._records.insert(index, self._validate_record(value))

733

734 def append(self, value: Record) -> None:

735 # Docstring provided by ABC.

736 # Only overridden to accept `LogRecord`, not just `ButlerLogRecord`.

737 self._records.append(self._validate_record(value))

738

739 @classmethod

740 def write_streaming_extra(cls, file: IO[str], extra_data: str) -> None:

741 """Append the special delimiter and extra JSON data to a file written

742 in streaming mode.

743

744 Parameters

745 ----------

746 file : `typing.IO`

747 File object to write to, pointing to the end of the streamed log

748 records.

749 extra_data : `str`

750 Extra JSON data as a string.

751 """

752 print(cls.STREAMING_EXTRA_DELIMITER, file=file)

753 file.write(extra_data)

754

755

756class ButlerLogRecordHandler(StreamHandler):

757 """Python log handler that accumulates records."""

758

759 def __init__(self) -> None:

760 super().__init__()

761 self.records = ButlerLogRecords([])

762

763 def emit(self, record: LogRecord) -> None:

764 self.records.append(record)

765

766

767class JsonLogFormatter(Formatter):

768 """Format a `LogRecord` in JSON format."""

769

770 def format(self, record: LogRecord) -> str:

771 butler_record = ButlerLogRecord.from_record(record)

772 return butler_record.model_dump_json(exclude_unset=True, exclude_defaults=True)