Coverage for python / lsst / utils / logging.py: 45%

1# This file is part of utils. 

2# 

3# Developed for the LSST Data Management System. 

4# This product includes software developed by the LSST Project 

5# (https://www.lsst.org). 

6# See the COPYRIGHT file at the top-level directory of this distribution 

7# for details of code ownership. 

8# 

9# Use of this source code is governed by a 3-clause BSD-style 

10# license that can be found in the LICENSE file. 

11 

12from __future__ import annotations 

13 

14__all__ = ( 

15 "TRACE", 

16 "VERBOSE", 

17 "LsstLogAdapter", 

18 "LsstLoggers", 

19 "PeriodicLogger", 

20 "getLogger", 

21 "getTraceLogger", 

22 "trace_set_at", 

23) 

24 

25import logging 

26import sys 

27import time 

28from collections.abc import Generator 

29from contextlib import contextmanager 

30from logging import LoggerAdapter 

31from typing import TYPE_CHECKING, Any, TypeAlias, TypeGuard 

32 

33try: 

34 import lsst.log.utils as logUtils 

35except ImportError: 

36 logUtils = None 

37 

38try: 

39 from structlog import get_context as get_structlog_context 

40except ImportError: 

41 get_structlog_context = None # type: ignore[assignment] 

42 

43 

44if TYPE_CHECKING: 

45 try: 

46 from structlog.typing import BindableLogger 

47 except ImportError: 

48 BindableLogger: TypeAlias = Any # type: ignore[no-redef] 

49 

50# log level for trace (verbose debug). 

51TRACE = 5 

52logging.addLevelName(TRACE, "TRACE") 

53 

54# Verbose logging is midway between INFO and DEBUG. 

55VERBOSE = (logging.INFO + logging.DEBUG) // 2 

56logging.addLevelName(VERBOSE, "VERBOSE") 

57 

58 

59def _is_structlog_logger( 

60 logger: logging.Logger | LsstLogAdapter | BindableLogger, 

61) -> TypeGuard[BindableLogger]: 

62 """Check if the given logger is a structlog logger.""" 

63 if get_structlog_context is None: 

64 return False # type: ignore[unreachable] 

65 

66 try: 

67 # Returns a dict for structlog loggers; raises for stdlib logger 

68 # objects. 

69 get_structlog_context(logger) # type: ignore[arg-type] 

70 return True 

71 except Exception: 

72 # In practice this is usually ValueError or AttributeError. 

73 return False 

74 

75 

76def _calculate_base_stacklevel(default: int, offset: int) -> int: 

77 """Calculate the default logging stacklevel to use. 

78 

79 Parameters 

80 ---------- 

81 default : `int` 

82 The stacklevel to use in Python 3.11 and newer where the only 

83 thing to take into account is the number of levels above the core 

84 Python logging infrastructure. 

85 offset : `int` 

86 The offset to apply for older Python implementations that need to 

87 take into account internal call stacks. 

88 

89 Returns 

90 ------- 

91 stacklevel : `int` 

92 The stack level to pass to internal logging APIs that should result 

93 in the log messages being reported in caller lines. 

94 

95 Notes 

96 ----- 

97 In Python 3.11 the logging infrastructure was fixed such that we no 

98 longer need to understand that a LoggerAdapter log messages need to 

99 have a stack level one higher than a Logger would need. ``stacklevel=1`` 

100 now always means "log from the caller's line" without the caller having 

101 to understand internal implementation details. 

102 """ 

103 stacklevel = default 

104 if sys.version_info < (3, 11, 0): 104 ↛ 105line 104 didn't jump to line 105 because the condition on line 104 was never true

105 stacklevel += offset 

106 return stacklevel 

107 

108 

109def trace_set_at(name: str, number: int) -> None: 

110 """Adjust logging level to display messages with the trace number being 

111 less than or equal to the provided value. 

112 

113 Parameters 

114 ---------- 

115 name : `str` 

116 Name of the logger. 

117 number : `int` 

118 The trace number threshold for display. 

119 

120 Examples 

121 -------- 

122 .. code-block:: python 

123 

124 lsst.utils.logging.trace_set_at("lsst.afw", 3) 

125 

126 This will set loggers ``TRACE0.lsst.afw`` to ``TRACE3.lsst.afw`` to 

127 ``DEBUG`` and ``TRACE4.lsst.afw`` and ``TRACE5.lsst.afw`` to ``INFO``. 

128 

129 Notes 

130 ----- 

131 Loggers ``TRACE0.`` to ``TRACE5.`` are set. All loggers above 

132 the specified threshold are set to ``INFO`` and those below the threshold 

133 are set to ``DEBUG``. The expectation is that ``TRACE`` loggers only 

134 issue ``DEBUG`` log messages. 

135 

136 If ``lsst.log`` is installed, this function will also call 

137 `lsst.log.utils.traceSetAt` to ensure that non-Python loggers are 

138 also configured correctly. 

139 """ 

