stdlib.py 16 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474
  1. # This file is dual licensed under the terms of the Apache License, Version
  2. # 2.0, and the MIT License. See the LICENSE file in the root of this
  3. # repository for complete details.
  4. """
  5. Processors and helpers specific to the :mod:`logging` module from the `Python
  6. standard library <https://docs.python.org/>`_.
  7. See also :doc:`structlog's standard library support <standard-library>`.
  8. """
  9. from __future__ import absolute_import, division, print_function
  10. import logging
  11. from structlog._base import BoundLoggerBase
  12. from structlog._frames import _find_first_app_frame_and_name, _format_stack
  13. from structlog.exceptions import DropEvent
  14. from six import PY3
  15. class _FixedFindCallerLogger(logging.Logger):
  16. """
  17. Change the behavior of findCaller to cope with structlog's extra frames.
  18. """
  19. def findCaller(self, stack_info=False):
  20. """
  21. Finds the first caller frame outside of structlog so that the caller
  22. info is populated for wrapping stdlib.
  23. This logger gets set as the default one when using LoggerFactory.
  24. """
  25. f, name = _find_first_app_frame_and_name(['logging'])
  26. if PY3:
  27. if stack_info:
  28. sinfo = _format_stack(f)
  29. else:
  30. sinfo = None
  31. return f.f_code.co_filename, f.f_lineno, f.f_code.co_name, sinfo
  32. else:
  33. return f.f_code.co_filename, f.f_lineno, f.f_code.co_name
  34. class BoundLogger(BoundLoggerBase):
  35. """
  36. Python Standard Library version of :class:`structlog.BoundLogger`.
  37. Works exactly like the generic one except that it takes advantage of
  38. knowing the logging methods in advance.
  39. Use it like::
  40. structlog.configure(
  41. wrapper_class=structlog.stdlib.BoundLogger,
  42. )
  43. """
  44. def debug(self, event=None, *args, **kw):
  45. """
  46. Process event and call :meth:`logging.Logger.debug` with the result.
  47. """
  48. return self._proxy_to_logger('debug', event, *args, **kw)
  49. def info(self, event=None, *args, **kw):
  50. """
  51. Process event and call :meth:`logging.Logger.info` with the result.
  52. """
  53. return self._proxy_to_logger('info', event, *args, **kw)
  54. def warning(self, event=None, *args, **kw):
  55. """
  56. Process event and call :meth:`logging.Logger.warning` with the result.
  57. """
  58. return self._proxy_to_logger('warning', event, *args, **kw)
  59. warn = warning
  60. def error(self, event=None, *args, **kw):
  61. """
  62. Process event and call :meth:`logging.Logger.error` with the result.
  63. """
  64. return self._proxy_to_logger('error', event, *args, **kw)
  65. def critical(self, event=None, *args, **kw):
  66. """
  67. Process event and call :meth:`logging.Logger.critical` with the result.
  68. """
  69. return self._proxy_to_logger('critical', event, *args, **kw)
  70. def exception(self, event=None, *args, **kw):
  71. """
  72. Process event and call :meth:`logging.Logger.error` with the result,
  73. after setting ``exc_info`` to `True`.
  74. """
  75. kw['exc_info'] = True
  76. return self.error(event, *args, **kw)
  77. def log(self, level, event, *args, **kw):
  78. """
  79. Process event and call the appropriate logging method depending on
  80. `level`.
  81. """
  82. return self._proxy_to_logger(_LEVEL_TO_NAME[level], event, *args, **kw)
  83. fatal = critical
  84. def _proxy_to_logger(self, method_name, event, *event_args,
  85. **event_kw):
  86. """
  87. Propagate a method call to the wrapped logger.
  88. This is the same as the superclass implementation, except that
  89. it also preserves positional arguments in the `event_dict` so
  90. that the stdblib's support for format strings can be used.
  91. """
  92. if event_args:
  93. event_kw['positional_args'] = event_args
  94. return super(BoundLogger, self)._proxy_to_logger(method_name,
  95. event=event,
  96. **event_kw)
  97. #
  98. # Pass-through methods to mimick the stdlib's logger interface.
  99. #
  100. def setLevel(self, level):
  101. """
  102. Calls :meth:`logging.Logger.setLevel` with unmodified arguments.
  103. """
  104. self._logger.setLevel(level)
  105. def findCaller(self, stack_info=False):
  106. """
  107. Calls :meth:`logging.Logger.findCaller` with unmodified arguments.
  108. """
  109. return self._logger.findCaller(stack_info=stack_info)
  110. def makeRecord(self, name, level, fn, lno, msg, args,
  111. exc_info, func=None, extra=None):
  112. """
  113. Calls :meth:`logging.Logger.makeRecord` with unmodified arguments.
  114. """
  115. return self._logger.makeRecord(name, level, fn, lno, msg, args,
  116. exc_info, func=func, extra=extra)
  117. def handle(self, record):
  118. """
  119. Calls :meth:`logging.Logger.handle` with unmodified arguments.
  120. """
  121. self._logger.handle(record)
  122. def addHandler(self, hdlr):
  123. """
  124. Calls :meth:`logging.Logger.addHandler` with unmodified arguments.
  125. """
  126. self._logger.addHandler(hdlr)
  127. def removeHandler(self, hdlr):
  128. """
  129. Calls :meth:`logging.Logger.removeHandler` with unmodified arguments.
  130. """
  131. self._logger.removeHandler(hdlr)
  132. def hasHandlers(self):
  133. """
  134. Calls :meth:`logging.Logger.hasHandlers` with unmodified arguments.
  135. Exists only in Python 3.
  136. """
  137. return self._logger.hasHandlers()
  138. def callHandlers(self, record):
  139. """
  140. Calls :meth:`logging.Logger.callHandlers` with unmodified arguments.
  141. """
  142. self._logger.callHandlers(record)
  143. def getEffectiveLevel(self):
  144. """
  145. Calls :meth:`logging.Logger.getEffectiveLevel` with unmodified
  146. arguments.
  147. """
  148. return self._logger.getEffectiveLevel()
  149. def isEnabledFor(self, level):
  150. """
  151. Calls :meth:`logging.Logger.isEnabledFor` with unmodified arguments.
  152. """
  153. return self._logger.isEnabledFor(level)
  154. def getChild(self, suffix):
  155. """
  156. Calls :meth:`logging.Logger.getChild` with unmodified arguments.
  157. """
  158. return self._logger.getChild(suffix)
  159. class LoggerFactory(object):
  160. """
  161. Build a standard library logger when an *instance* is called.
  162. Sets a custom logger using :func:`logging.setLoggerClass` so variables in
  163. log format are expanded properly.
  164. >>> from structlog import configure
  165. >>> from structlog.stdlib import LoggerFactory
  166. >>> configure(logger_factory=LoggerFactory())
  167. :param ignore_frame_names: When guessing the name of a logger, skip frames
  168. whose names *start* with one of these. For example, in pyramid
  169. applications you'll want to set it to
  170. ``['venusian', 'pyramid.config']``.
  171. :type ignore_frame_names: `list` of `str`
  172. """
  173. def __init__(self, ignore_frame_names=None):
  174. self._ignore = ignore_frame_names
  175. logging.setLoggerClass(_FixedFindCallerLogger)
  176. def __call__(self, *args):
  177. """
  178. Deduce the caller's module name and create a stdlib logger.
  179. If an optional argument is passed, it will be used as the logger name
  180. instead of guesswork. This optional argument would be passed from the
  181. :func:`structlog.get_logger` call. For example
  182. ``structlog.get_logger('foo')`` would cause this method to be called
  183. with ``'foo'`` as its first positional argument.
  184. :rtype: logging.Logger
  185. .. versionchanged:: 0.4.0
  186. Added support for optional positional arguments. Using the first
  187. one for naming the constructed logger.
  188. """
  189. if args:
  190. return logging.getLogger(args[0])
  191. # We skip all frames that originate from within structlog or one of the
  192. # configured names.
  193. _, name = _find_first_app_frame_and_name(self._ignore)
  194. return logging.getLogger(name)
  195. class PositionalArgumentsFormatter(object):
  196. """
  197. Apply stdlib-like string formatting to the `event` key.
  198. If the `positional_args` key in the event dict is set, it must
  199. contain a tuple that is used for formatting (using the `%s` string
  200. formatting operator) of the value from the `event` key. This works
  201. in the same way as the stdlib handles arguments to the various log
  202. methods: if the tuple contains only a single `dict` argument it is
  203. used for keyword placeholders in the `event` string, otherwise it
  204. will be used for positional placeholders.
  205. `positional_args` is populated by `structlog.stdlib.BoundLogger` or
  206. can be set manually.
  207. The `remove_positional_args` flag can be set to `False` to keep the
  208. `positional_args` key in the event dict; by default it will be
  209. removed from the event dict after formatting a message.
  210. """
  211. def __init__(self, remove_positional_args=True):
  212. self.remove_positional_args = remove_positional_args
  213. def __call__(self, _, __, event_dict):
  214. args = event_dict.get("positional_args")
  215. # Mimick the formatting behaviour of the stdlib's logging
  216. # module, which accepts both positional arguments and a single
  217. # dict argument. The "single dict" check is the same one as the
  218. # stdlib's logging module performs in LogRecord.__init__().
  219. if args:
  220. if len(args) == 1 and isinstance(args[0], dict) and args[0]:
  221. args = args[0]
  222. event_dict["event"] = event_dict["event"] % args
  223. if self.remove_positional_args and args is not None:
  224. del event_dict["positional_args"]
  225. return event_dict
  226. # Adapted from the stdlib
  227. CRITICAL = 50
  228. FATAL = CRITICAL
  229. ERROR = 40
  230. WARNING = 30
  231. WARN = WARNING
  232. INFO = 20
  233. DEBUG = 10
  234. NOTSET = 0
  235. _NAME_TO_LEVEL = {
  236. 'critical': CRITICAL,
  237. 'exception': ERROR,
  238. 'error': ERROR,
  239. 'warn': WARNING,
  240. 'warning': WARNING,
  241. 'info': INFO,
  242. 'debug': DEBUG,
  243. 'notset': NOTSET,
  244. }
  245. _LEVEL_TO_NAME = dict(
  246. (v, k) for k, v in _NAME_TO_LEVEL.items()
  247. if k not in ("warn", "exception", "notset", )
  248. )
  249. def filter_by_level(logger, name, event_dict):
  250. """
  251. Check whether logging is configured to accept messages from this log level.
  252. Should be the first processor if stdlib's filtering by level is used so
  253. possibly expensive processors like exception formatters are avoided in the
  254. first place.
  255. >>> import logging
  256. >>> from structlog.stdlib import filter_by_level
  257. >>> logging.basicConfig(level=logging.WARN)
  258. >>> logger = logging.getLogger()
  259. >>> filter_by_level(logger, 'warn', {})
  260. {}
  261. >>> filter_by_level(logger, 'debug', {})
  262. Traceback (most recent call last):
  263. ...
  264. DropEvent
  265. """
  266. if logger.isEnabledFor(_NAME_TO_LEVEL[name]):
  267. return event_dict
  268. else:
  269. raise DropEvent
  270. def add_log_level(logger, method_name, event_dict):
  271. """
  272. Add the log level to the event dict.
  273. """
  274. if method_name == 'warn':
  275. # The stdlib has an alias
  276. method_name = 'warning'
  277. event_dict['level'] = method_name
  278. return event_dict
  279. def add_logger_name(logger, method_name, event_dict):
  280. """
  281. Add the logger name to the event dict.
  282. """
  283. record = event_dict.get("_record")
  284. if record is None:
  285. event_dict["logger"] = logger.name
  286. else:
  287. event_dict["logger"] = record.name
  288. return event_dict
  289. def render_to_log_kwargs(wrapped_logger, method_name, event_dict):
  290. """
  291. Render `event_dict` into keyword arguments for :func:`logging.log`.
  292. The `event` field is translated into `msg` and the rest of the `event_dict`
  293. is added as `extra`.
  294. This allows you to defer formatting to :mod:`logging`.
  295. .. versionadded:: 17.1.0
  296. """
  297. return {
  298. "msg": event_dict.pop("event"),
  299. "extra": event_dict,
  300. }
  301. class ProcessorFormatter(logging.Formatter):
  302. """
  303. Call ``structlog`` processors on :class:`logging.LogRecord`\ s.
  304. This :class:`logging.Formatter` allows to configure :mod:`logging` to call
  305. *processor* on ``structlog``-borne log entries (origin is determined solely
  306. on the fact whether the ``msg`` field on the :class:`logging.LogRecord` is
  307. a dict or not).
  308. This allows for two interesting use cases:
  309. #. You can format non-``structlog`` log entries.
  310. #. You can multiplex log records into multiple :class:`logging.Handler`\ s.
  311. Please refer to :doc:`standard-library` for examples.
  312. :param callable processor: A ``structlog`` processor.
  313. :param foreign_pre_chain:
  314. If not `None`, it is used as an iterable of processors that is applied
  315. to non-``structlog`` log entries before *processor*. If `None`,
  316. formatting is left to :mod:`logging`. (default: `None`)
  317. :param bool keep_exc_info: ``exc_info`` on :class:`logging.LogRecord`\ s is
  318. added to the ``event_dict`` and removed afterwards. Set this to
  319. ``True`` to keep it on the :class:`logging.LogRecord`. (default: False)
  320. :param bool keep_stack_info: Same as *keep_exc_info* except for Python 3's
  321. ``stack_info``.
  322. :rtype: str
  323. .. versionadded:: 17.1.0
  324. .. versionadded:: 17.2.0 *keep_exc_info* and *keep_stack_info*
  325. """
  326. def __init__(self, processor, foreign_pre_chain=None,
  327. keep_exc_info=False, keep_stack_info=False, *args, **kwargs):
  328. fmt = kwargs.pop("fmt", "%(message)s")
  329. super(ProcessorFormatter, self).__init__(*args, fmt=fmt, **kwargs)
  330. self.processor = processor
  331. self.foreign_pre_chain = foreign_pre_chain
  332. self.keep_exc_info = keep_exc_info
  333. # The and clause saves us checking for PY3 in the formatter.
  334. self.keep_stack_info = keep_stack_info and PY3
  335. def format(self, record):
  336. """
  337. Extract ``structlog``'s `event_dict` from ``record.msg`` and format it.
  338. """
  339. # Make a shallow copy of the record to let other handlers/formatters
  340. # process the original one
  341. record = logging.makeLogRecord(record.__dict__)
  342. if isinstance(record.msg, dict):
  343. # Both attached by wrap_for_formatter
  344. logger = record._logger
  345. meth_name = record._name
  346. # We need to copy because it's possible that the same record gets
  347. # processed by multiple logging formatters. LogRecord.getMessage
  348. # would transform our dict into a str.
  349. ed = record.msg.copy()
  350. else:
  351. logger = None
  352. meth_name = record.levelname.lower()
  353. ed = {"event": record.getMessage(), "_record": record}
  354. record.args = ()
  355. # Add stack-related attributes to event_dict and unset them
  356. # on the record copy so that the base implementation wouldn't
  357. # append stacktraces to the output.
  358. if record.exc_info:
  359. ed["exc_info"] = record.exc_info
  360. if PY3 and record.stack_info:
  361. ed["stack_info"] = record.stack_info
  362. if not self.keep_exc_info:
  363. record.exc_text = None
  364. record.exc_info = None
  365. if not self.keep_stack_info:
  366. record.stack_info = None
  367. # Non-structlog allows to run through a chain to prepare it for the
  368. # final processor (e.g. adding timestamps and log levels).
  369. for proc in self.foreign_pre_chain or ():
  370. ed = proc(None, meth_name, ed)
  371. del ed["_record"]
  372. record.msg = self.processor(logger, meth_name, ed)
  373. return super(ProcessorFormatter, self).format(record)
  374. @staticmethod
  375. def wrap_for_formatter(logger, name, event_dict):
  376. """
  377. Wrap *logger*, *name*, and *event_dict*.
  378. The result is later unpacked by :class:`ProcessorFormatter` when
  379. formatting log entries.
  380. Use this static method as the renderer (i.e. final processor) if you
  381. want to use :class:`ProcessorFormatter` in your :mod:`logging`
  382. configuration.
  383. """
  384. return (event_dict,), {"extra": {"_logger": logger, "_name": name}}