Coverage for /pythoncovmergedfiles/medio/medio/src/aiohttp/aiohttp/web_log.py: 47%

1import datetime 

2import functools 

3import logging 

4import os 

5import re 

6import time as time_mod 

7from collections import namedtuple 

8from typing import Any, Callable, Dict, Iterable, List, Tuple # noqa 

9 

10from .abc import AbstractAccessLogger 

11from .web_request import BaseRequest 

12from .web_response import StreamResponse 

13 

14KeyMethod = namedtuple("KeyMethod", "key method") 

15 

16 

17class AccessLogger(AbstractAccessLogger): 

18 """Helper object to log access. 

19 

20 Usage: 

21 log = logging.getLogger("spam") 

22 log_format = "%a %{User-Agent}i" 

23 access_logger = AccessLogger(log, log_format) 

24 access_logger.log(request, response, time) 

25 

26 Format: 

27 %% The percent sign 

28 %a Remote IP-address (IP-address of proxy if using reverse proxy) 

29 %t Time when the request was started to process 

30 %P The process ID of the child that serviced the request 

31 %r First line of request 

32 %s Response status code 

33 %b Size of response in bytes, including HTTP headers 

34 %T Time taken to serve the request, in seconds 

35 %Tf Time taken to serve the request, in seconds with floating fraction 

36 in .06f format 

37 %D Time taken to serve the request, in microseconds 

38 %{FOO}i request.headers['FOO'] 

39 %{FOO}o response.headers['FOO'] 

40 %{FOO}e os.environ['FOO'] 

41 

42 """ 

43 

44 LOG_FORMAT_MAP = { 

45 "a": "remote_address", 

46 "t": "request_start_time", 

47 "P": "process_id", 

48 "r": "first_request_line", 

49 "s": "response_status", 

50 "b": "response_size", 

51 "T": "request_time", 

52 "Tf": "request_time_frac", 

53 "D": "request_time_micro", 

54 "i": "request_header", 

55 "o": "response_header", 

56 } 

57 

58 LOG_FORMAT = '%a %t "%r" %s %b "%{Referer}i" "%{User-Agent}i"' 

59 FORMAT_RE = re.compile(r"%(\{([A-Za-z0-9\-_]+)\}([ioe])|[atPrsbOD]|Tf?)") 

60 CLEANUP_RE = re.compile(r"(%[^s])") 

61 _FORMAT_CACHE: Dict[str, Tuple[str, List[KeyMethod]]] = {} 

62 

63 def __init__(self, logger: logging.Logger, log_format: str = LOG_FORMAT) -> None: 

64 """Initialise the logger. 

65 

66 logger is a logger object to be used for logging. 

67 log_format is a string with apache compatible log format description. 

68 

69 """ 

70 super().__init__(logger, log_format=log_format) 

71 

72 _compiled_format = AccessLogger._FORMAT_CACHE.get(log_format) 

73 if not _compiled_format: 

74 _compiled_format = self.compile_format(log_format) 

75 AccessLogger._FORMAT_CACHE[log_format] = _compiled_format 

76 

77 self._log_format, self._methods = _compiled_format 

78 

79 def compile_format(self, log_format: str) -> Tuple[str, List[KeyMethod]]: 

80 """Translate log_format into form usable by modulo formatting 

81 

82 All known atoms will be replaced with %s 

83 Also methods for formatting of those atoms will be added to 

84 _methods in appropriate order 

85 

86 For example we have log_format = "%a %t" 

87 This format will be translated to "%s %s" 

88 Also contents of _methods will be 

89 [self._format_a, self._format_t] 

90 These method will be called and results will be passed 

91 to translated string format. 

92 

93 Each _format_* method receive 'args' which is list of arguments 

94 given to self.log 

95 

96 Exceptions are _format_e, _format_i and _format_o methods which 

97 also receive key name (by functools.partial) 

98 

99 """ 

100 # list of (key, method) tuples, we don't use an OrderedDict as users 

101 # can repeat the same key more than once 

102 methods = list() 

103 

104 for atom in self.FORMAT_RE.findall(log_format): 

105 if atom[1] == "": 

106 format_key1 = self.LOG_FORMAT_MAP[atom[0]] 

