logging_extra.py 6.4 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247
  1. import io
  2. import os
  3. import sys
  4. import copy
  5. import json
  6. import time
  7. import uuid
  8. import socket
  9. import logging
  10. import traceback
  11. from threading import local
  12. from collections import OrderedDict
  13. from contextlib import contextmanager
  14. LOG_TIMESTAMPS = "LOG_TIMESTAMPS" in os.environ
  15. def json_handler(obj):
  16. # if isinstance(obj, (datetime.date, datetime.time)):
  17. # return obj.isoformat()
  18. return repr(obj)
  19. def json_robust_dumps(obj):
  20. return json.dumps(obj, default=json_handler)
  21. class NiceOrderedDict(OrderedDict):
  22. def __str__(self):
  23. return json_robust_dumps(self)
  24. class SwagFormatter(logging.Formatter):
  25. def __init__(self, swaglogger):
  26. logging.Formatter.__init__(self, None, '%a %b %d %H:%M:%S %Z %Y')
  27. self.swaglogger = swaglogger
  28. self.host = socket.gethostname()
  29. def format_dict(self, record):
  30. record_dict = NiceOrderedDict()
  31. if isinstance(record.msg, dict):
  32. record_dict['msg'] = record.msg
  33. else:
  34. try:
  35. record_dict['msg'] = record.getMessage()
  36. except (ValueError, TypeError):
  37. record_dict['msg'] = [record.msg]+record.args
  38. record_dict['ctx'] = self.swaglogger.get_ctx()
  39. if record.exc_info:
  40. record_dict['exc_info'] = self.formatException(record.exc_info)
  41. record_dict['level'] = record.levelname
  42. record_dict['levelnum'] = record.levelno
  43. record_dict['name'] = record.name
  44. record_dict['filename'] = record.filename
  45. record_dict['lineno'] = record.lineno
  46. record_dict['pathname'] = record.pathname
  47. record_dict['module'] = record.module
  48. record_dict['funcName'] = record.funcName
  49. record_dict['host'] = self.host
  50. record_dict['process'] = record.process
  51. record_dict['thread'] = record.thread
  52. record_dict['threadName'] = record.threadName
  53. record_dict['created'] = record.created
  54. return record_dict
  55. def format(self, record):
  56. if self.swaglogger is None:
  57. raise Exception("must set swaglogger before calling format()")
  58. return json_robust_dumps(self.format_dict(record))
  59. class SwagLogFileFormatter(SwagFormatter):
  60. def fix_kv(self, k, v):
  61. # append type to names to preserve legacy naming in logs
  62. # avoids overlapping key namespaces with different types
  63. # e.g. log.info() creates 'msg' -> 'msg$s'
  64. # log.event() creates 'msg.health.logMonoTime' -> 'msg.health.logMonoTime$i'
  65. # because overlapping namespace 'msg' caused problems
  66. if isinstance(v, (str, bytes)):
  67. k += "$s"
  68. elif isinstance(v, float):
  69. k += "$f"
  70. elif isinstance(v, bool):
  71. k += "$b"
  72. elif isinstance(v, int):
  73. k += "$i"
  74. elif isinstance(v, dict):
  75. nv = {}
  76. for ik, iv in v.items():
  77. ik, iv = self.fix_kv(ik, iv)
  78. nv[ik] = iv
  79. v = nv
  80. elif isinstance(v, list):
  81. k += "$a"
  82. return k, v
  83. def format(self, record):
  84. if isinstance(record, str):
  85. v = json.loads(record)
  86. else:
  87. v = self.format_dict(record)
  88. mk, mv = self.fix_kv('msg', v['msg'])
  89. del v['msg']
  90. v[mk] = mv
  91. v['id'] = uuid.uuid4().hex
  92. return json_robust_dumps(v)
  93. class SwagErrorFilter(logging.Filter):
  94. def filter(self, record):
  95. return record.levelno < logging.ERROR
  96. def _tmpfunc():
  97. return 0
  98. def _srcfile():
  99. return os.path.normcase(_tmpfunc.__code__.co_filename)
  100. class SwagLogger(logging.Logger):
  101. def __init__(self):
  102. logging.Logger.__init__(self, "swaglog")
  103. self.global_ctx = {}
  104. self.log_local = local()
  105. self.log_local.ctx = {}
  106. def local_ctx(self):
  107. try:
  108. return self.log_local.ctx
  109. except AttributeError:
  110. self.log_local.ctx = {}
  111. return self.log_local.ctx
  112. def get_ctx(self):
  113. return dict(self.local_ctx(), **self.global_ctx)
  114. @contextmanager
  115. def ctx(self, **kwargs):
  116. old_ctx = self.local_ctx()
  117. self.log_local.ctx = copy.copy(old_ctx) or {}
  118. self.log_local.ctx.update(kwargs)
  119. try:
  120. yield
  121. finally:
  122. self.log_local.ctx = old_ctx
  123. def bind(self, **kwargs):
  124. self.local_ctx().update(kwargs)
  125. def bind_global(self, **kwargs):
  126. self.global_ctx.update(kwargs)
  127. def event(self, event, *args, **kwargs):
  128. evt = NiceOrderedDict()
  129. evt['event'] = event
  130. if args:
  131. evt['args'] = args
  132. evt.update(kwargs)
  133. if 'error' in kwargs:
  134. self.error(evt)
  135. elif 'debug' in kwargs:
  136. self.debug(evt)
  137. else:
  138. self.info(evt)
  139. def timestamp(self, event_name):
  140. if LOG_TIMESTAMPS:
  141. t = time.monotonic()
  142. tstp = NiceOrderedDict()
  143. tstp['timestamp'] = NiceOrderedDict()
  144. tstp['timestamp']["event"] = event_name
  145. tstp['timestamp']["time"] = t*1e9
  146. self.debug(tstp)
  147. def findCaller(self, stack_info=False, stacklevel=1):
  148. """
  149. Find the stack frame of the caller so that we can note the source
  150. file name, line number and function name.
  151. """
  152. f = sys._getframe(3)
  153. #On some versions of IronPython, currentframe() returns None if
  154. #IronPython isn't run with -X:Frames.
  155. if f is not None:
  156. f = f.f_back
  157. orig_f = f
  158. while f and stacklevel > 1:
  159. f = f.f_back
  160. stacklevel -= 1
  161. if not f:
  162. f = orig_f
  163. rv = "(unknown file)", 0, "(unknown function)", None
  164. while hasattr(f, "f_code"):
  165. co = f.f_code
  166. filename = os.path.normcase(co.co_filename)
  167. # TODO: is this pylint exception correct?
  168. if filename == _srcfile:
  169. f = f.f_back
  170. continue
  171. sinfo = None
  172. if stack_info:
  173. sio = io.StringIO()
  174. sio.write('Stack (most recent call last):\n')
  175. traceback.print_stack(f, file=sio)
  176. sinfo = sio.getvalue()
  177. if sinfo[-1] == '\n':
  178. sinfo = sinfo[:-1]
  179. sio.close()
  180. rv = (co.co_filename, f.f_lineno, co.co_name, sinfo)
  181. break
  182. return rv
  183. if __name__ == "__main__":
  184. log = SwagLogger()
  185. stdout_handler = logging.StreamHandler(sys.stdout)
  186. stdout_handler.setLevel(logging.INFO)
  187. stdout_handler.addFilter(SwagErrorFilter())
  188. log.addHandler(stdout_handler)
  189. stderr_handler = logging.StreamHandler(sys.stderr)
  190. stderr_handler.setLevel(logging.ERROR)
  191. log.addHandler(stderr_handler)
  192. log.info("asdasd %s", "a")
  193. log.info({'wut': 1})
  194. log.warning("warning")
  195. log.error("error")
  196. log.critical("critical")
  197. log.event("test", x="y")
  198. with log.ctx():
  199. stdout_handler.setFormatter(SwagFormatter(log))
  200. stderr_handler.setFormatter(SwagFormatter(log))
  201. log.bind(user="some user")
  202. log.info("in req")
  203. print("")
  204. log.warning("warning")
  205. print("")
  206. log.error("error")
  207. print("")
  208. log.critical("critical")
  209. print("")
  210. log.event("do_req", a=1, b="c")