web_log.py 8.4 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234
  1. import datetime
  2. import functools
  3. import logging
  4. import os
  5. import re
  6. import time as time_mod
  7. from collections import namedtuple
  8. from collections.abc import Iterable
  9. from typing import Callable, ClassVar, Dict, List, Optional, Tuple
  10. from .abc import AbstractAccessLogger
  11. from .web_request import BaseRequest
  12. from .web_response import StreamResponse
  13. KeyMethod = namedtuple("KeyMethod", "key method")
  14. class AccessLogger(AbstractAccessLogger):
  15. """Helper object to log access.
  16. Usage:
  17. log = logging.getLogger("spam")
  18. log_format = "%a %{User-Agent}i"
  19. access_logger = AccessLogger(log, log_format)
  20. access_logger.log(request, response, time)
  21. Format:
  22. %% The percent sign
  23. %a Remote IP-address (IP-address of proxy if using reverse proxy)
  24. %t Time when the request was started to process
  25. %P The process ID of the child that serviced the request
  26. %r First line of request
  27. %s Response status code
  28. %b Size of response in bytes, including HTTP headers
  29. %T Time taken to serve the request, in seconds
  30. %Tf Time taken to serve the request, in seconds with floating fraction
  31. in .06f format
  32. %D Time taken to serve the request, in microseconds
  33. %{FOO}i request.headers['FOO']
  34. %{FOO}o response.headers['FOO']
  35. %{FOO}e os.environ['FOO']
  36. """
  37. LOG_FORMAT_MAP = {
  38. "a": "remote_address",
  39. "t": "request_start_time",
  40. "P": "process_id",
  41. "r": "first_request_line",
  42. "s": "response_status",
  43. "b": "response_size",
  44. "T": "request_time",
  45. "Tf": "request_time_frac",
  46. "D": "request_time_micro",
  47. "i": "request_header",
  48. "o": "response_header",
  49. }
  50. LOG_FORMAT = '%a %t "%r" %s %b "%{Referer}i" "%{User-Agent}i"'
  51. FORMAT_RE = re.compile(r"%(\{([A-Za-z0-9\-_]+)\}([ioe])|[atPrsbOD]|Tf?)")
  52. CLEANUP_RE = re.compile(r"(%[^s])")
  53. _FORMAT_CACHE: Dict[str, Tuple[str, List[KeyMethod]]] = {}
  54. _cached_tz: ClassVar[Optional[datetime.timezone]] = None
  55. _cached_tz_expires: ClassVar[float] = 0.0
  56. def __init__(self, logger: logging.Logger, log_format: str = LOG_FORMAT) -> None:
  57. """Initialise the logger.
  58. logger is a logger object to be used for logging.
  59. log_format is a string with apache compatible log format description.
  60. """
  61. super().__init__(logger, log_format=log_format)
  62. _compiled_format = AccessLogger._FORMAT_CACHE.get(log_format)
  63. if not _compiled_format:
  64. _compiled_format = self.compile_format(log_format)
  65. AccessLogger._FORMAT_CACHE[log_format] = _compiled_format
  66. self._log_format, self._methods = _compiled_format
  67. def compile_format(self, log_format: str) -> Tuple[str, List[KeyMethod]]:
  68. """Translate log_format into form usable by modulo formatting
  69. All known atoms will be replaced with %s
  70. Also methods for formatting of those atoms will be added to
  71. _methods in appropriate order
  72. For example we have log_format = "%a %t"
  73. This format will be translated to "%s %s"
  74. Also contents of _methods will be
  75. [self._format_a, self._format_t]
  76. These method will be called and results will be passed
  77. to translated string format.
  78. Each _format_* method receive 'args' which is list of arguments
  79. given to self.log
  80. Exceptions are _format_e, _format_i and _format_o methods which
  81. also receive key name (by functools.partial)
  82. """
  83. # list of (key, method) tuples, we don't use an OrderedDict as users
  84. # can repeat the same key more than once
  85. methods = list()
  86. for atom in self.FORMAT_RE.findall(log_format):
  87. if atom[1] == "":
  88. format_key1 = self.LOG_FORMAT_MAP[atom[0]]
  89. m = getattr(AccessLogger, "_format_%s" % atom[0])
  90. key_method = KeyMethod(format_key1, m)
  91. else:
  92. format_key2 = (self.LOG_FORMAT_MAP[atom[2]], atom[1])
  93. m = getattr(AccessLogger, "_format_%s" % atom[2])
  94. key_method = KeyMethod(format_key2, functools.partial(m, atom[1]))
  95. methods.append(key_method)
  96. log_format = self.FORMAT_RE.sub(r"%s", log_format)
  97. log_format = self.CLEANUP_RE.sub(r"%\1", log_format)
  98. return log_format, methods
  99. @staticmethod
  100. def _format_i(
  101. key: str, request: BaseRequest, response: StreamResponse, time: float
  102. ) -> str:
  103. if request is None:
  104. return "(no headers)"
  105. # suboptimal, make istr(key) once
  106. return request.headers.get(key, "-")
  107. @staticmethod
  108. def _format_o(
  109. key: str, request: BaseRequest, response: StreamResponse, time: float
  110. ) -> str:
  111. # suboptimal, make istr(key) once
  112. return response.headers.get(key, "-")
  113. @staticmethod
  114. def _format_a(request: BaseRequest, response: StreamResponse, time: float) -> str:
  115. if request is None:
  116. return "-"
  117. ip = request.remote
  118. return ip if ip is not None else "-"
  119. @classmethod
  120. def _get_local_time(cls) -> datetime.datetime:
  121. if cls._cached_tz is None or time_mod.time() >= cls._cached_tz_expires:
  122. gmtoff = time_mod.localtime().tm_gmtoff
  123. cls._cached_tz = tz = datetime.timezone(datetime.timedelta(seconds=gmtoff))
  124. now = datetime.datetime.now(tz)
  125. # Expire at every 30 mins, as any DST change should occur at 0/30 mins past.
  126. d = now + datetime.timedelta(minutes=30)
  127. d = d.replace(minute=30 if d.minute >= 30 else 0, second=0, microsecond=0)
  128. cls._cached_tz_expires = d.timestamp()
  129. return now
  130. return datetime.datetime.now(cls._cached_tz)
  131. @staticmethod
  132. def _format_t(request: BaseRequest, response: StreamResponse, time: float) -> str:
  133. now = AccessLogger._get_local_time()
  134. start_time = now - datetime.timedelta(seconds=time)
  135. return start_time.strftime("[%d/%b/%Y:%H:%M:%S %z]")
  136. @staticmethod
  137. def _format_P(request: BaseRequest, response: StreamResponse, time: float) -> str:
  138. return "<%s>" % os.getpid()
  139. @staticmethod
  140. def _format_r(request: BaseRequest, response: StreamResponse, time: float) -> str:
  141. if request is None:
  142. return "-"
  143. return "{} {} HTTP/{}.{}".format(
  144. request.method,
  145. request.path_qs,
  146. request.version.major,
  147. request.version.minor,
  148. )
  149. @staticmethod
  150. def _format_s(request: BaseRequest, response: StreamResponse, time: float) -> int:
  151. return response.status
  152. @staticmethod
  153. def _format_b(request: BaseRequest, response: StreamResponse, time: float) -> int:
  154. return response.body_length
  155. @staticmethod
  156. def _format_T(request: BaseRequest, response: StreamResponse, time: float) -> str:
  157. return str(round(time))
  158. @staticmethod
  159. def _format_Tf(request: BaseRequest, response: StreamResponse, time: float) -> str:
  160. return "%06f" % time
  161. @staticmethod
  162. def _format_D(request: BaseRequest, response: StreamResponse, time: float) -> str:
  163. return str(round(time * 1000000))
  164. def _format_line(
  165. self, request: BaseRequest, response: StreamResponse, time: float
  166. ) -> Iterable[Tuple[str, Callable[[BaseRequest, StreamResponse, float], str]]]:
  167. return [(key, method(request, response, time)) for key, method in self._methods]
  168. @property
  169. def enabled(self) -> bool:
  170. """Check if logger is enabled."""
  171. # Avoid formatting the log line if it will not be emitted.
  172. return self.logger.isEnabledFor(logging.INFO)
  173. def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None:
  174. try:
  175. fmt_info = self._format_line(request, response, time)
  176. values = list()
  177. extra = dict()
  178. for key, value in fmt_info:
  179. values.append(value)
  180. if key.__class__ is str:
  181. extra[key] = value
  182. else:
  183. k1, k2 = key # type: ignore[misc]
  184. dct = extra.get(k1, {}) # type: ignore[var-annotated,has-type]
  185. dct[k2] = value # type: ignore[index,has-type]
  186. extra[k1] = dct # type: ignore[has-type,assignment]
  187. self.logger.info(self._log_format % tuple(values), extra=extra)
  188. except Exception:
  189. self.logger.exception("Error in logging")