107 m = getattr(AccessLogger, "_format_%s" % atom[0]) 

108 key_method = KeyMethod(format_key1, m) 

109 else: 

110 format_key2 = (self.LOG_FORMAT_MAP[atom[2]], atom[1]) 

111 m = getattr(AccessLogger, "_format_%s" % atom[2]) 

112 key_method = KeyMethod(format_key2, functools.partial(m, atom[1])) 

113 

114 methods.append(key_method) 

115 

116 log_format = self.FORMAT_RE.sub(r"%s", log_format) 

117 log_format = self.CLEANUP_RE.sub(r"%\1", log_format) 

118 return log_format, methods 

119 

120 @staticmethod 

121 def _format_i( 

122 key: str, request: BaseRequest, response: StreamResponse, time: float 

123 ) -> str: 

124 # suboptimal, make istr(key) once 

125 return request.headers.get(key, "-") 

126 

127 @staticmethod 

128 def _format_o( 

129 key: str, request: BaseRequest, response: StreamResponse, time: float 

130 ) -> str: 

131 # suboptimal, make istr(key) once 

132 return response.headers.get(key, "-") 

133 

134 @staticmethod 

135 def _format_a(request: BaseRequest, response: StreamResponse, time: float) -> str: 

136 ip = request.remote 

137 return ip if ip is not None else "-" 

138 

139 @staticmethod 

140 def _format_t(request: BaseRequest, response: StreamResponse, time: float) -> str: 

141 tz = datetime.timezone(datetime.timedelta(seconds=-time_mod.timezone)) 

142 now = datetime.datetime.now(tz) 

143 start_time = now - datetime.timedelta(seconds=time) 

144 return start_time.strftime("[%d/%b/%Y:%H:%M:%S %z]") 

145 

146 @staticmethod 

147 def _format_P(request: BaseRequest, response: StreamResponse, time: float) -> str: 

148 return "<%s>" % os.getpid() 

149 

150 @staticmethod 

151 def _format_r(request: BaseRequest, response: StreamResponse, time: float) -> str: 

152 return "{} {} HTTP/{}.{}".format( 

153 request.method, 

154 request.path_qs, 

155 request.version.major, 

156 request.version.minor, 

157 ) 

158 

159 @staticmethod 

160 def _format_s(request: BaseRequest, response: StreamResponse, time: float) -> int: 

161 return response.status 

162 

163 @staticmethod 

164 def _format_b(request: BaseRequest, response: StreamResponse, time: float) -> int: 

165 return response.body_length 

166 

167 @staticmethod 

168 def _format_T(request: BaseRequest, response: StreamResponse, time: float) -> str: 

169 return str(round(time)) 

170 

171 @staticmethod 

172 def _format_Tf(request: BaseRequest, response: StreamResponse, time: float) -> str: 

173 return "%06f" % time 

174 

175 @staticmethod 

176 def _format_D(request: BaseRequest, response: StreamResponse, time: float) -> str: 

177 return str(round(time * 1000000)) 

178 

179 def _format_line( 

180 self, request: BaseRequest, response: StreamResponse, time: float 

181 ) -> Iterable[Tuple[str, Callable[[BaseRequest, StreamResponse, float], str]]]: 

182 return [(key, method(request, response, time)) for key, method in self._methods] 

183 

184 @property 

185 def enabled(self) -> bool: 

186 """Check if logger is enabled.""" 

187 # Avoid formatting the log line if it will not be emitted. 

188 return self.logger.isEnabledFor(logging.INFO) 

189 

190 def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None: 

191 try: 

192 fmt_info = self._format_line(request, response, time) 

193 

194 values = list() 

195 extra = dict() 

196 for key, value in fmt_info: 

197 values.append(value) 

198 

199 if key.__class__ is str: 

200 extra[key] = value 

201 else: 

202 k1, k2 = key # type: ignore[misc] 

203 dct = extra.get(k1, {}) # type: ignore[var-annotated,has-type] 

204 dct[k2] = value # type: ignore[index,has-type] 

205 extra[k1] = dct # type: ignore[has-type,assignment] 

206 

207 self.logger.info(self._log_format % tuple(values), extra=extra) 

208 except Exception: 

209 self.logger.exception("Error in logging")