Make access log use local time with timezone

[NewUserHa]

What do these changes do?

change access log use localtime and timezone instead all uctime

Are there changes in behavior for the user?

show localtime instead utctime if turn on access log

Related issue number

Fixes #3853

Checklist

• I think the code is well written
• Unit tests for the changes exist
• Documentation reflects the changes
• If you provide code modification, please add yourself to CONTRIBUTORS.txt
  • The format is <Name> <Surname>.
  • Please keep alphabetical order, the file is sorted by names.
• Add a new news fragment into the CHANGES folder
  • name it <issue_id>.<type> for example (588.bugfix)
  • if you don't have an issue_id change it to the pr id after creating the pr
  • ensure type is one of the following:
    • .feature: Signifying a new feature.
    • .bugfix: Signifying a bug fix.
    • .doc: Signifying a documentation improvement.
    • .removal: Signifying a deprecation or removal of public API.
    • .misc: A ticket has been closed, but it is not of interest to users.
  • Make sure to use full sentences with correct case and punctuation, for example: "Fix issue with non-ascii contents in doctest text files."

[codecov-io]

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

Impacted Files	Coverage Δ
aiohttp/web_log.py	97% <100%> (+0.06%)	⬆️
aiohttp/locks.py	92.85% <0%> (-7.15%)	⬇️
aiohttp/web_fileresponse.py	96.55% <0%> (-1.15%)	⬇️
aiohttp/streams.py	97.92% <0%> (-0.52%)	⬇️
aiohttp/helpers.py	96.96% <0%> (-0.51%)	⬇️

---

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.

[asvetlov]

A test and changelog record would be awesome!

[NewUserHa]

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

[webknjaz]

@NewUserHa google pytest monkeypatch

[asvetlov]

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

[NewUserHa]

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

[NewUserHa]

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

[asvetlov]

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.

[webknjaz]

I'm pretty sure that skip marker doesn't work on fixtures.

[NewUserHa]

but if use parameterizing, it seems to have to use fixtrue

[webknjaz]

Yes, but I'm talking about that the marked is supposed to skip things depending on the condition (PyPy). And if you apply it to fixtures, not test functions it just doesn't have any effect meaning it will never skip any tests.

[NewUserHa]

ok. I need to check some documents.

[webknjaz]

Currently, it's okay since you removed the fixture.

[NewUserHa]

but...

[webknjaz]

(needs fixing to actually work)

[webknjaz]

LGTM

[webknjaz]

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

[webknjaz]

Thanks, @NewUserHa!

[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?

[webknjaz]

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.

[NewUserHa]

release 3.5 against test_web_log.py 3.5.

#3863

[chansonzhang]

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

[asvetlov]

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

#5351 should land at 3.8