Codecov Report

Merging #3860 into master will decrease coverage by 0.09%.
The diff coverage is 100%.

@@            Coverage Diff            @@
##           master    #3860     +/-   ##
=========================================
- Coverage   97.96%   97.86%   -0.1%     
=========================================
  Files          43       43             
  Lines        8588     8590      +2     
  Branches     1373     1373             
=========================================
- Hits         8413     8407      -6     
- Misses         71       78      +7     
- Partials      104      105      +1

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 4273c7f...c5f66e6. Read the comment docs.

I read the test codes about web_log.py. but how to test this since there are expected and extras dicts in it?

@NewUserHa google pytest monkeypatch

tests/test_web_log.py
Something like:

def test_logger_time() -> None:
    mock_logger = mock.Mock()
    access_logger = AccessLogger(mock_logger, "%t")
    access_logger.log(None, None, 0)
    mock_logger.info.assert_called_with("[1/2/3:12:13:14 +0200]", extra={'request_start_time': ...})

No need for monkey-patching here

I know. the problem is:
there's a test already like that:

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)

I meant, can it test/assert the timezone? because request_start_time is fixed, then the expected always will be the same

well. Will adding tz to datetime.datetime(1843, 1, 1, 0, 30) of test_access_logger_atoms work?

I guess yes, please extract checking of %t format into a separate test.
Should be easy to do.
test_access_logger_atoms() tests too much format options.
Now I see that monkey-patching is the easiest way to check your functionality, that's fine.

It should be good to merge once CI jobs show up as green.

Thanks, @NewUserHa!

thanks for your review and merge.
but why is test_access_logger_atoms SKIPPED in release 3.5 with running pytest against the 3.5 test_web_log.py?
need change log?

Because you submitted the PR against devel which is future 4.0. 3.5 is in its own stable branch.

And yes, the changelog fragment is needed. We just missed it. So please submit a follow-up PR with it.

release 3.5 against test_web_log.py 3.5.

#3863

I use version 3.7.3 and the timestamp in access log still in UTC timezone

Thanks for the reminder. We missed to backport the PR.

#5351 should land at 3.8