_format.py 12 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421
  1. # -*- test-case-name: twisted.logger.test.test_format -*-
  2. # Copyright (c) Twisted Matrix Laboratories.
  3. # See LICENSE for details.
  4. """
  5. Tools for formatting logging events.
  6. """
  7. from datetime import datetime as DateTime
  8. from twisted.python.compat import unicode
  9. from twisted.python.failure import Failure
  10. from twisted.python.reflect import safe_repr
  11. from twisted.python._tzhelper import FixedOffsetTimeZone
  12. from ._flatten import flatFormat, aFormatter
  13. timeFormatRFC3339 = "%Y-%m-%dT%H:%M:%S%z"
  14. def formatEvent(event):
  15. """
  16. Formats an event as a L{unicode}, using the format in
  17. C{event["log_format"]}.
  18. This implementation should never raise an exception; if the formatting
  19. cannot be done, the returned string will describe the event generically so
  20. that a useful message is emitted regardless.
  21. @param event: A logging event.
  22. @type event: L{dict}
  23. @return: A formatted string.
  24. @rtype: L{unicode}
  25. """
  26. return eventAsText(
  27. event,
  28. includeTraceback=False,
  29. includeTimestamp=False,
  30. includeSystem=False,
  31. )
  32. def formatUnformattableEvent(event, error):
  33. """
  34. Formats an event as a L{unicode} that describes the event generically and a
  35. formatting error.
  36. @param event: A logging event.
  37. @type event: L{dict}
  38. @param error: The formatting error.
  39. @type error: L{Exception}
  40. @return: A formatted string.
  41. @rtype: L{unicode}
  42. """
  43. try:
  44. return (
  45. u"Unable to format event {event!r}: {error}"
  46. .format(event=event, error=error)
  47. )
  48. except BaseException:
  49. # Yikes, something really nasty happened.
  50. #
  51. # Try to recover as much formattable data as possible; hopefully at
  52. # least the namespace is sane, which will help you find the offending
  53. # logger.
  54. failure = Failure()
  55. text = u", ".join(
  56. u" = ".join((safe_repr(key), safe_repr(value)))
  57. for key, value in event.items()
  58. )
  59. return (
  60. u"MESSAGE LOST: unformattable object logged: {error}\n"
  61. u"Recoverable data: {text}\n"
  62. u"Exception during formatting:\n{failure}"
  63. .format(error=safe_repr(error), failure=failure, text=text)
  64. )
  65. def formatTime(when, timeFormat=timeFormatRFC3339, default=u"-"):
  66. """
  67. Format a timestamp as text.
  68. Example::
  69. >>> from time import time
  70. >>> from twisted.logger import formatTime
  71. >>>
  72. >>> t = time()
  73. >>> formatTime(t)
  74. u'2013-10-22T14:19:11-0700'
  75. >>> formatTime(t, timeFormat="%Y/%W") # Year and week number
  76. u'2013/42'
  77. >>>
  78. @param when: A timestamp.
  79. @type then: L{float}
  80. @param timeFormat: A time format.
  81. @type timeFormat: L{unicode} or L{None}
  82. @param default: Text to return if C{when} or C{timeFormat} is L{None}.
  83. @type default: L{unicode}
  84. @return: A formatted time.
  85. @rtype: L{unicode}
  86. """
  87. if (timeFormat is None or when is None):
  88. return default
  89. else:
  90. tz = FixedOffsetTimeZone.fromLocalTimeStamp(when)
  91. datetime = DateTime.fromtimestamp(when, tz)
  92. return unicode(datetime.strftime(timeFormat))
  93. def formatEventAsClassicLogText(event, formatTime=formatTime):
  94. """
  95. Format an event as a line of human-readable text for, e.g. traditional log
  96. file output.
  97. The output format is C{u"{timeStamp} [{system}] {event}\\n"}, where:
  98. - C{timeStamp} is computed by calling the given C{formatTime} callable
  99. on the event's C{"log_time"} value
  100. - C{system} is the event's C{"log_system"} value, if set, otherwise,
  101. the C{"log_namespace"} and C{"log_level"}, joined by a C{u"#"}. Each
  102. defaults to C{u"-"} is not set.
  103. - C{event} is the event, as formatted by L{formatEvent}.
  104. Example::
  105. >>> from __future__ import print_function
  106. >>> from time import time
  107. >>> from twisted.logger import formatEventAsClassicLogText
  108. >>> from twisted.logger import LogLevel
  109. >>>
  110. >>> formatEventAsClassicLogText(dict()) # No format, returns None
  111. >>> formatEventAsClassicLogText(dict(log_format=u"Hello!"))
  112. u'- [-#-] Hello!\\n'
  113. >>> formatEventAsClassicLogText(dict(
  114. ... log_format=u"Hello!",
  115. ... log_time=time(),
  116. ... log_namespace="my_namespace",
  117. ... log_level=LogLevel.info,
  118. ... ))
  119. u'2013-10-22T17:30:02-0700 [my_namespace#info] Hello!\\n'
  120. >>> formatEventAsClassicLogText(dict(
  121. ... log_format=u"Hello!",
  122. ... log_time=time(),
  123. ... log_system="my_system",
  124. ... ))
  125. u'2013-11-11T17:22:06-0800 [my_system] Hello!\\n'
  126. >>>
  127. @param event: an event.
  128. @type event: L{dict}
  129. @param formatTime: A time formatter
  130. @type formatTime: L{callable} that takes an C{event} argument and returns
  131. a L{unicode}
  132. @return: A formatted event, or L{None} if no output is appropriate.
  133. @rtype: L{unicode} or L{None}
  134. """
  135. eventText = eventAsText(event, formatTime=formatTime)
  136. if not eventText:
  137. return None
  138. eventText = eventText.replace(u"\n", u"\n\t")
  139. return eventText + u"\n"
  140. class CallMapping(object):
  141. """
  142. Read-only mapping that turns a C{()}-suffix in key names into an invocation
  143. of the key rather than a lookup of the key.
  144. Implementation support for L{formatWithCall}.
  145. """
  146. def __init__(self, submapping):
  147. """
  148. @param submapping: Another read-only mapping which will be used to look
  149. up items.
  150. """
  151. self._submapping = submapping
  152. def __getitem__(self, key):
  153. """
  154. Look up an item in the submapping for this L{CallMapping}, calling it
  155. if C{key} ends with C{"()"}.
  156. """
  157. callit = key.endswith(u"()")
  158. realKey = key[:-2] if callit else key
  159. value = self._submapping[realKey]
  160. if callit:
  161. value = value()
  162. return value
  163. def formatWithCall(formatString, mapping):
  164. """
  165. Format a string like L{unicode.format}, but:
  166. - taking only a name mapping; no positional arguments
  167. - with the additional syntax that an empty set of parentheses
  168. correspond to a formatting item that should be called, and its result
  169. C{str}'d, rather than calling C{str} on the element directly as
  170. normal.
  171. For example::
  172. >>> formatWithCall("{string}, {function()}.",
  173. ... dict(string="just a string",
  174. ... function=lambda: "a function"))
  175. 'just a string, a function.'
  176. @param formatString: A PEP-3101 format string.
  177. @type formatString: L{unicode}
  178. @param mapping: A L{dict}-like object to format.
  179. @return: The string with formatted values interpolated.
  180. @rtype: L{unicode}
  181. """
  182. return unicode(
  183. aFormatter.vformat(formatString, (), CallMapping(mapping))
  184. )
  185. def _formatEvent(event):
  186. """
  187. Formats an event as a L{unicode}, using the format in
  188. C{event["log_format"]}.
  189. This implementation should never raise an exception; if the formatting
  190. cannot be done, the returned string will describe the event generically so
  191. that a useful message is emitted regardless.
  192. @param event: A logging event.
  193. @type event: L{dict}
  194. @return: A formatted string.
  195. @rtype: L{unicode}
  196. """
  197. try:
  198. if "log_flattened" in event:
  199. return flatFormat(event)
  200. format = event.get("log_format", None)
  201. if format is None:
  202. return u""
  203. # Make sure format is unicode.
  204. if isinstance(format, bytes):
  205. # If we get bytes, assume it's UTF-8 bytes
  206. format = format.decode("utf-8")
  207. elif not isinstance(format, unicode):
  208. raise TypeError(
  209. "Log format must be unicode or bytes, not {0!r}".format(format)
  210. )
  211. return formatWithCall(format, event)
  212. except BaseException as e:
  213. return formatUnformattableEvent(event, e)
  214. def _formatTraceback(failure):
  215. """
  216. Format a failure traceback, assuming UTF-8 and using a replacement
  217. strategy for errors. Every effort is made to provide a usable
  218. traceback, but should not that not be possible, a message and the
  219. captured exception are logged.
  220. @param failure: The failure to retrieve a traceback from.
  221. @type failure: L{twisted.python.failure.Failure}
  222. @return: The formatted traceback.
  223. @rtype: L{unicode}
  224. """
  225. try:
  226. traceback = failure.getTraceback()
  227. if isinstance(traceback, bytes):
  228. traceback = traceback.decode('utf-8', errors='replace')
  229. except BaseException as e:
  230. traceback = (
  231. u"(UNABLE TO OBTAIN TRACEBACK FROM EVENT):" + unicode(e)
  232. )
  233. return traceback
  234. def _formatSystem(event):
  235. """
  236. Format the system specified in the event in the "log_system" key if set,
  237. otherwise the C{"log_namespace"} and C{"log_level"}, joined by a C{u"#"}.
  238. Each defaults to C{u"-"} is not set. If formatting fails completely,
  239. "UNFORMATTABLE" is returned.
  240. @param event: The event containing the system specification.
  241. @type event: L{dict}
  242. @return: A formatted string representing the "log_system" key.
  243. @rtype: L{unicode}
  244. """
  245. system = event.get("log_system", None)
  246. if system is None:
  247. level = event.get("log_level", None)
  248. if level is None:
  249. levelName = u"-"
  250. else:
  251. levelName = level.name
  252. system = u"{namespace}#{level}".format(
  253. namespace=event.get("log_namespace", u"-"),
  254. level=levelName,
  255. )
  256. else:
  257. try:
  258. system = unicode(system)
  259. except Exception:
  260. system = u"UNFORMATTABLE"
  261. return system
  262. def eventAsText(
  263. event,
  264. includeTraceback=True,
  265. includeTimestamp=True,
  266. includeSystem=True,
  267. formatTime=formatTime,
  268. ):
  269. r"""
  270. Format an event as a unicode string. Optionally, attach timestamp,
  271. traceback, and system information.
  272. The full output format is:
  273. C{u"{timeStamp} [{system}] {event}\n{traceback}\n"} where:
  274. - C{timeStamp} is the event's C{"log_time"} value formatted with
  275. the provided C{formatTime} callable.
  276. - C{system} is the event's C{"log_system"} value, if set, otherwise,
  277. the C{"log_namespace"} and C{"log_level"}, joined by a C{u"#"}. Each
  278. defaults to C{u"-"} is not set.
  279. - C{event} is the event, as formatted by L{formatEvent}.
  280. - C{traceback} is the traceback if the event contains a
  281. C{"log_failure"} key. In the event the original traceback cannot
  282. be formatted, a message indicating the failure will be substituted.
  283. If the event cannot be formatted, and no traceback exists, an empty string
  284. is returned, even if includeSystem or includeTimestamp are true.
  285. @param event: A logging event.
  286. @type event: L{dict}
  287. @param includeTraceback: If true and a C{"log_failure"} key exists, append
  288. a traceback.
  289. @type includeTraceback: L{bool}
  290. @param includeTimestamp: If true include a formatted timestamp before the
  291. event.
  292. @type includeTimestamp: L{bool}
  293. @param includeSystem: If true, include the event's C{"log_system"} value.
  294. @type includeSystem: L{bool}
  295. @param formatTime: A time formatter
  296. @type formatTime: L{callable} that takes an C{event} argument and returns
  297. a L{unicode}
  298. @return: A formatted string with specified options.
  299. @rtype: L{unicode}
  300. @since: Twisted 18.9.0
  301. """
  302. eventText = _formatEvent(event)
  303. if includeTraceback and 'log_failure' in event:
  304. f = event['log_failure']
  305. traceback = _formatTraceback(f)
  306. eventText = u"\n".join((eventText, traceback))
  307. if not eventText:
  308. return eventText
  309. timeStamp = u""
  310. if includeTimestamp:
  311. timeStamp = u"".join([formatTime(event.get("log_time", None)), " "])
  312. system = u""
  313. if includeSystem:
  314. system = u"".join([
  315. u"[",
  316. _formatSystem(event),
  317. u"]",
  318. u" "
  319. ])
  320. return u"{timeStamp}{system}{eventText}".format(
  321. timeStamp=timeStamp,
  322. system=system,
  323. eventText=eventText,
  324. )