logging / log format

[jmcaine]

• aiohttp-devtools version: 3.8.1-cp39-cp39-manylinux_2_5_x86_64
• aiohttp version: 3.6.2
• python version: 3.9.2
• Platform: Debian Linux

Issue Summary

Cannot throttle logging; logging is "mangled", further motivating the ability to throttle it.

Steps to reproduce

Simply run adev runserver. Log files include verbose "details" like this:

[05:56:38]                                                                                                                                                                     
          tyle.resetm ●                                                                                                                                                        
                       tyle.resetm GET / 200 20.6KB 22ms                                                                                                                       
                                                        tyle.resetm
2022-06-07 05:56:38,361 - DEBUG : app.main:732 -- Websocket prepared, listening for messages...
details: {
    'request_duration_ms': 0.562,
    'request_headers': {
        'Host': 'localhost:8000',
        'User-Agent': 'Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0',
        'Accept': 'image/webp,*/*',
        'Accept-Language': 'en-US,en;q=0.5',
        'Accept-Encoding': 'gzip, deflate',
        'Connection': 'keep-alive',
        'Cookie': (
            'AIOHTTP_SESSION=gAAAAABin0sG9FkEZbsZ8BxqBDHa3Rvdl0IWkD6CkVkWz8lFBqOLvqRrY-OiLXMupa4rx9bCQyzXt3kk7mQpFl-UI'
            'JDxBt31crLIbmq7W3rlSQGNUvNnzAS8QozGfBT3-Tu-NgHtKjq0CsNgcyzwO-5oghmZoNePZ5MVxQltbURK_aKVE4-9R1Wr-Ai0KZfEuZ'
            'ax-P_D3xzu'
        ),
    },
    'request_body': None,
    'request_size': '',
    'response_headers': {
        'Content-Type': 'text/plain; charset=utf-8',
        'Content-Length': '14',
        'Date': 'Tue, 07 Jun 2022 12:56:38 GMT',
        'Server': 'Python/3.9 aiohttp/3.8.1',
    },
    'response_body': '404: Not Found',
}

Not only are the log strings malformatted with weird symbols and constant color changes to distract the eyes, they're very long and make it very hard to isolate my own (much more terse) app debug info. None of this logging occurs when running via standard "python -m aiohttp.web", so I assume it's supposed to be additionally "helpful", but it's not. I have turned off sub-package logging via

logging.getLogger('aiosqlite').setLevel(logging.CRITICAL)
logging.getLogger('aiohttp').setLevel(logging.CRITICAL)

and even attempted this for 'adev' package, but it has no effect, presumably since I'm not importing adev directly.

I see in aiohttp_devtools/logs.py:83 the code that pumps out the longest "msg" detail for every single message:

msg = 'details: {}\n{}' ...

As a workaround, I just set log_level to 'CRITICAL' on line 112 (of logs.py, just in my local codebase). Since this setting is tied to the --verbose cli, perhaps one easy approach would be to extend the --verbose idea to include a --terse or --critical-only or something, to allow developers to easily turn off all of the extra adev logging.

TIA

[Dreamsorcerer]

Maybe we can do something to make it easier to customise, feel free to come up with some suggestions.

But, the logger you are complaining about is aiohttp.access. It also only outputs all those details on a non-successful response (note the 404 in your output), which is generally very useful to see in the terminal while developing.

You can see in the code, that we install a custom formatter for aiohttp:
https://github.com/aio-libs/aiohttp-devtools/blob/master/aiohttp_devtools/logs.py#L127
And set the aiohttp_access log level to DEBUG or INFO:
https://github.com/aio-libs/aiohttp-devtools/blob/master/aiohttp_devtools/logs.py#L146

[Dreamsorcerer]

Maybe we can just change that log_level variable. In other projects I've used -v and -q as a count variable, so the log level is something like 20 - (10 * v) + (10 * q). That way you can just make it critical with -qqq or ensure everything is logged with -vv.

[jmcaine]

I see. Thank you; knowing that it's aiohttp.access is helpful. The verbosity is debatable, and not a big problem for me (especially since I can throttle it now), but the first three lines in my above snippet (and often more lines than that) were malformed and caused weird color-changes in the terminal output. again:

[05:56:38]
tyle.resetm ●
tyle.resetm GET / 200 20.6KB 22ms
tyle.resetm

That's the bit that seemed "broken". I say "were" and "seemed" because, since I figured out how to turn this off long ago, I haven't encountered it again. It may also be that somebody fixed something. But I thought I'd finally close this out, one way or another. If you'd like me to try to reproduce this anew, I'll be happy to give it a shot. If you're pretty sure that's a "known" and historic issue, I won't go to any trouble.

Thanks again. Sorry for the delayed response.

[Dreamsorcerer]

There has been no new release in that time, so I don't think anything should have changed.
Some minor formatting issues are probably not something I'm going to be bothered about exploring, but if someone decides to investigate and provide a fix, we'll certainly accept it.

[jmcaine]

Totally understandable. Thank you for your attention to it. I'll close it, with this. And if I get time, I'll look into it further and maybe offer a fix.