Server access log format %b is the size of the whole response, not excluding headers

[cdunklau]

Long story short

Access log format %b is the size of the whole response, not excluding headers. The documentation says it should exclude the headers... "%b - Size of response in bytes, excluding HTTP headers".

https://github.com/aio-libs/aiohttp/blob/708d1f07bb7878c09b47df620cd6b38a9bec470b/docs/logging.rst#format-specification

While this looks like an implementation bug, I don't really understand the rationale behind the idea of excluding the headers from the length calculation... ISTM that the full response size would be a more useful metric. I'd recommend leaving the behavior as-is, and just updating the docs to correctly reflect the behavior.

Expected behaviour

Returning web.Response(body=None, status=200) to result in 0 for the %b replacement value, and returning web.Response(body=b'foo', status=200) to result in 3.

Actual behaviour

Results are 149 and 152, respectively. These are the lengths of the entire response, including status line and headers.

Steps to reproduce

Run this:

import sys
import logging
import asyncio

from aiohttp import web


def nobody(request):
    return web.Response(body=None, status=200)


def somebody(request):
    return web.Response(body=b'foo', status=200)


def init_app(*, loop):
    app = web.Application()
    app.router.add_route('GET', '/nobody', nobody)
    app.router.add_route('GET', '/somebody', somebody)
    return app


def main():
    logging.basicConfig(stream=sys.stderr, level=logging.DEBUG)

    loop = asyncio.get_event_loop()
    app = init_app(loop=loop)
    web.run_app(
        app,
        host="127.0.0.1",
        port=8080,
        access_log_format='%r response_length=%b',
    )

if __name__ == '__main__':
    main()

Hit the two endpoints:

curl -vv http://localhost:8080/nobody
curl -vv http://localhost:8080/somebody

Notice the log lines have the incorrect values for response length, if the documentation is to be believed:

INFO:aiohttp.access:GET /nobody HTTP/1.1 response_length=149
INFO:aiohttp.access:GET /somebody HTTP/1.1 response_length=152

Your environment

Mac, Python 3.6.3. Installed versions:

$ venv/bin/pip freeze
aiohttp==3.4.4
async-timeout==3.0.0
attrs==18.2.0
chardet==3.0.4
idna==2.7
idna-ssl==1.1.0
multidict==4.4.2
yarl==1.2.6

[aio-libs-bot]

GitMate.io thinks the contributor most likely able to help you is @asvetlov.

Possibly related issues are #2506 (Default access log format is wrong), #524 (Access log %(D)s has tens-of-microseconds precision), #2633 (Default access log format tries to include Referer header but spells it correctly and thus it doesn't work ), #705 (access log format is invalid when using gunicorn worker), and #3231 (Feature request: in the server, modifying the response headers after they have been sent should raise).

[asvetlov]

Let's keep the behavior as is but fix documentation.

[srinivasreddy]

can be closed?

[cdunklau]

I think so... the PR (#3312) raised a couple questions, but they seem to be out of scope of this issue. The doc bug fix has been merged.

[asvetlov]

Fixed by #3312

[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