140 for i in range(6): 

141 level = logging.INFO if i > number else logging.DEBUG 

142 getTraceLogger(name, i).setLevel(level) 

143 

144 # if lsst log is available also set the trace loggers there. 

145 if logUtils is not None: 

146 logUtils.traceSetAt(name, number) 

147 

148 

149class _F: 

150 """Format, supporting `str.format()` syntax. 

151 

152 Notes 

153 ----- 

154 This follows the recommendation from 

155 https://docs.python.org/3/howto/logging-cookbook.html#using-custom-message-objects 

156 """ 

157 

158 def __init__(self, fmt: str, /, *args: Any, **kwargs: Any): 

159 self.fmt = fmt 

160 self.args = args 

161 self.kwargs = kwargs 

162 

163 def __str__(self) -> str: 

164 return self.fmt.format(*self.args, **self.kwargs) 

165 

166 

167class LsstLogAdapter(LoggerAdapter): 

168 """A special logging adapter to provide log features for LSST code. 

169 

170 Expected to be instantiated initially by a call to `getLogger()`. 

171 

172 This class provides enhancements over `logging.Logger` that include: 

173 

174 * Methods for issuing trace and verbose level log messages. 

175 * Provision of a context manager to temporarily change the log level. 

176 * Attachment of logging level constants to the class to make it easier 

177 for a Task writer to access a specific log level without having to 

178 know the underlying logger class. 

179 """ 

180 

181 # Store logging constants in the class for convenience. This is not 

182 # something supported by Python loggers but can simplify some 

183 # logic if the logger is available. 

184 CRITICAL = logging.CRITICAL 

185 ERROR = logging.ERROR 

186 DEBUG = logging.DEBUG 

187 INFO = logging.INFO 

188 WARNING = logging.WARNING 

189 

190 # Python supports these but prefers they are not used. 

191 FATAL = logging.FATAL 

192 WARN = logging.WARN 

193 

194 # These are specific to Tasks 

195 TRACE = TRACE 

196 VERBOSE = VERBOSE 

197 

198 # The stack level to use when issuing log messages. For Python 3.11 

199 # this is generally 2 (this method and the internal infrastructure). 

200 # For older python we need one higher because of the extra indirection 

201 # via LoggingAdapter internals. 

202 _stacklevel = _calculate_base_stacklevel(2, 1) 

203 

204 @contextmanager 

205 def temporary_log_level(self, level: int | str) -> Generator: 

206 """Temporarily set the level of this logger. 

207 

208 Parameters 

209 ---------- 

210 level : `int` 

211 The new temporary log level. 

212 """ 

213 old = self.level 

214 self.setLevel(level) 

215 try: 

216 yield 

217 finally: 

218 self.setLevel(old) 

219 

220 @property 

221 def level(self) -> int: 

222 """Return current level of this logger (``int``).""" 

223 return self.logger.level 

224 

225 def getChild(self, name: str) -> LsstLogAdapter: 

226 """Get the named child logger. 

227 

228 Parameters 

229 ---------- 

230 name : `str` 

231 Name of the child relative to this logger. 

232 

233 Returns 

234 ------- 

235 child : `LsstLogAdapter` 

236 The child logger. 

237 """ 

238 return getLogger(name=name, logger=self.logger) 

239 

240 def _process_stacklevel(self, kwargs: dict[str, Any], offset: int = 0) -> int: 

241 # Return default stacklevel, taking into account kwargs[stacklevel]. 

242 stacklevel = self._stacklevel 

243 if "stacklevel" in kwargs: 

244 # External user expects stacklevel=1 to mean "report from their 

245 # line" but the code here is already trying to achieve that by 

246 # default. Therefore if an external stacklevel is specified we 

247 # adjust their stacklevel request by 1. 

248 stacklevel = stacklevel + kwargs.pop("stacklevel") - 1 

249 

