glogging.py 15 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473
  1. #
  2. # This file is part of gunicorn released under the MIT license.
  3. # See the NOTICE for more information.
  4. import base64
  5. import binascii
  6. import json
  7. import time
  8. import logging
  9. logging.Logger.manager.emittedNoHandlerWarning = 1 # noqa
  10. from logging.config import dictConfig
  11. from logging.config import fileConfig
  12. import os
  13. import socket
  14. import sys
  15. import threading
  16. import traceback
  17. from gunicorn import util
  18. # syslog facility codes
  19. SYSLOG_FACILITIES = {
  20. "auth": 4,
  21. "authpriv": 10,
  22. "cron": 9,
  23. "daemon": 3,
  24. "ftp": 11,
  25. "kern": 0,
  26. "lpr": 6,
  27. "mail": 2,
  28. "news": 7,
  29. "security": 4, # DEPRECATED
  30. "syslog": 5,
  31. "user": 1,
  32. "uucp": 8,
  33. "local0": 16,
  34. "local1": 17,
  35. "local2": 18,
  36. "local3": 19,
  37. "local4": 20,
  38. "local5": 21,
  39. "local6": 22,
  40. "local7": 23
  41. }
  42. CONFIG_DEFAULTS = {
  43. "version": 1,
  44. "disable_existing_loggers": False,
  45. "root": {"level": "INFO", "handlers": ["console"]},
  46. "loggers": {
  47. "gunicorn.error": {
  48. "level": "INFO",
  49. "handlers": ["error_console"],
  50. "propagate": True,
  51. "qualname": "gunicorn.error"
  52. },
  53. "gunicorn.access": {
  54. "level": "INFO",
  55. "handlers": ["console"],
  56. "propagate": True,
  57. "qualname": "gunicorn.access"
  58. }
  59. },
  60. "handlers": {
  61. "console": {
  62. "class": "logging.StreamHandler",
  63. "formatter": "generic",
  64. "stream": "ext://sys.stdout"
  65. },
  66. "error_console": {
  67. "class": "logging.StreamHandler",
  68. "formatter": "generic",
  69. "stream": "ext://sys.stderr"
  70. },
  71. },
  72. "formatters": {
  73. "generic": {
  74. "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s",
  75. "datefmt": "[%Y-%m-%d %H:%M:%S %z]",
  76. "class": "logging.Formatter"
  77. }
  78. }
  79. }
  80. def loggers():
  81. """ get list of all loggers """
  82. root = logging.root
  83. existing = list(root.manager.loggerDict.keys())
  84. return [logging.getLogger(name) for name in existing]
  85. class SafeAtoms(dict):
  86. def __init__(self, atoms):
  87. dict.__init__(self)
  88. for key, value in atoms.items():
  89. if isinstance(value, str):
  90. self[key] = value.replace('"', '\\"')
  91. else:
  92. self[key] = value
  93. def __getitem__(self, k):
  94. if k.startswith("{"):
  95. kl = k.lower()
  96. if kl in self:
  97. return super().__getitem__(kl)
  98. else:
  99. return "-"
  100. if k in self:
  101. return super().__getitem__(k)
  102. else:
  103. return '-'
  104. def parse_syslog_address(addr):
  105. # unix domain socket type depends on backend
  106. # SysLogHandler will try both when given None
  107. if addr.startswith("unix://"):
  108. sock_type = None
  109. # set socket type only if explicitly requested
  110. parts = addr.split("#", 1)
  111. if len(parts) == 2:
  112. addr = parts[0]
  113. if parts[1] == "dgram":
  114. sock_type = socket.SOCK_DGRAM
  115. return (sock_type, addr.split("unix://")[1])
  116. if addr.startswith("udp://"):
  117. addr = addr.split("udp://")[1]
  118. socktype = socket.SOCK_DGRAM
  119. elif addr.startswith("tcp://"):
  120. addr = addr.split("tcp://")[1]
  121. socktype = socket.SOCK_STREAM
  122. else:
  123. raise RuntimeError("invalid syslog address")
  124. if '[' in addr and ']' in addr:
  125. host = addr.split(']')[0][1:].lower()
  126. elif ':' in addr:
  127. host = addr.split(':')[0].lower()
  128. elif addr == "":
  129. host = "localhost"
  130. else:
  131. host = addr.lower()
  132. addr = addr.split(']')[-1]
  133. if ":" in addr:
  134. port = addr.split(':', 1)[1]
  135. if not port.isdigit():
  136. raise RuntimeError("%r is not a valid port number." % port)
  137. port = int(port)
  138. else:
  139. port = 514
  140. return (socktype, (host, port))
  141. class Logger:
  142. LOG_LEVELS = {
  143. "critical": logging.CRITICAL,
  144. "error": logging.ERROR,
  145. "warning": logging.WARNING,
  146. "info": logging.INFO,
  147. "debug": logging.DEBUG
  148. }
  149. loglevel = logging.INFO
  150. error_fmt = r"%(asctime)s [%(process)d] [%(levelname)s] %(message)s"
  151. datefmt = r"[%Y-%m-%d %H:%M:%S %z]"
  152. access_fmt = "%(message)s"
  153. syslog_fmt = "[%(process)d] %(message)s"
  154. atoms_wrapper_class = SafeAtoms
  155. def __init__(self, cfg):
  156. self.error_log = logging.getLogger("gunicorn.error")
  157. self.error_log.propagate = False
  158. self.access_log = logging.getLogger("gunicorn.access")
  159. self.access_log.propagate = False
  160. self.error_handlers = []
  161. self.access_handlers = []
  162. self.logfile = None
  163. self.lock = threading.Lock()
  164. self.cfg = cfg
  165. self.setup(cfg)
  166. def setup(self, cfg):
  167. self.loglevel = self.LOG_LEVELS.get(cfg.loglevel.lower(), logging.INFO)
  168. self.error_log.setLevel(self.loglevel)
  169. self.access_log.setLevel(logging.INFO)
  170. # set gunicorn.error handler
  171. if self.cfg.capture_output and cfg.errorlog != "-":
  172. for stream in sys.stdout, sys.stderr:
  173. stream.flush()
  174. self.logfile = open(cfg.errorlog, 'a+')
  175. os.dup2(self.logfile.fileno(), sys.stdout.fileno())
  176. os.dup2(self.logfile.fileno(), sys.stderr.fileno())
  177. self._set_handler(self.error_log, cfg.errorlog,
  178. logging.Formatter(self.error_fmt, self.datefmt))
  179. # set gunicorn.access handler
  180. if cfg.accesslog is not None:
  181. self._set_handler(
  182. self.access_log, cfg.accesslog,
  183. fmt=logging.Formatter(self.access_fmt), stream=sys.stdout
  184. )
  185. # set syslog handler
  186. if cfg.syslog:
  187. self._set_syslog_handler(
  188. self.error_log, cfg, self.syslog_fmt, "error"
  189. )
  190. if not cfg.disable_redirect_access_to_syslog:
  191. self._set_syslog_handler(
  192. self.access_log, cfg, self.syslog_fmt, "access"
  193. )
  194. if cfg.logconfig_dict:
  195. config = CONFIG_DEFAULTS.copy()
  196. config.update(cfg.logconfig_dict)
  197. try:
  198. dictConfig(config)
  199. except (
  200. AttributeError,
  201. ImportError,
  202. ValueError,
  203. TypeError
  204. ) as exc:
  205. raise RuntimeError(str(exc))
  206. elif cfg.logconfig_json:
  207. config = CONFIG_DEFAULTS.copy()
  208. if os.path.exists(cfg.logconfig_json):
  209. try:
  210. config_json = json.load(open(cfg.logconfig_json))
  211. config.update(config_json)
  212. dictConfig(config)
  213. except (
  214. json.JSONDecodeError,
  215. AttributeError,
  216. ImportError,
  217. ValueError,
  218. TypeError
  219. ) as exc:
  220. raise RuntimeError(str(exc))
  221. elif cfg.logconfig:
  222. if os.path.exists(cfg.logconfig):
  223. defaults = CONFIG_DEFAULTS.copy()
  224. defaults['__file__'] = cfg.logconfig
  225. defaults['here'] = os.path.dirname(cfg.logconfig)
  226. fileConfig(cfg.logconfig, defaults=defaults,
  227. disable_existing_loggers=False)
  228. else:
  229. msg = "Error: log config '%s' not found"
  230. raise RuntimeError(msg % cfg.logconfig)
  231. def critical(self, msg, *args, **kwargs):
  232. self.error_log.critical(msg, *args, **kwargs)
  233. def error(self, msg, *args, **kwargs):
  234. self.error_log.error(msg, *args, **kwargs)
  235. def warning(self, msg, *args, **kwargs):
  236. self.error_log.warning(msg, *args, **kwargs)
  237. def info(self, msg, *args, **kwargs):
  238. self.error_log.info(msg, *args, **kwargs)
  239. def debug(self, msg, *args, **kwargs):
  240. self.error_log.debug(msg, *args, **kwargs)
  241. def exception(self, msg, *args, **kwargs):
  242. self.error_log.exception(msg, *args, **kwargs)
  243. def log(self, lvl, msg, *args, **kwargs):
  244. if isinstance(lvl, str):
  245. lvl = self.LOG_LEVELS.get(lvl.lower(), logging.INFO)
  246. self.error_log.log(lvl, msg, *args, **kwargs)
  247. def atoms(self, resp, req, environ, request_time):
  248. """ Gets atoms for log formatting.
  249. """
  250. status = resp.status
  251. if isinstance(status, str):
  252. status = status.split(None, 1)[0]
  253. atoms = {
  254. 'h': environ.get('REMOTE_ADDR', '-'),
  255. 'l': '-',
  256. 'u': self._get_user(environ) or '-',
  257. 't': self.now(),
  258. 'r': "%s %s %s" % (environ['REQUEST_METHOD'],
  259. environ['RAW_URI'],
  260. environ["SERVER_PROTOCOL"]),
  261. 's': status,
  262. 'm': environ.get('REQUEST_METHOD'),
  263. 'U': environ.get('PATH_INFO'),
  264. 'q': environ.get('QUERY_STRING'),
  265. 'H': environ.get('SERVER_PROTOCOL'),
  266. 'b': getattr(resp, 'sent', None) is not None and str(resp.sent) or '-',
  267. 'B': getattr(resp, 'sent', None),
  268. 'f': environ.get('HTTP_REFERER', '-'),
  269. 'a': environ.get('HTTP_USER_AGENT', '-'),
  270. 'T': request_time.seconds,
  271. 'D': (request_time.seconds * 1000000) + request_time.microseconds,
  272. 'M': (request_time.seconds * 1000) + int(request_time.microseconds / 1000),
  273. 'L': "%d.%06d" % (request_time.seconds, request_time.microseconds),
  274. 'p': "<%s>" % os.getpid()
  275. }
  276. # add request headers
  277. if hasattr(req, 'headers'):
  278. req_headers = req.headers
  279. else:
  280. req_headers = req
  281. if hasattr(req_headers, "items"):
  282. req_headers = req_headers.items()
  283. atoms.update({"{%s}i" % k.lower(): v for k, v in req_headers})
  284. resp_headers = resp.headers
  285. if hasattr(resp_headers, "items"):
  286. resp_headers = resp_headers.items()
  287. # add response headers
  288. atoms.update({"{%s}o" % k.lower(): v for k, v in resp_headers})
  289. # add environ variables
  290. environ_variables = environ.items()
  291. atoms.update({"{%s}e" % k.lower(): v for k, v in environ_variables})
  292. return atoms
  293. def access(self, resp, req, environ, request_time):
  294. """ See http://httpd.apache.org/docs/2.0/logs.html#combined
  295. for format details
  296. """
  297. if not (self.cfg.accesslog or self.cfg.logconfig or
  298. self.cfg.logconfig_dict or self.cfg.logconfig_json or
  299. (self.cfg.syslog and not self.cfg.disable_redirect_access_to_syslog)):
  300. return
  301. # wrap atoms:
  302. # - make sure atoms will be test case insensitively
  303. # - if atom doesn't exist replace it by '-'
  304. safe_atoms = self.atoms_wrapper_class(
  305. self.atoms(resp, req, environ, request_time)
  306. )
  307. try:
  308. self.access_log.info(self.cfg.access_log_format, safe_atoms)
  309. except Exception:
  310. self.error(traceback.format_exc())
  311. def now(self):
  312. """ return date in Apache Common Log Format """
  313. return time.strftime('[%d/%b/%Y:%H:%M:%S %z]')
  314. def reopen_files(self):
  315. if self.cfg.capture_output and self.cfg.errorlog != "-":
  316. for stream in sys.stdout, sys.stderr:
  317. stream.flush()
  318. with self.lock:
  319. if self.logfile is not None:
  320. self.logfile.close()
  321. self.logfile = open(self.cfg.errorlog, 'a+')
  322. os.dup2(self.logfile.fileno(), sys.stdout.fileno())
  323. os.dup2(self.logfile.fileno(), sys.stderr.fileno())
  324. for log in loggers():
  325. for handler in log.handlers:
  326. if isinstance(handler, logging.FileHandler):
  327. handler.acquire()
  328. try:
  329. if handler.stream:
  330. handler.close()
  331. handler.stream = handler._open()
  332. finally:
  333. handler.release()
  334. def close_on_exec(self):
  335. for log in loggers():
  336. for handler in log.handlers:
  337. if isinstance(handler, logging.FileHandler):
  338. handler.acquire()
  339. try:
  340. if handler.stream:
  341. util.close_on_exec(handler.stream.fileno())
  342. finally:
  343. handler.release()
  344. def _get_gunicorn_handler(self, log):
  345. for h in log.handlers:
  346. if getattr(h, "_gunicorn", False):
  347. return h
  348. def _set_handler(self, log, output, fmt, stream=None):
  349. # remove previous gunicorn log handler
  350. h = self._get_gunicorn_handler(log)
  351. if h:
  352. log.handlers.remove(h)
  353. if output is not None:
  354. if output == "-":
  355. h = logging.StreamHandler(stream)
  356. else:
  357. util.check_is_writable(output)
  358. h = logging.FileHandler(output)
  359. # make sure the user can reopen the file
  360. try:
  361. os.chown(h.baseFilename, self.cfg.user, self.cfg.group)
  362. except OSError:
  363. # it's probably OK there, we assume the user has given
  364. # /dev/null as a parameter.
  365. pass
  366. h.setFormatter(fmt)
  367. h._gunicorn = True
  368. log.addHandler(h)
  369. def _set_syslog_handler(self, log, cfg, fmt, name):
  370. # setup format
  371. prefix = cfg.syslog_prefix or cfg.proc_name.replace(":", ".")
  372. prefix = "gunicorn.%s.%s" % (prefix, name)
  373. # set format
  374. fmt = logging.Formatter(r"%s: %s" % (prefix, fmt))
  375. # syslog facility
  376. try:
  377. facility = SYSLOG_FACILITIES[cfg.syslog_facility.lower()]
  378. except KeyError:
  379. raise RuntimeError("unknown facility name")
  380. # parse syslog address
  381. socktype, addr = parse_syslog_address(cfg.syslog_addr)
  382. # finally setup the syslog handler
  383. h = logging.handlers.SysLogHandler(address=addr,
  384. facility=facility, socktype=socktype)
  385. h.setFormatter(fmt)
  386. h._gunicorn = True
  387. log.addHandler(h)
  388. def _get_user(self, environ):
  389. user = None
  390. http_auth = environ.get("HTTP_AUTHORIZATION")
  391. if http_auth and http_auth.lower().startswith('basic'):
  392. auth = http_auth.split(" ", 1)
  393. if len(auth) == 2:
  394. try:
  395. # b64decode doesn't accept unicode in Python < 3.3
  396. # so we need to convert it to a byte string
  397. auth = base64.b64decode(auth[1].strip().encode('utf-8'))
  398. # b64decode returns a byte string
  399. user = auth.split(b":", 1)[0].decode("UTF-8")
  400. except (TypeError, binascii.Error, UnicodeDecodeError) as exc:
  401. self.debug("Couldn't get username: %s", exc)
  402. return user