test_format.py 12 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431
  1. # Copyright (c) Twisted Matrix Laboratories.
  2. # See LICENSE for details.
  3. """
  4. Test cases for L{twisted.logger._format}.
  5. """
  6. from twisted.python.test.test_tzhelper import mktime, addTZCleanup, setTZ
  7. try:
  8. from time import tzset
  9. # We should upgrade to a version of pyflakes that does not require this.
  10. tzset
  11. except ImportError:
  12. tzset = None
  13. from twisted.trial import unittest
  14. from twisted.trial.unittest import SkipTest
  15. from twisted.python.compat import _PY3, unicode
  16. from .._levels import LogLevel
  17. from .._format import (
  18. formatEvent, formatUnformattableEvent, formatTime,
  19. formatEventAsClassicLogText, formatWithCall,
  20. )
  21. class FormattingTests(unittest.TestCase):
  22. """
  23. Tests for basic event formatting functions.
  24. """
  25. def test_formatEvent(self):
  26. """
  27. L{formatEvent} will format an event according to several rules:
  28. - A string with no formatting instructions will be passed straight
  29. through.
  30. - PEP 3101 strings will be formatted using the keys and values of
  31. the event as named fields.
  32. - PEP 3101 keys ending with C{()} will be treated as instructions
  33. to call that key (which ought to be a callable) before
  34. formatting.
  35. L{formatEvent} will always return L{unicode}, and if given bytes, will
  36. always treat its format string as UTF-8 encoded.
  37. """
  38. def format(logFormat, **event):
  39. event["log_format"] = logFormat
  40. result = formatEvent(event)
  41. self.assertIs(type(result), unicode)
  42. return result
  43. self.assertEqual(u"", format(b""))
  44. self.assertEqual(u"", format(u""))
  45. self.assertEqual(u"abc", format("{x}", x="abc"))
  46. self.assertEqual(
  47. u"no, yes.",
  48. format(
  49. "{not_called}, {called()}.",
  50. not_called="no", called=lambda: "yes"
  51. )
  52. )
  53. self.assertEqual(u"S\xe1nchez", format(b"S\xc3\xa1nchez"))
  54. badResult = format(b"S\xe1nchez")
  55. self.assertIn(u"Unable to format event", badResult)
  56. maybeResult = format(b"S{a!s}nchez", a=b"\xe1")
  57. # The behavior of unicode.format("{x}", x=bytes) differs on py2 and
  58. # py3. Perhaps we should make our modified formatting more consistent
  59. # than this? -glyph
  60. if not _PY3:
  61. self.assertIn(u"Unable to format event", maybeResult)
  62. else:
  63. self.assertIn(u"Sb'\\xe1'nchez", maybeResult)
  64. xe1 = unicode(repr(b"\xe1"))
  65. self.assertIn(u"S" + xe1 + "nchez", format(b"S{a!r}nchez", a=b"\xe1"))
  66. def test_formatEventNoFormat(self):
  67. """
  68. Formatting an event with no format.
  69. """
  70. event = dict(foo=1, bar=2)
  71. result = formatEvent(event)
  72. self.assertEqual(u"", result)
  73. def test_formatEventWeirdFormat(self):
  74. """
  75. Formatting an event with a bogus format.
  76. """
  77. event = dict(log_format=object(), foo=1, bar=2)
  78. result = formatEvent(event)
  79. self.assertIn("Log format must be unicode or bytes", result)
  80. self.assertIn(repr(event), result)
  81. def test_formatUnformattableEvent(self):
  82. """
  83. Formatting an event that's just plain out to get us.
  84. """
  85. event = dict(log_format="{evil()}", evil=lambda: 1 / 0)
  86. result = formatEvent(event)
  87. self.assertIn("Unable to format event", result)
  88. self.assertIn(repr(event), result)
  89. def test_formatUnformattableEventWithUnformattableKey(self):
  90. """
  91. Formatting an unformattable event that has an unformattable key.
  92. """
  93. event = {
  94. "log_format": "{evil()}",
  95. "evil": lambda: 1 / 0,
  96. Unformattable(): "gurk",
  97. }
  98. result = formatEvent(event)
  99. self.assertIn("MESSAGE LOST: unformattable object logged:", result)
  100. self.assertIn("Recoverable data:", result)
  101. self.assertIn("Exception during formatting:", result)
  102. def test_formatUnformattableEventWithUnformattableValue(self):
  103. """
  104. Formatting an unformattable event that has an unformattable value.
  105. """
  106. event = dict(
  107. log_format="{evil()}",
  108. evil=lambda: 1 / 0,
  109. gurk=Unformattable(),
  110. )
  111. result = formatEvent(event)
  112. self.assertIn("MESSAGE LOST: unformattable object logged:", result)
  113. self.assertIn("Recoverable data:", result)
  114. self.assertIn("Exception during formatting:", result)
  115. def test_formatUnformattableEventWithUnformattableErrorOMGWillItStop(self):
  116. """
  117. Formatting an unformattable event that has an unformattable value.
  118. """
  119. event = dict(
  120. log_format="{evil()}",
  121. evil=lambda: 1 / 0,
  122. recoverable="okay",
  123. )
  124. # Call formatUnformattableEvent() directly with a bogus exception.
  125. result = formatUnformattableEvent(event, Unformattable())
  126. self.assertIn("MESSAGE LOST: unformattable object logged:", result)
  127. self.assertIn(repr("recoverable") + " = " + repr("okay"), result)
  128. class TimeFormattingTests(unittest.TestCase):
  129. """
  130. Tests for time formatting functions.
  131. """
  132. def setUp(self):
  133. addTZCleanup(self)
  134. def test_formatTimeWithDefaultFormat(self):
  135. """
  136. Default time stamp format is RFC 3339 and offset respects the timezone
  137. as set by the standard C{TZ} environment variable and L{tzset} API.
  138. """
  139. if tzset is None:
  140. raise SkipTest(
  141. "Platform cannot change timezone; unable to verify offsets."
  142. )
  143. def testForTimeZone(name, expectedDST, expectedSTD):
  144. setTZ(name)
  145. localDST = mktime((2006, 6, 30, 0, 0, 0, 4, 181, 1))
  146. localSTD = mktime((2007, 1, 31, 0, 0, 0, 2, 31, 0))
  147. self.assertEqual(formatTime(localDST), expectedDST)
  148. self.assertEqual(formatTime(localSTD), expectedSTD)
  149. # UTC
  150. testForTimeZone(
  151. "UTC+00",
  152. u"2006-06-30T00:00:00+0000",
  153. u"2007-01-31T00:00:00+0000",
  154. )
  155. # West of UTC
  156. testForTimeZone(
  157. "EST+05EDT,M4.1.0,M10.5.0",
  158. u"2006-06-30T00:00:00-0400",
  159. u"2007-01-31T00:00:00-0500",
  160. )
  161. # East of UTC
  162. testForTimeZone(
  163. "CEST-01CEDT,M4.1.0,M10.5.0",
  164. u"2006-06-30T00:00:00+0200",
  165. u"2007-01-31T00:00:00+0100",
  166. )
  167. # No DST
  168. testForTimeZone(
  169. "CST+06",
  170. u"2006-06-30T00:00:00-0600",
  171. u"2007-01-31T00:00:00-0600",
  172. )
  173. def test_formatTimeWithNoTime(self):
  174. """
  175. If C{when} argument is L{None}, we get the default output.
  176. """
  177. self.assertEqual(formatTime(None), u"-")
  178. self.assertEqual(formatTime(None, default=u"!"), u"!")
  179. def test_formatTimeWithNoFormat(self):
  180. """
  181. If C{timeFormat} argument is L{None}, we get the default output.
  182. """
  183. t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, 1))
  184. self.assertEqual(formatTime(t, timeFormat=None), u"-")
  185. self.assertEqual(formatTime(t, timeFormat=None, default=u"!"), u"!")
  186. def test_formatTimeWithAlternateTimeFormat(self):
  187. """
  188. Alternate time format in output.
  189. """
  190. t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, 1))
  191. self.assertEqual(formatTime(t, timeFormat="%Y/%W"), u"2013/38")
  192. def test_formatTimePercentF(self):
  193. """
  194. "%f" supported in time format.
  195. """
  196. self.assertEqual(formatTime(1.23456, timeFormat="%f"), u"234560")
  197. class ClassicLogFormattingTests(unittest.TestCase):
  198. """
  199. Tests for classic text log event formatting functions.
  200. """
  201. def test_formatTimeDefault(self):
  202. """
  203. Time is first field. Default time stamp format is RFC 3339 and offset
  204. respects the timezone as set by the standard C{TZ} environment variable
  205. and L{tzset} API.
  206. """
  207. if tzset is None:
  208. raise SkipTest(
  209. "Platform cannot change timezone; unable to verify offsets."
  210. )
  211. addTZCleanup(self)
  212. setTZ("UTC+00")
  213. t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, 1))
  214. event = dict(log_format=u"XYZZY", log_time=t)
  215. self.assertEqual(
  216. formatEventAsClassicLogText(event),
  217. u"2013-09-24T11:40:47+0000 [-#-] XYZZY\n",
  218. )
  219. def test_formatTimeCustom(self):
  220. """
  221. Time is first field. Custom formatting function is an optional
  222. argument.
  223. """
  224. formatTime = lambda t: u"__{0}__".format(t)
  225. event = dict(log_format=u"XYZZY", log_time=12345)
  226. self.assertEqual(
  227. formatEventAsClassicLogText(event, formatTime=formatTime),
  228. u"__12345__ [-#-] XYZZY\n",
  229. )
  230. def test_formatNamespace(self):
  231. """
  232. Namespace is first part of second field.
  233. """
  234. event = dict(log_format=u"XYZZY", log_namespace="my.namespace")
  235. self.assertEqual(
  236. formatEventAsClassicLogText(event),
  237. u"- [my.namespace#-] XYZZY\n",
  238. )
  239. def test_formatLevel(self):
  240. """
  241. Level is second part of second field.
  242. """
  243. event = dict(log_format=u"XYZZY", log_level=LogLevel.warn)
  244. self.assertEqual(
  245. formatEventAsClassicLogText(event),
  246. u"- [-#warn] XYZZY\n",
  247. )
  248. def test_formatSystem(self):
  249. """
  250. System is second field.
  251. """
  252. event = dict(log_format=u"XYZZY", log_system=u"S.Y.S.T.E.M.")
  253. self.assertEqual(
  254. formatEventAsClassicLogText(event),
  255. u"- [S.Y.S.T.E.M.] XYZZY\n",
  256. )
  257. def test_formatSystemRulz(self):
  258. """
  259. System is not supplanted by namespace and level.
  260. """
  261. event = dict(
  262. log_format=u"XYZZY",
  263. log_namespace="my.namespace",
  264. log_level=LogLevel.warn,
  265. log_system=u"S.Y.S.T.E.M.",
  266. )
  267. self.assertEqual(
  268. formatEventAsClassicLogText(event),
  269. u"- [S.Y.S.T.E.M.] XYZZY\n",
  270. )
  271. def test_formatSystemUnformattable(self):
  272. """
  273. System is not supplanted by namespace and level.
  274. """
  275. event = dict(log_format=u"XYZZY", log_system=Unformattable())
  276. self.assertEqual(
  277. formatEventAsClassicLogText(event),
  278. u"- [UNFORMATTABLE] XYZZY\n",
  279. )
  280. def test_formatFormat(self):
  281. """
  282. Formatted event is last field.
  283. """
  284. event = dict(log_format=u"id:{id}", id="123")
  285. self.assertEqual(
  286. formatEventAsClassicLogText(event),
  287. u"- [-#-] id:123\n",
  288. )
  289. def test_formatNoFormat(self):
  290. """
  291. No format string.
  292. """
  293. event = dict(id="123")
  294. self.assertIs(
  295. formatEventAsClassicLogText(event),
  296. None
  297. )
  298. def test_formatEmptyFormat(self):
  299. """
  300. Empty format string.
  301. """
  302. event = dict(log_format="", id="123")
  303. self.assertIs(
  304. formatEventAsClassicLogText(event),
  305. None
  306. )
  307. def test_formatFormatMultiLine(self):
  308. """
  309. If the formatted event has newlines, indent additional lines.
  310. """
  311. event = dict(log_format=u'XYZZY\nA hollow voice says:\n"Plugh"')
  312. self.assertEqual(
  313. formatEventAsClassicLogText(event),
  314. u'- [-#-] XYZZY\n\tA hollow voice says:\n\t"Plugh"\n',
  315. )
  316. class FormatFieldTests(unittest.TestCase):
  317. """
  318. Tests for format field functions.
  319. """
  320. def test_formatWithCall(self):
  321. """
  322. L{formatWithCall} is an extended version of L{unicode.format} that
  323. will interpret a set of parentheses "C{()}" at the end of a format key
  324. to mean that the format key ought to be I{called} rather than
  325. stringified.
  326. """
  327. self.assertEqual(
  328. formatWithCall(
  329. u"Hello, {world}. {callme()}.",
  330. dict(world="earth", callme=lambda: "maybe")
  331. ),
  332. "Hello, earth. maybe."
  333. )
  334. self.assertEqual(
  335. formatWithCall(
  336. u"Hello, {repr()!r}.",
  337. dict(repr=lambda: "repr")
  338. ),
  339. "Hello, 'repr'."
  340. )
  341. class Unformattable(object):
  342. """
  343. An object that raises an exception from C{__repr__}.
  344. """
  345. def __repr__(self):
  346. return str(1 / 0)