250 # The offset can be used to indicate that we have to take into account 

251 # additional internal layers before calling python logging. 

252 return _calculate_base_stacklevel(stacklevel, offset) 

253 

254 def fatal(self, msg: str, *args: Any, **kwargs: Any) -> None: 

255 # Python does not provide this method in LoggerAdapter but does 

256 # not formally deprecate it in favor of critical() either. 

257 # Provide it without deprecation message for consistency with Python. 

258 # Have to adjust stacklevel on Python 3.10 and older to account 

259 # for call through self.critical. 

260 stacklevel = self._process_stacklevel(kwargs, offset=1) 

261 self.critical(msg, *args, **kwargs, stacklevel=stacklevel) 

262 

263 def verbose(self, fmt: str, *args: Any, **kwargs: Any) -> None: 

264 """Issue a VERBOSE level log message. 

265 

266 Arguments are as for `logging.info`. 

267 ``VERBOSE`` is between ``DEBUG`` and ``INFO``. 

268 

269 Parameters 

270 ---------- 

271 fmt : `str` 

272 Log message. 

273 *args : `~typing.Any` 

274 Parameters references by log message. 

275 **kwargs : `~typing.Any` 

276 Parameters forwarded to underlying logger. 

277 """ 

278 # There is no other way to achieve this other than a special logger 

279 # method. 

280 # Stacklevel is passed in so that the correct line is reported 

281 stacklevel = self._process_stacklevel(kwargs) 

282 self.log(VERBOSE, fmt, *args, **kwargs, stacklevel=stacklevel) 

283 

284 def trace(self, fmt: str, *args: Any, **kwargs: Any) -> None: 

285 """Issue a TRACE level log message. 

286 

287 Arguments are as for `logging.info`. 

288 ``TRACE`` is lower than ``DEBUG``. 

289 

290 Parameters 

291 ---------- 

292 fmt : `str` 

293 Log message. 

294 *args : `~typing.Any` 

295 Parameters references by log message. 

296 **kwargs : `~typing.Any` 

297 Parameters forwarded to underlying logger. 

298 """ 

299 # There is no other way to achieve this other than a special logger 

300 # method. 

301 stacklevel = self._process_stacklevel(kwargs) 

302 self.log(TRACE, fmt, *args, **kwargs, stacklevel=stacklevel) 

303 

304 def setLevel(self, level: int | str) -> None: 

305 """Set the level for the logger, trapping lsst.log values. 

306 

307 Parameters 

308 ---------- 

309 level : `int` 

310 The level to use. If the level looks too big to be a Python 

311 logging level it is assumed to be a lsst.log level. 

312 """ 

313 if isinstance(level, int) and level > logging.CRITICAL: 

314 self.logger.warning( 

315 "Attempting to set level to %d -- looks like an lsst.log level so scaling it accordingly.", 

316 level, 

317 ) 

318 level //= 1000 

319 

320 self.logger.setLevel(level) 

321 

322 @property 

323 def handlers(self) -> list[logging.Handler]: 

324 """Log handlers associated with this logger.""" 

325 return self.logger.handlers 

326 

327 def addHandler(self, handler: logging.Handler) -> None: 

328 """Add a handler to this logger. 

329 

330 Parameters 

331 ---------- 

332 handler : `logging.Handler` 

333 Handler to add. The handler is forwarded to the underlying logger. 

334 """ 

335 self.logger.addHandler(handler) 

336 

337 def removeHandler(self, handler: logging.Handler) -> None: 

338 """Remove the given handler from the underlying logger. 

339 

340 Parameters 

341 ---------- 

342 handler : `logging.Handler` 

343 Handler to remove. 

344 """ 

345 self.logger.removeHandler(handler) 

346 

347 

348def getLogger(name: str | None = None, logger: logging.Logger | None = None) -> LsstLogAdapter: 

349 """Get a logger compatible with LSST usage. 

350 

351 Parameters 

352 ---------- 

353 name : `str`, optional 

354 Name of the logger. Root logger if `None`. 

355 logger : `logging.Logger` or `LsstLogAdapter` 

356 If given the logger is converted to the relevant logger class. 

357 If ``name`` is given the logger is assumed to be a child of the 

358 supplied logger. 

359 

360 Returns 

361 ------- 

362 logger : `LsstLogAdapter` 

363 The relevant logger. 

364 

365 Notes 

366 ----- 

367 A `logging.LoggerAdapter` is used since it is easier to provide a more 

368 uniform interface than when using `logging.setLoggerClass`. An adapter 

369 can be wrapped around the root logger and the `~logging.setLoggerClass` 

370 will return the logger first given that name even if the name was 

371 used before the `~lsst.pipe.base.Task` was created. 

372 """ 

