def test_access_logger_atoms(mocker) -> None:
utcnow = datetime.datetime(1843, 1, 1, 0, 30)
mock_datetime = mocker.patch("aiohttp.datetime.datetime")
mock_getpid = mocker.patch("os.getpid")
mock_datetime.utcnow.return_value = utcnow
mock_getpid.return_value = 42
log_format = '%a %t %P %r %s %b %T %Tf %D "%{H1}i" "%{H2}i"'
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, log_format)
request = mock.Mock(headers={'H1': 'a', 'H2': 'b'},
method="GET", path_qs="/path",
version=(1, 1),
remote="127.0.0.2")
response = mock.Mock(headers={}, body_length=42, status=200)
access_logger.log(request, response, 3.1415926)
assert not mock_logger.exception.called
expected = ('127.0.0.2 [01/Jan/1843:00:29:56 +0000] <42> '
'GET /path HTTP/1.1 200 42 3 3.141593 3141593 "a" "b"')
extra = {
'first_request_line': 'GET /path HTTP/1.1',
'process_id': '<42>',
'remote_address': '127.0.0.2',
'request_start_time': '[01/Jan/1843:00:29:56 +0000]',
'request_time': 3,
'request_time_frac': '3.141593',
'request_time_micro': 3141593,
'response_size': 42,
'response_status': 200,
'request_header': {'H1': 'a', 'H2': 'b'},
}
mock_logger.info.assert_called_with(expected, extra=extra)
def test_access_logger_atoms(monkeypatch, log_format, expected, extra) -> None:
class PatchedDatetime(datetime.datetime):
@staticmethod
def now(tz):
return datetime.datetime(1843, 1, 1, 0, 30, tzinfo=tz)
monkeypatch.setattr("datetime.datetime", PatchedDatetime)
monkeypatch.setattr("time.timezone", -28800)
monkeypatch.setattr("os.getpid", lambda: 42)
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, log_format)
request = mock.Mock(
headers={
"H1": "a",
"H2": "b"
},
method="GET",
path_qs="/path",
version=aiohttp.HttpVersion(1, 1),
remote="127.0.0.2",
)
response = mock.Mock(headers={}, body_length=42, status=200)
access_logger.log(request, response, 3.1415926)
assert not mock_logger.exception.called, mock_logger.exception.call_args
mock_logger.info.assert_called_with(expected, extra=extra)
def test_logger_no_message() -> None:
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, "%r %{content-type}i")
extra_dict = {
"first_request_line": "-",
"request_header": {"content-type": "(no headers)"},
}
access_logger.log(None, None, 0.0)
mock_logger.info.assert_called_with("- (no headers)", extra=extra_dict)
def test_access_logger_unix_socket() -> None:
log_format = "|%a|"
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, log_format)
request = mock.Mock(headers={"User-Agent": "Mock/1.0"}, version=(1, 1), remote="")
response = mock.Mock()
access_logger.log(request, response, 0.0)
assert not mock_logger.error.called
expected = "||"
mock_logger.info.assert_called_with(expected, extra={"remote_address": ""})
def test_logger_no_message() -> None:
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger,
"%r %{content-type}i")
extra_dict = {
'first_request_line': '-',
'request_header': {'content-type': '(no headers)'}
}
access_logger.log(None, None, 0.0)
mock_logger.info.assert_called_with("- (no headers)", extra=extra_dict)
def test_access_logger_unix_socket() -> None:
log_format = '|%a|'
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, log_format)
request = mock.Mock(headers={"User-Agent": "Mock/1.0"}, version=(1, 1),
remote="")
response = mock.Mock()
access_logger.log(request, response, 0.0)
assert not mock_logger.error.called
expected = '||'
mock_logger.info.assert_called_with(expected, extra={'remote_address': ''})
def test_logger_no_message() -> None:
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger,
"%r %{content-type}i")
extra_dict = {
'first_request_line': '-',
'request_header': {'content-type': '(no headers)'}
}
access_logger.log(None, None, 0.0)
mock_logger.info.assert_called_with("- (no headers)", extra=extra_dict)
def test_access_logger_dicts() -> None:
log_format = '%{User-Agent}i %{Content-Length}o %{None}i'
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, log_format)
request = mock.Mock(headers={"User-Agent": "Mock/1.0"}, version=(1, 1),
remote="127.0.0.2")
response = mock.Mock(headers={"Content-Length": 123})
access_logger.log(request, response, 0.0)
assert not mock_logger.error.called
expected = 'Mock/1.0 123 -'
extra = {
'request_header': {"User-Agent": "Mock/1.0", 'None': '-'},
'response_header': {'Content-Length': 123}
}
mock_logger.info.assert_called_with(expected, extra=extra)
def test_access_logger_dicts() -> None:
log_format = '%{User-Agent}i %{Content-Length}o %{None}i'
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, log_format)
request = mock.Mock(headers={"User-Agent": "Mock/1.0"}, version=(1, 1),
remote="127.0.0.2")
response = mock.Mock(headers={"Content-Length": 123})
access_logger.log(request, response, 0.0)
assert not mock_logger.error.called
expected = 'Mock/1.0 123 -'
extra = {
'request_header': {"User-Agent": "Mock/1.0", 'None': '-'},
'response_header': {'Content-Length': 123}
}
mock_logger.info.assert_called_with(expected, extra=extra)
def test_access_logger_atoms(mocker) -> None:
utcnow = datetime.datetime(1843, 1, 1, 0, 30)
mock_datetime = mocker.patch("aiohttp.datetime.datetime")
mock_getpid = mocker.patch("os.getpid")
mock_datetime.utcnow.return_value = utcnow
mock_getpid.return_value = 42
log_format = '%a %t %P %r %s %b %T %Tf %D "%{H1}i" "%{H2}i"'
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, log_format)
request = mock.Mock(headers={
'H1': 'a',
'H2': 'b'
},
method="GET",
path_qs="/path",
version=(1, 1),
remote="127.0.0.2")
response = mock.Mock(headers={}, body_length=42, status=200)
access_logger.log(request, response, 3.1415926)
assert not mock_logger.exception.called
expected = ('127.0.0.2 [01/Jan/1843:00:29:56 +0000] <42> '
'GET /path HTTP/1.1 200 42 3 3.141593 3141593 "a" "b"')
extra = {
'first_request_line': 'GET /path HTTP/1.1',
'process_id': '<42>',
'remote_address': '127.0.0.2',
'request_start_time': '[01/Jan/1843:00:29:56 +0000]',
'request_time': 3,
'request_time_frac': '3.141593',
'request_time_micro': 3141593,
'response_size': 42,
'response_status': 200,
'request_header': {
'H1': 'a',
'H2': 'b'
},
}
mock_logger.info.assert_called_with(expected, extra=extra)
def test_access_logger_format() -> None:
log_format = '%T "%{ETag}o" %X {X} %%P'
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, log_format)
expected = '%s "%s" %%X {X} %%%s'
assert expected == access_logger._log_format
def test_logger_no_transport() -> None:
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, "%a")
access_logger.log(None, None, 0)
mock_logger.info.assert_called_with("-", extra={"remote_address": "-"})
def test_logger_internal_error() -> None:
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, "%D")
access_logger.log(None, None, "invalid")
mock_logger.exception.assert_called_with("Error in logging")
def test_logger_no_transport() -> None:
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, "%a")
access_logger.log(None, None, 0)
mock_logger.info.assert_called_with("-", extra={'remote_address': '-'})
def test_logger_internal_error() -> None:
mock_logger = mock.Mock()
access_logger = AccessLogger(mock_logger, "%D")
access_logger.log(None, None, 'invalid')
mock_logger.exception.assert_called_with("Error in logging")