Scope sent in access logs by default

[euri10]

Checklist

• The bug is reproducible against the latest release and/or master.
• There are no similar issues or pull requests to fix it yet.

Describe the bug

prompted by @alicederyn in gitter you can leak headers from the scope in the access logs given that you use json formatting for your logging.

To reproduce

logging.yaml

version: 1
formatters:
  json_formatter:
    format: '%(levelname)s'
    "()": "pythonjsonlogger.jsonlogger.JsonFormatter"
handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: json_formatter
    stream: ext://sys.stdout
loggers:
  uvicorn:
    level: DEBUG
    handlers: [console]
    propagate: no
root:
  level: DEBUG
  handlers: [console]

cookieapp.py

from starlette.requests import Request
from starlette.responses import Response


import uvicorn


async def app(scope, receive, send):
    request = Request(scope, receive)
    mycookie = request.cookies.get("mycookie")
    if mycookie:
        response = Response(mycookie, media_type="text/plain")
    else:
        response = Response("Hello, world!", media_type="text/plain")
        response.set_cookie("mycookie", "Hello, cookies!")

    await response(scope, receive, send)


if __name__ == '__main__':
    uvicorn.run("cookieapp:app", log_level="debug", log_config="logging.yaml")

returns :

{"levelname": "INFO", "color_message": "Uvicorn running on \u001b[1m%s://%s:%d\u001b[0m (Press CTRL+C to quit)"}
{"levelname": "INFO", "status_code": 200, "scope": {"type": "http", "asgi": {"version": "3.0", "spec_version": "2.1"}, "http_version": "1.1", "server": ["127.0.0.1", 8000], "client": ["127.0.0.1", 35808], "scheme": "http", "method": "GET", "root_path": "", "path": "/", "raw_path": "b'/'", "query_string": "b''", "headers": [["b'host'", "b'127.0.0.1:8000'"], ["b'connection'", "b'keep-alive'"], ["b'cache-control'", "b'max-age=0'"], ["b'dnt'", "b'1'"], ["b'upgrade-insecure-requests'", "b'1'"], ["b'user-agent'", "b'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.116 Safari/537.36'"], ["b'accept'", "b'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9'"], ["b'sec-fetch-site'", "b'none'"], ["b'sec-fetch-mode'", "b'navigate'"], ["b'sec-fetch-user'", "b'?1'"], ["b'sec-fetch-dest'", "b'document'"], ["b'accept-encoding'", "b'gzip, deflate, br'"], ["b'accept-language'", "b'en-US,en;q=0.9,fr;q=0.8'"], ["b'cookie'", "b'mycookie=\"Hello\\\\054 cookies!\"'"]]}}

Expected behavior

we should hide the headers like we do in by default [[?? and provide a mechanism (flag ??) so that people who truly want the scope in logs can have it ]]

uvicorn/uvicorn/middleware/message_logger.py

Line 7 in 79a72e3

"headers": "<...>",

Actual behavior

Debugging material

Environment

• OS / Python / Uvicorn version: just run uvicorn --version
• The exact command you're running uvicorn with, all flags you passed included. If you run it with gunicorn please do the same. If there is a reverse-proxy involved and you cannot reproduce without it please give the minimal config of it to reproduce.

Additional context

[NightMachinery]

My log filtering no longer works, and I suppose this change is the culprit?

class EndpointFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        try:
            return record.scope.get('path', '') != '/zsh/nolog/'
        except:
            logger.warn(traceback.format_exc())
            return True

[tonkolviktor]

Hallo uvicorn,

#859 (comment)

Very funny, please let me/us know how can I/we scream so I/we'd get a flag.

BTW this no longer works because of this MR:
https://stackoverflow.com/a/64807716

Thanks!

[alicederyn]

Perhaps add an extension to register a callback function that defaults to the current log call? That way users can log whatever they want.