373 if not logger: 

374 logger = logging.getLogger(name) 

375 elif name: 

376 logger = logger.getChild(name) 

377 return LsstLogAdapter(logger, {}) 

378 

379 

380LsstLoggers: TypeAlias = logging.Logger | LsstLogAdapter 

381 

382 

383def getTraceLogger(logger: str | LsstLoggers, trace_level: int) -> LsstLogAdapter: 

384 """Get a logger with the appropriate TRACE name. 

385 

386 Parameters 

387 ---------- 

388 logger : `logging.Logger` or `LsstLogAdapter` or `lsst.log.Log` or `str` 

389 A logger to be used to derive the new trace logger. Can be a logger 

390 object that supports the ``name`` property or a string. 

391 trace_level : `int` 

392 The trace level to use for the logger. 

393 

394 Returns 

395 ------- 

396 trace_logger : `LsstLogAdapter` 

397 A new trace logger. The name will be derived by pre-pending ``TRACEn.`` 

398 to the name of the supplied logger. If the root logger is given 

399 the returned logger will be named ``TRACEn``. 

400 """ 

401 name = getattr(logger, "name", str(logger)) 

402 trace_name = f"TRACE{trace_level}.{name}" if name else f"TRACE{trace_level}" 

403 return getLogger(trace_name) 

404 

405 

406class PeriodicLogger: 

407 """Issue log messages if a time threshold has elapsed. 

408 

409 This class can be used in long-running sections of code where it would 

410 be useful to issue a log message periodically to show that the 

411 algorithm is progressing. 

412 

413 The first time threshold is counted from object construction, so in general 

414 the first call to `log` does not log. 

415 

416 Parameters 

417 ---------- 

418 logger : `logging.Logger` or `LsstLogAdapter` 

419 Logger to use when issuing a message. 

420 interval : `float` 

421 The minimum interval in seconds between log messages. If `None`, 

422 `LOGGING_INTERVAL` will be used. 

423 level : `int`, optional 

424 Log level to use when issuing messages, default is 

425 `~logging.INFO`. 

426 """ 

427 

428 LOGGING_INTERVAL = 600.0 

429 """Default interval between log messages in seconds.""" 

430 

431 def __init__(self, logger: LsstLoggers, interval: float | None = None, level: int = logging.INFO): 

432 self.logger = logger 

433 # None -> LOGGING_INTERVAL conversion done so that unit tests (e.g., in 

434 # pipe_base) can tweak log interval without access to the constructor. 

435 self.interval = interval if interval is not None else self.LOGGING_INTERVAL 

436 self.level = level 

437 self.next_log_time = time.time() + self.interval 

438 self.num_issued = 0 

439 

440 # The stacklevel we need to issue logs is determined by the type 

441 # of logger we have been given. A LoggerAdapter has an extra 

442 # level of indirection. In Python 3.11 the logging infrastructure 

443 # takes care to check for internal logging stack frames so there 

444 # is no need for a difference. 

445 self._stacklevel = _calculate_base_stacklevel(2, 1 if isinstance(self.logger, LoggerAdapter) else 0) 

446 

447 def log(self, msg: str, *args: Any) -> bool: 

448 """Issue a log message if the interval has elapsed. 

449 

450 The interval is measured from the previous call to ``log``, or from the 

451 creation of this object. 

452 

453 Parameters 

454 ---------- 

455 msg : `str` 

456 Message to issue if the time has been exceeded. 

457 *args : Any 

458 Arguments to be merged into the message string, as described under 

459 `logging.Logger.debug`. 

460 

461 Returns 

462 ------- 

463 issued : `bool` 

464 Returns `True` if a log message was sent to the logging system. 

465 Returns `False` if the interval has not yet elapsed. Returning 

466 `True` does not indicate whether the log message was in fact 

467 issued by the logging system. 

468 """ 

469 if (current_time := time.time()) > self.next_log_time: 

470 self.logger.log(self.level, msg, *args, stacklevel=self._stacklevel) 

471 self.next_log_time = current_time + self.interval 

472 self.num_issued += 1 

473 return True 

474 return False