feat(asgi): no longer add NullHandler to the falcon logger (#2595)

Author: vytas7

MANIFEST.in

@@ -1,6 +1,6 @@
 recursive-include docs *.rst *.md *.html *.ico *.png *.py *.svg
 recursive-include e2e-tests *.py *.css *.html *.js
-recursive-include examples *.py
+recursive-include examples *.py *.yaml
 recursive-include falcon *.pyx
 recursive-include tests *.py *.pyx
 include .coveragerc
@@ -14,6 +14,8 @@ include docs/conf.py docs/Makefile
 include falcon/py.typed
 graft docs/_static
 graft docs/_templates
+graft examples/asgilook/requirements
+graft examples/look/requirements
 graft requirements
 graft tools
 prune docs/_build

docs/_newsfragments/2594.misc.rst

@@ -0,0 +1,4 @@
+Falcon no longer adds an instance of :class:`logging.NullHandler` to the
+``falcon`` logger, so ASGI application tracebacks may still reach
+``sys.stderr`` via the :any:`logging.lastResort` handler in the absence of
+configuration (see also: :ref:`debugging_asgi_applications`).

docs/user/faq.rst

@@ -1414,7 +1414,7 @@ is non-zero, we can overwrite that value in the header.
 Why do I see no error tracebacks in my ASGI application?
 --------------------------------------------------------
 
-When using Falcon with an ASGI server like Uvicorn,
+When using Falcon with an ASGI server,
 you might notice that server errors do not include any traceback by default.
 This behavior differs from WSGI, where the PEP-3333 specification defines the
 `wsgi.errors <https://peps.python.org/pep-3333/#environ-variables>`__ stream
@@ -1424,8 +1424,17 @@ This behavior differs from WSGI, where the PEP-3333 specification defines the
 Since there is no standardized way to log errors back to the ASGI server,
 the framework simply opts to log them using the ``falcon``
 :class:`logger <logging.Logger>`.
+As a well-behaved library, Falcon does not preconfigure any loggers since that
+might interfere with the user's logging setup.
 
-The easiest way to get started is configuring the root logger via
+Starting with Falcon :doc:`4.3 </changes/4.3.0>`, however, the framework no
+longer adds an instance of :class:`logging.NullHandler` to the ``falcon``
+logger, so error tracebacks may still reach ``sys.stderr`` via the
+:any:`logging.lastResort` handler (but it depends on the existing logging
+configuration of the ASGI server in question).
+
+If you are seeing an HTTP 500 error response without any corresponding
+traceback, the easiest way to get started is configuring the root logger via
 :func:`logging.basicConfig`:
 
 .. code:: python
@@ -1451,4 +1460,4 @@ By adding the above logging configuration, you should now see tracebacks logged
 to :any:`stderr <sys.stderr>` when accessing ``/things``.
 
 For additional details on this topic,
-please refer to :ref:`debugging_asgi_applications`.
+please refer to the ASGI tutorial: :ref:`debugging_asgi_applications`.

docs/user/tutorial-asgi.rst

@@ -129,8 +129,13 @@ Unlike WSGI, the ASGI specification has no standard mechanism for logging
 errors back to the application server, so Falcon falls back to the stdlib's
 :mod:`logging` (using the ``falcon`` :class:`logger <logging.Logger>`).
 
-As a well-behaved library, Falcon does not configure any loggers since that
+As a well-behaved library, Falcon does not preconfigure any loggers since that
 might interfere with the user's logging setup.
+(Starting with Falcon :doc:`4.3 </changes/4.3.0>`, however, the framework no
+longer adds an instance of :class:`logging.NullHandler` to the ``falcon``
+logger, so error tracebacks may still reach ``sys.stderr`` via the
+:any:`logging.lastResort` handler.)
+
 Here's how you can set up basic logging in your ASGI Falcon application via
 :func:`logging.basicConfig`:
 
@@ -165,6 +170,23 @@ might look like:
         raise Exception("Something went wrong!")
     Exception: Something went wrong!
 
+Your ASGI application server may also provide means to configure logging.
+For instance, Uvicorn (that we are using in this tutorial) can be pointed to a
+logging configuration via the ``--log-config`` command line parameter (or via
+its config file)::
+
+  uvicorn --log-config logging.yaml asgilook.app:app
+
+A suitable logging configuration (including the ``falcon`` logger) for Uvicorn
+could look like:
+
+.. literalinclude:: ../../examples/asgilook/logging.yaml
+    :caption: logging.yaml
+    :language: python
+
+Falcon's tracebacks should now blend into Uvicorn's own logs seamlessly.
+You can also configure logging to files, syslog, or other destinations, in this way.
+
 .. note::
     While logging is helpful for development and debugging, be mindful of
     logging sensitive information. Ensure that log files are stored securely

examples/asgilook/logging.yaml

@@ -0,0 +1,32 @@
+version: 1
+disable_existing_loggers: false
+formatters:
+  default:
+    (): 'uvicorn.logging.DefaultFormatter'
+    fmt: '%(levelprefix)s [%(asctime)s] %(message)s'
+  access:
+    (): 'uvicorn.logging.AccessFormatter'
+    fmt: '%(levelprefix)s [%(asctime)s] %(client_addr)s - "%(request_line)s" %(status_code)s'
+handlers:
+  default:
+    class: logging.StreamHandler
+    formatter: default
+    stream: ext://sys.stderr
+  access:
+    class: logging.StreamHandler
+    formatter: access
+    stream: ext://sys.stdout
+loggers:
+  falcon:
+    level: WARNING
+    handlers:
+      - default
+  uvicorn:
+    level: INFO
+    handlers:
+      - default
+  uvicorn.access:
+    level: INFO
+    propagate: false
+    handlers:
+      - access

falcon/__init__.py

@@ -649,4 +649,12 @@
 # NOTE(kgriffs): Only to be used internally on the rare occasion that we
 #   need to log something that we can't communicate any other way.
 _logger = _logging.getLogger('falcon')
-_logger.addHandler(_logging.NullHandler())
+
+# NOTE(vytas): We used to add a NullHandler() to the above _logger;
+#   which *could* be done according to the stdlib's docs,
+#   "*if* you want to prevent your library's logged events being output to
+#   sys.stderr in the absence of logging configuration".
+#
+#   However, this has mostly resulted in confusion for people trying the ASGI
+#   flavor of the framework as HTTP 500 tracebacks may disappear completely,
+#   so the revised choice is NOT to prevent last resort logging to sys.stderr.