Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix logger after scope removal #884

Merged
merged 2 commits into from
Dec 12, 2020

Conversation

euri10
Copy link
Member

@euri10 euri10 commented Dec 12, 2020

This PR fixes a bug I introduced in #859 that wasn't caught with test.

Since the scope has been removed from the log record, the access log formatter is broken, we cant rely on the scope anymore to build the record

So the PR does 2 things:

  1. pass explicitly as extra kwarg of the access logger in httptools and h11 the required scope elements to build subsequent access log records (precisely root_path, path and query_string)
  2. derive the log records directly without relying on the scope and remove all unnecessary method that were using scope

see this trace:

INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [3287] using watchgod
INFO:     Started server process [3293]
INFO:     Waiting for application startup.
INFO:     ASGI 'lifespan' protocol appears unsupported.
INFO:     Application startup complete.
--- Logging error ---
Traceback (most recent call last):
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/logging/__init__.py", line 1081, in emit
    msg = self.format(record)
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/logging/__init__.py", line 925, in format
    return fmt.format(record)
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/logging/__init__.py", line 667, in format
    s = self.formatMessage(record)
  File "./uvicorn/logging.py", line 111, in formatMessage
    scope = recordcopy.__dict__["scope"]
KeyError: 'scope'
Call stack:
  File "<string>", line 1, in <module>
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/multiprocessing/spawn.py", line 116, in spawn_main
    exitcode = _main(fd, parent_sentinel)
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/multiprocessing/spawn.py", line 129, in _main
    return self._bootstrap(parent_sentinel)
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "./uvicorn/subprocess.py", line 61, in subprocess_started
    target(sockets=sockets)
  File "./uvicorn/server.py", line 48, in run
    loop.run_until_complete(self.serve(sockets=sockets))
  File "./uvicorn/protocols/http/httptools_impl.py", line 396, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "./uvicorn/middleware/proxy_headers.py", line 45, in __call__
    return await self.app(scope, receive, send)
  File "./app.py", line 26, in app
    await send({
  File "./uvicorn/protocols/http/httptools_impl.py", line 458, in send
    self.access_logger.info(
Message: '%s - "%s %s HTTP/%s" %d'
Arguments: ('127.0.0.1:51410', 'GET', '/', '1.1', 200)
--- Logging error ---
Traceback (most recent call last):
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/logging/__init__.py", line 1081, in emit
    msg = self.format(record)
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/logging/__init__.py", line 925, in format
    return fmt.format(record)
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/logging/__init__.py", line 667, in format
    s = self.formatMessage(record)
  File "./uvicorn/logging.py", line 111, in formatMessage
    scope = recordcopy.__dict__["scope"]
KeyError: 'scope'
Call stack:
  File "<string>", line 1, in <module>
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/multiprocessing/spawn.py", line 116, in spawn_main
    exitcode = _main(fd, parent_sentinel)
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/multiprocessing/spawn.py", line 129, in _main
    return self._bootstrap(parent_sentinel)
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/home/lotso/.asdf/installs/python/3.8.6/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "./uvicorn/subprocess.py", line 61, in subprocess_started
    target(sockets=sockets)
  File "./uvicorn/server.py", line 48, in run
    loop.run_until_complete(self.serve(sockets=sockets))
  File "./uvicorn/protocols/http/httptools_impl.py", line 396, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "./uvicorn/middleware/proxy_headers.py", line 45, in __call__
    return await self.app(scope, receive, send)
  File "./app.py", line 26, in app
    await send({
  File "./uvicorn/protocols/http/httptools_impl.py", line 458, in send
    self.access_logger.info(
Message: '%s - "%s %s HTTP/%s" %d'
Arguments: ('127.0.0.1:51410', 'GET', '/favicon.ico', '1.1', 200)

@euri10 euri10 mentioned this pull request Dec 12, 2020
Copy link
Member

@florimondmanca florimondmanca left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yup, good catch!

@florimondmanca florimondmanca merged commit a227f17 into encode:master Dec 12, 2020
@euri10 euri10 deleted the fix_logger_post_scope_leak branch December 13, 2020 12:53
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants