diff --git a/README.md b/README.md index 6f42ee41..40f8e80e 100644 --- a/README.md +++ b/README.md @@ -420,6 +420,11 @@ The following atoms are available for use: | method | Request HTTP method | | scheme | Request scheme | | protocol | HTTP protocol version | +| user\_agent | Request User-Agent header | + +Arbitrary request headers can be accessed using `%({Header-Name}i)s` (case-insensitive), e.g. `%({X-Request-Id}i)s`. + +Arbitrary response headers can be accessed using `%({Header-Name}o)s` (case-insensitive), e.g. `%({X-Trace-Id}o)s`. ### Workers and threads diff --git a/granian/asgi.py b/granian/asgi.py index d9f816f5..394e7f01 100644 --- a/granian/asgi.py +++ b/granian/asgi.py @@ -120,16 +120,34 @@ async def _http_logger(scope, proto): access_log(rt, mt, scope, proto.sent_response_code) return rv + async def _http_logger_with_resp_headers(scope, proto): + rt, mt = time.time(), time.perf_counter() + resp_headers_raw = [] + original_send = proto.send + + async def capturing_send(message): + if message.get('type') == 'http.response.start': + resp_headers_raw.extend(message.get('headers', ())) + return await original_send(message) + + try: + scope.update(root_path=root_url_path, state=state.copy()) + rv = await callback(scope, proto.receive, capturing_send) + finally: + access_log(rt, mt, scope, proto.sent_response_code, resp_headers_raw) + return rv + def _ws_logger(scope, proto): access_log(time.time(), time.perf_counter(), scope, 101) return _runner(scope, proto) def _logger(scope, proto): if scope['type'] == 'http': - return _http_logger(scope, proto) + return _http_log(scope, proto) return _ws_logger(scope, proto) - access_log = _build_access_logger(access_log_fmt) + access_log, _needs_resp_headers = _build_access_logger(access_log_fmt) + _http_log = _http_logger_with_resp_headers if _needs_resp_headers else _http_logger wrapper = _logger if access_log_fmt else _runner wraps(callback)(wrapper) @@ -138,20 +156,32 @@ def _logger(scope, proto): def _build_access_logger(fmt): logger = log_request_builder(fmt) - - def access_log(rt, mt, scope, resp_code): - logger( - rt, - mt, - { - 'addr_remote': scope['client'][0], - 'protocol': 'HTTP/' + scope['http_version'], - 'path': scope['path'], - 'qs': scope['query_string'], - 'method': scope.get('method', '-'), - 'scheme': scope['scheme'], - }, - resp_code, - ) - - return access_log + _needs_resp_headers = logger.needs_resp_headers + + def access_log(rt, mt, scope, resp_code, resp_headers_raw=()): + user_agent = '-' + headers_dict = {} + for hname_b, hval_b in scope.get('headers', ()): + hname = hname_b.decode('latin-1').lower() + hval = hval_b.decode('latin-1') + headers_dict[hname] = hval + if hname == 'user-agent': + user_agent = hval + req = { + 'addr_remote': scope['client'][0], + 'protocol': 'HTTP/' + scope['http_version'], + 'path': scope['path'], + 'qs': scope['query_string'], + 'method': scope.get('method', '-'), + 'scheme': scope['scheme'], + 'user_agent': user_agent, + 'get_header': headers_dict.get, + } + if _needs_resp_headers: + req['get_response_header'] = { + hname_b.decode('latin-1').lower(): hval_b.decode('latin-1') + for hname_b, hval_b in resp_headers_raw + }.get + logger(rt, mt, req, resp_code) + + return access_log, _needs_resp_headers diff --git a/granian/log.py b/granian/log.py index 2f5409ab..32d1ac62 100644 --- a/granian/log.py +++ b/granian/log.py @@ -2,6 +2,7 @@ import datetime import logging import logging.config +import re import time from enum import Enum from typing import Any @@ -72,7 +73,48 @@ def configure_logging(level: LogLevels, config: dict[str, Any] | None = None, en logger.setLevel(logging.CRITICAL + 1) +_REQUEST_HEADER_RE = re.compile(r'%\(\{([^}]+)\}i\)s') +_RESPONSE_HEADER_RE = re.compile(r'%\(\{([^}]+)\}o\)s') + + def log_request_builder(fmt): + required_req_headers = [] + required_resp_headers = [] + + def _replace_req(m): + name = m.group(1).strip().lower() + required_req_headers.append(name) + return f'%(header:{name})s' + + def _replace_resp(m): + name = m.group(1).strip().lower() + required_resp_headers.append(name) + return f'%(resp_header:{name})s' + + transformed_fmt = _REQUEST_HEADER_RE.sub(_replace_req, fmt) + transformed_fmt = _RESPONSE_HEADER_RE.sub(_replace_resp, transformed_fmt) + + # Validate the format string eagerly so misconfiguration is caught at startup, + # not silently swallowed on the first real request. + _dummy = { + 'addr': '127.0.0.1', + 'time': '2000-01-01 00:00:00 +0000', + 'dt_ms': 0.0, + 'status': 200, + 'path': '/', + 'query_string': '', + 'method': 'GET', + 'scheme': 'http', + 'protocol': 'HTTP/1.1', + 'user_agent': '-', + **{f'header:{h}': '-' for h in required_req_headers}, + **{f'resp_header:{h}': '-' for h in required_resp_headers}, + } + try: + transformed_fmt % _dummy + except (KeyError, ValueError) as exc: + raise ValueError(f'Invalid access log format: {exc}') from exc + now = datetime.datetime.now() local_now = now.astimezone() local_tz = local_now.tzinfo @@ -80,19 +122,27 @@ def log_request_builder(fmt): def log_request(rtime, mtime, req, res_code): dt = time.perf_counter() - mtime rdt = datetime.datetime.fromtimestamp(rtime, tz=local_tz) - access_logger.info( - fmt, - { - 'addr': req['addr_remote'], - 'time': rdt.strftime('%Y-%m-%d %H:%M:%S %z'), - 'dt_ms': dt * 1000, - 'status': res_code, - 'path': req['path'], - 'query_string': req['qs'], - 'method': req['method'], - 'scheme': req['scheme'], - 'protocol': req['protocol'], - }, - ) - + log_dict = { + 'addr': req['addr_remote'], + 'time': rdt.strftime('%Y-%m-%d %H:%M:%S %z'), + 'dt_ms': dt * 1000, + 'status': res_code, + 'path': req['path'], + 'query_string': req['qs'], + 'method': req['method'], + 'scheme': req['scheme'], + 'protocol': req['protocol'], + 'user_agent': req['user_agent'], + } + if required_req_headers: + get_header = req.get('get_header') or (lambda _: None) + for hname in required_req_headers: + log_dict[f'header:{hname}'] = get_header(hname) or '-' + if required_resp_headers: + get_resp_header = req.get('get_response_header') or (lambda _: None) + for hname in required_resp_headers: + log_dict[f'resp_header:{hname}'] = get_resp_header(hname) or '-' + access_logger.info(transformed_fmt, log_dict) + + log_request.needs_resp_headers = bool(required_resp_headers) return log_request diff --git a/granian/rsgi.py b/granian/rsgi.py index f3224710..8c20cc4e 100644 --- a/granian/rsgi.py +++ b/granian/rsgi.py @@ -40,11 +40,12 @@ class WebsocketMessage: class _LoggingProto: - __slots__ = ['inner', 'status'] + __slots__ = ['inner', 'status', 'resp_headers'] def __init__(self, inner): self.inner = inner self.status = 500 + self.resp_headers = () def __call__(self): return self.inner() @@ -57,26 +58,32 @@ def client_disconnect(self): def response_empty(self, status, headers): self.status = status + self.resp_headers = headers return self.inner.response_empty(status, headers) def response_str(self, status, headers, body): self.status = status + self.resp_headers = headers return self.inner.response_str(status, headers, body) def response_bytes(self, status, headers, body): self.status = status + self.resp_headers = headers return self.inner.response_bytes(status, headers, body) def response_file(self, status, headers, file): self.status = status + self.resp_headers = headers return self.inner.response_file(status, headers, file) def response_file_range(self, status, headers, file, start, end): self.status = status + self.resp_headers = headers return self.inner.response_file_range(status, headers, file, start, end) def response_stream(self, status, headers): self.status = status + self.resp_headers = headers return self.inner.response_stream(status, headers) @@ -98,16 +105,25 @@ async def _http_logger(scope, proto): access_log(rt, mt, scope, proto.status) return rv + async def _http_logger_with_resp_headers(scope, proto): + rt, mt = time.time(), time.perf_counter() + try: + rv = await callback(scope, proto) + finally: + access_log(rt, mt, scope, proto.status, proto.resp_headers) + return rv + def _ws_logger(scope, proto): access_log(time.time(), time.perf_counter(), scope, 101) return callback(scope, proto) def _logger(scope, proto): if scope.proto == 'http': - return _http_logger(scope, _LoggingProto(proto)) + return _http_log(scope, _LoggingProto(proto)) return _ws_logger(scope, proto) - access_log = _build_access_logger(access_log_fmt) + access_log, _needs_resp_headers = _build_access_logger(access_log_fmt) + _http_log = _http_logger_with_resp_headers if _needs_resp_headers else _http_logger wrapper = callback if access_log_fmt: wrapper = _logger @@ -117,20 +133,22 @@ def _logger(scope, proto): def _build_access_logger(fmt): logger = log_request_builder(fmt) - - def access_log(rt, mt, scope, resp_code): - logger( - rt, - mt, - { - 'addr_remote': scope.client.rsplit(':', 1)[0], - 'protocol': 'HTTP/' + scope.http_version, - 'path': scope.path, - 'qs': scope.query_string, - 'method': scope.method, - 'scheme': scope.scheme, - }, - resp_code, - ) - - return access_log + _needs_resp_headers = logger.needs_resp_headers + + def access_log(rt, mt, scope, resp_code, resp_headers=()): + req = { + 'addr_remote': scope.client.rsplit(':', 1)[0], + 'protocol': 'HTTP/' + scope.http_version, + 'path': scope.path, + 'qs': scope.query_string, + 'method': scope.method, + 'scheme': scope.scheme, + 'user_agent': scope.headers.get('user-agent') or '-', + 'get_header': scope.headers.get, + } + if _needs_resp_headers: + # RSGI response headers are (str, str) tuples + req['get_response_header'] = {hname.lower(): hval for hname, hval in resp_headers}.get + logger(rt, mt, req, resp_code) + + return access_log, _needs_resp_headers diff --git a/granian/wsgi.py b/granian/wsgi.py index c2b069f2..889f40e8 100644 --- a/granian/wsgi.py +++ b/granian/wsgi.py @@ -28,7 +28,24 @@ def __init__(self, inner): self.__next__ = iter(inner).__next__ def close(self): - self.inner.close() + if hasattr(self.inner, 'close'): + self.inner.close() + + +class _LoggingProto: + __slots__ = ['inner', 'resp_headers'] + + def __init__(self, inner): + self.inner = inner + self.resp_headers = () + + def response_bytes(self, status, headers, body): + self.resp_headers = headers + return self.inner.response_bytes(status, headers, body) + + def response_iter(self, status, headers, body): + self.resp_headers = headers + return self.inner.response_iter(status, headers, body) def _callback_wrapper(callback: Callable[..., Any], scope_opts: dict[str, Any], access_log_fmt=None): @@ -71,28 +88,47 @@ def _logger(proto, scope): raise return status - access_log = _build_access_logger(access_log_fmt) - wrapper = _logger if access_log_fmt else _runner + def _logger_with_resp_headers(proto, scope): + rt, mt = time.time(), time.perf_counter() + lproto = _LoggingProto(proto) + try: + status = _runner(lproto, scope) + access_log(rt, mt, scope, status, lproto.resp_headers) + except BaseException: + access_log(rt, mt, scope, 500, lproto.resp_headers) + raise + return status + + access_log, _needs_resp_headers = _build_access_logger(access_log_fmt) + if access_log_fmt: + wrapper = _logger_with_resp_headers if _needs_resp_headers else _logger + else: + wrapper = _runner wraps(callback)(wrapper) return wrapper def _build_access_logger(fmt): logger = log_request_builder(fmt) + _needs_resp_headers = logger.needs_resp_headers + + def access_log(rt, mt, scope, resp_code, resp_headers=()): + def get_header(name): + return scope.get('HTTP_' + name.upper().replace('-', '_')) + + req = { + 'addr_remote': scope['REMOTE_ADDR'].rsplit(':', 1)[0], + 'protocol': scope['SERVER_PROTOCOL'], + 'path': scope['PATH_INFO'], + 'qs': scope['QUERY_STRING'], + 'method': scope['REQUEST_METHOD'], + 'scheme': scope['wsgi.url_scheme'], + 'user_agent': scope.get('HTTP_USER_AGENT', '-'), + 'get_header': get_header, + } + if _needs_resp_headers: + # WSGI response headers are [(str, str)] e.g. [('Content-Type', 'application/json')] + req['get_response_header'] = {hname.lower(): hval for hname, hval in resp_headers}.get + logger(rt, mt, req, resp_code) - def access_log(rt, mt, scope, resp_code): - logger( - rt, - mt, - { - 'addr_remote': scope['REMOTE_ADDR'].rsplit(':', 1)[0], - 'protocol': scope['SERVER_PROTOCOL'], - 'path': scope['PATH_INFO'], - 'qs': scope['QUERY_STRING'], - 'method': scope['REQUEST_METHOD'], - 'scheme': scope['wsgi.url_scheme'], - }, - resp_code, - ) - - return access_log + return access_log, _needs_resp_headers diff --git a/tests/test_access_log.py b/tests/test_access_log.py new file mode 100644 index 00000000..2704822d --- /dev/null +++ b/tests/test_access_log.py @@ -0,0 +1,336 @@ +import logging +import time +from unittest.mock import MagicMock + +from granian.asgi import _build_access_logger as asgi_build_access_logger +from granian.log import log_request_builder +from granian.rsgi import _build_access_logger as rsgi_build_access_logger +from granian.wsgi import _build_access_logger as wsgi_build_access_logger + + +_FMT = '%(method)s %(path)s %(status)d %(user_agent)s' + + +def _log_message(caplog): + assert len(caplog.records) == 1 + return caplog.records[0].getMessage() + + +def _base_req(user_agent='TestAgent/1.0'): + return { + 'addr_remote': '127.0.0.1', + 'protocol': 'HTTP/1.1', + 'path': '/test', + 'qs': '', + 'method': 'GET', + 'scheme': 'http', + 'user_agent': user_agent, + } + + +def _asgi_scope(user_agent=b'TestAgent/1.0'): + headers = [(b'user-agent', user_agent)] if user_agent is not None else [] + return { + 'client': ('127.0.0.1', 9999), + 'http_version': '1.1', + 'path': '/test', + 'query_string': '', + 'method': 'GET', + 'scheme': 'http', + 'headers': headers, + } + + +def _rsgi_scope(user_agent='TestAgent/1.0'): + scope = MagicMock() + scope.client = '127.0.0.1:9999' + scope.http_version = '1.1' + scope.path = '/test' + scope.query_string = '' + scope.method = 'GET' + scope.scheme = 'http' + scope.headers.get.return_value = user_agent + return scope + + +def _wsgi_scope(user_agent='TestAgent/1.0'): + scope = { + 'REMOTE_ADDR': '127.0.0.1', + 'SERVER_PROTOCOL': 'HTTP/1.1', + 'PATH_INFO': '/test', + 'QUERY_STRING': '', + 'REQUEST_METHOD': 'GET', + 'wsgi.url_scheme': 'http', + } + if user_agent is not None: + scope['HTTP_USER_AGENT'] = user_agent + return scope + + +# --------------------------------------------------------------------------- +# log_request_builder (granian/log.py) +# --------------------------------------------------------------------------- + + +def test_log_request_user_agent(caplog): + fn = log_request_builder(_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + fn(time.time(), time.perf_counter(), _base_req('Mozilla/5.0'), 200) + assert 'Mozilla/5.0' in _log_message(caplog) + + +def test_log_request_missing_user_agent_dash(caplog): + fn = log_request_builder(_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + fn(time.time(), time.perf_counter(), _base_req(user_agent='-'), 200) + assert _log_message(caplog).endswith(' -') + + +# --------------------------------------------------------------------------- +# ASGI access logger (granian/asgi.py) +# --------------------------------------------------------------------------- + + +def test_asgi_access_log_user_agent(caplog): + access_log, _ = asgi_build_access_logger(_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _asgi_scope(b'curl/7.88'), 200) + assert 'curl/7.88' in _log_message(caplog) + + +def test_asgi_access_log_absent_user_agent_defaults_to_dash(caplog): + access_log, _ = asgi_build_access_logger(_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _asgi_scope(user_agent=None), 200) + assert _log_message(caplog).endswith(' -') + + +def test_asgi_access_log_user_agent_latin1_decoded(caplog): + access_log, _ = asgi_build_access_logger(_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _asgi_scope(b'Agent/\xe9'), 200) + assert 'Agent/\xe9' in _log_message(caplog) + + +# --------------------------------------------------------------------------- +# RSGI access logger (granian/rsgi.py) +# --------------------------------------------------------------------------- + + +def test_rsgi_access_log_user_agent(caplog): + access_log, _ = rsgi_build_access_logger(_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _rsgi_scope('Go-http-client/2.0'), 200) + assert 'Go-http-client/2.0' in _log_message(caplog) + + +def test_rsgi_access_log_absent_user_agent_defaults_to_dash(caplog): + access_log, _ = rsgi_build_access_logger(_FMT) + scope = _rsgi_scope() + scope.headers.get.return_value = None + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), scope, 200) + assert _log_message(caplog).endswith(' -') + + +# --------------------------------------------------------------------------- +# WSGI access logger (granian/wsgi.py) +# --------------------------------------------------------------------------- + + +def test_wsgi_access_log_user_agent(caplog): + access_log, _ = wsgi_build_access_logger(_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _wsgi_scope('python-httpx/0.27'), 200) + assert 'python-httpx/0.27' in _log_message(caplog) + + +def test_wsgi_access_log_absent_user_agent_defaults_to_dash(caplog): + access_log, _ = wsgi_build_access_logger(_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _wsgi_scope(user_agent=None), 200) + assert _log_message(caplog).endswith(' -') + + +# --------------------------------------------------------------------------- +# Arbitrary request header atoms: %({Header-Name}i)s +# --------------------------------------------------------------------------- + +_HEADER_FMT = '%(method)s %(path)s %(status)d %({X-Request-Id}i)s %({x-forwarded-for}i)s' + + +def test_log_request_arbitrary_header(caplog): + fn = log_request_builder(_HEADER_FMT) + req = _base_req() + req['get_header'] = {'x-request-id': 'abc-123', 'x-forwarded-for': '10.0.0.1'}.get + with caplog.at_level(logging.INFO, logger='granian.access'): + fn(time.time(), time.perf_counter(), req, 200) + msg = _log_message(caplog) + assert 'abc-123' in msg + assert '10.0.0.1' in msg + + +def test_log_request_absent_arbitrary_header_defaults_to_dash(caplog): + fn = log_request_builder(_HEADER_FMT) + req = _base_req() + req['get_header'] = {}.get + with caplog.at_level(logging.INFO, logger='granian.access'): + fn(time.time(), time.perf_counter(), req, 200) + assert _log_message(caplog).endswith('- -') + + +def test_log_request_header_name_case_insensitive(caplog): + # %({X-Request-Id}i)s and %({x-request-id}i)s should both key on 'x-request-id' + for atom in ('%({X-Request-Id}i)s', '%({x-request-id}i)s', '%({X-REQUEST-ID}i)s'): + fn = log_request_builder(atom) + req = _base_req() + req['get_header'] = {'x-request-id': 'test-id'}.get + with caplog.at_level(logging.INFO, logger='granian.access'): + fn(time.time(), time.perf_counter(), req, 200) + assert 'test-id' in caplog.records[-1].getMessage() + + +def test_asgi_access_log_arbitrary_header(caplog): + access_log, _ = asgi_build_access_logger(_HEADER_FMT) + scope = _asgi_scope() + scope['headers'] = [ + (b'user-agent', b'test'), + (b'x-request-id', b'req-456'), + (b'x-forwarded-for', b'192.168.1.1'), + ] + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), scope, 200) + msg = _log_message(caplog) + assert 'req-456' in msg + assert '192.168.1.1' in msg + + +def test_asgi_access_log_absent_arbitrary_header_defaults_to_dash(caplog): + access_log, _ = asgi_build_access_logger(_HEADER_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _asgi_scope(), 200) + assert _log_message(caplog).endswith('- -') + + +def test_rsgi_access_log_arbitrary_header(caplog): + access_log, _ = rsgi_build_access_logger(_HEADER_FMT) + scope = _rsgi_scope() + scope.headers.get.side_effect = lambda name: { + 'user-agent': 'test', + 'x-request-id': 'rsgi-789', + 'x-forwarded-for': '172.16.0.1', + }.get(name) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), scope, 200) + msg = _log_message(caplog) + assert 'rsgi-789' in msg + assert '172.16.0.1' in msg + + +def test_wsgi_access_log_arbitrary_header(caplog): + access_log, _ = wsgi_build_access_logger(_HEADER_FMT) + scope = _wsgi_scope() + scope['HTTP_X_REQUEST_ID'] = 'wsgi-321' + scope['HTTP_X_FORWARDED_FOR'] = '10.10.0.1' + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), scope, 200) + msg = _log_message(caplog) + assert 'wsgi-321' in msg + assert '10.10.0.1' in msg + + +def test_wsgi_access_log_absent_arbitrary_header_defaults_to_dash(caplog): + access_log, _ = wsgi_build_access_logger(_HEADER_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _wsgi_scope(), 200) + assert _log_message(caplog).endswith('- -') + + +# --------------------------------------------------------------------------- +# Arbitrary response header atoms: %({Header-Name}o)s +# --------------------------------------------------------------------------- + +_RESP_HEADER_FMT = '%(method)s %(path)s %(status)d %({X-Trace-Id}o)s %({Content-Type}o)s' + + +def test_log_request_response_header(caplog): + fn = log_request_builder(_RESP_HEADER_FMT) + req = _base_req() + req['get_response_header'] = {'x-trace-id': 'trace-abc', 'content-type': 'application/json'}.get + with caplog.at_level(logging.INFO, logger='granian.access'): + fn(time.time(), time.perf_counter(), req, 200) + msg = _log_message(caplog) + assert 'trace-abc' in msg + assert 'application/json' in msg + + +def test_log_request_absent_response_header_defaults_to_dash(caplog): + fn = log_request_builder(_RESP_HEADER_FMT) + req = _base_req() + req['get_response_header'] = {}.get + with caplog.at_level(logging.INFO, logger='granian.access'): + fn(time.time(), time.perf_counter(), req, 200) + assert _log_message(caplog).endswith('- -') + + +def test_log_request_response_header_name_case_insensitive(caplog): + for atom in ('%({X-Trace-Id}o)s', '%({x-trace-id}o)s', '%({X-TRACE-ID}o)s'): + fn = log_request_builder(atom) + req = _base_req() + req['get_response_header'] = {'x-trace-id': 'tid-1'}.get + with caplog.at_level(logging.INFO, logger='granian.access'): + fn(time.time(), time.perf_counter(), req, 200) + assert 'tid-1' in caplog.records[-1].getMessage() + + +def test_asgi_access_log_response_header(caplog): + access_log, _ = asgi_build_access_logger(_RESP_HEADER_FMT) + scope = _asgi_scope() + resp_headers = [(b'x-trace-id', b'asgi-trace'), (b'content-type', b'text/plain')] + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), scope, 200, resp_headers) + msg = _log_message(caplog) + assert 'asgi-trace' in msg + assert 'text/plain' in msg + + +def test_asgi_access_log_absent_response_header_defaults_to_dash(caplog): + access_log, _ = asgi_build_access_logger(_RESP_HEADER_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _asgi_scope(), 200, ()) + assert _log_message(caplog).endswith('- -') + + +def test_rsgi_access_log_response_header(caplog): + access_log, _ = rsgi_build_access_logger(_RESP_HEADER_FMT) + scope = _rsgi_scope() + resp_headers = [('x-trace-id', 'rsgi-trace'), ('content-type', 'application/json')] + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), scope, 200, resp_headers) + msg = _log_message(caplog) + assert 'rsgi-trace' in msg + assert 'application/json' in msg + + +def test_rsgi_access_log_absent_response_header_defaults_to_dash(caplog): + access_log, _ = rsgi_build_access_logger(_RESP_HEADER_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _rsgi_scope(), 200, ()) + assert _log_message(caplog).endswith('- -') + + +def test_wsgi_access_log_response_header(caplog): + access_log, _ = wsgi_build_access_logger(_RESP_HEADER_FMT) + resp_headers = [('X-Trace-Id', 'wsgi-trace'), ('Content-Type', 'text/html')] + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _wsgi_scope(), 200, resp_headers) + msg = _log_message(caplog) + assert 'wsgi-trace' in msg + assert 'text/html' in msg + + +def test_wsgi_access_log_absent_response_header_defaults_to_dash(caplog): + access_log, _ = wsgi_build_access_logger(_RESP_HEADER_FMT) + with caplog.at_level(logging.INFO, logger='granian.access'): + access_log(time.time(), time.perf_counter(), _wsgi_scope(), 200, ()) + assert _log_message(caplog).endswith('- -')