Make log format %b doc reflect behavior and docstring

[cdunklau]

What do these changes do?

Update logging doc to reflect behavior and aiohttp.helpers.AccessLogger docs, fixing #3307.

I dug into the tests to make sure the full-response-size behavior is tested, but I'm confused about what this test is doing with response.body_length, or rather, what that attribute actually means:

aiohttp/tests/test_helpers.py

Lines 185 to 216 in 4c4401a

	def test_access_logger_atoms(mocker) -> None:
	utcnow = datetime.datetime(1843, 1, 1, 0, 30)
	mock_datetime = mocker.patch("aiohttp.helpers.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 = helpers.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)

ISTM that body_length would be the length of the response content, excluding status line, headers, and terminating blank line, but that doesn't reflect how it's used... it looks like that's the length of the entire response, not just the content. @asvetlov could you suggest how to make sure this test exercises that behavior, or should I work on a separate one?

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 #3312 into master will decrease coverage by 0.03%.
The diff coverage is n/a.

@@            Coverage Diff             @@
##           master    #3312      +/-   ##
==========================================
- Coverage   98.06%   98.02%   -0.04%     
==========================================
  Files          43       43              
  Lines        8018     8018              
  Branches     1355     1355              
==========================================
- Hits         7863     7860       -3     
- Misses         63       65       +2     
- Partials       92       93       +1

Impacted Files	Coverage Δ
aiohttp/tcp_helpers.py	90% <0%> (-6.67%)	⬇️
aiohttp/client_reqrep.py	97.48% <0%> (-0.17%)	⬇️

---

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 4c4401a...85f8855. Read the comment docs.

[asvetlov]

Sorry, was pretty busy today.
You've raised a complex question actually.

The source of misunderstanding is:
%b uses resp.body_length but .body_length is calculated from writer.output_size.
Ideally we can support both full message size and body length.

Logger codes were designed after Apache mnemonics: https://httpd.apache.org/docs/2.4/mod/mod_log_config.html#formats
Don't ask me why, but let's be consistent.

%b doesn't count http headers size.
To do this in aiohttp we can save writer.output_size after StreamResponse.prepare() for storing the size of headers. resp.body_length can substract the value from writer.output_size.

Do you like the idea?

[cdunklau]

It looks like "both full message size and body length" were indeed supported... %O did exist at one point, and was dropped in 0e99cfb. At the same time, the docstring was changed to say %b Size of response in bytes, including HTTP headers, as it is now. It looks like that's the change that brought the docstring and the logging.rst doc out of sync. Unfortunately, the discussion in #1673 is not all that enlightening. Perhaps @fafhrd91 and @kxepal can provide their input on how this should proceed?

I seem to have stumbled on something more complex than just the doc bug. My feeling is that we should for now just merge this doc change to re-sync, and address the underlying "what the behavior should be" question elsewhere.

[kxepal]

Sorry, I can't help much here since the only things I do with access logger is turn it off or keep it in default state.

But if docs says one, but code works in other way, it's good to fix the docs at the first place and then propose changes to the code if they are needed.

[asvetlov]

Merged!

@cdunklau thanks!

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a [new issue] for related bugs.
If you feel like there's important points made in this discussion, please include those exceprts into that [new issue].
[new issue]: https://github.com/aio-libs/aiohttp/issues/new