hypercorn overrides application logging handlers

[leifwalsh]

At https://github.com/pgjones/hypercorn/blob/8ae17ca68204d9718389fb3649ca0ed6ba851906/src/hypercorn/logging.py#L36 hypercorn overrides any application-defined logging handlers that may have already been set up - not even adding to them, just overwriting them.

This means that if you're trying to log everything with structlog or another logging system, you can't modify how hypercorn.access gets logged. For some reason this problem doesn't happen to hypercorn.error and I'm not sure why?

I'm actually not sure if this is a problem with hypercorn or a problem with quart run, but basically I can't figure out how to use quart run on the CLI and configure hypercorn not to override this logger handler.

If I edit hypercorn/logging.py to add if not logger.handlers: before the line I linked above, then my logging config is respected. Maybe that is a reasonable fix, or I need to learn how to configure hypercorn logging properly in this scenario (and maybe we can improve the docs in that case)?

[rajaravivarma-r]

I'm not sure if it is a related issue, but I'm not able to print or log anything from a middleware custom receive method.

And weirdly the print and logging statements in custom send gets printed twice.

Here is a minimal reproducible example,

import sys
import logging
import time

from fastapi import FastAPI, Request

app = FastAPI()

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler(sys.stdout)
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)

class LogRequestResponseMiddleware:
    def __init__(self, app):
        self.app = app

    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            await self.app(scope, receive, send)
            return

        async def receive_logging_request_body_size():
            print("Print: before receive()") # Doesn't work
            logger.warn("Log: before receive()") # Doesn't work
            message = await receive()
            print("Print: after receive()") # Doesn't work
            logger.warn("Log: after receive()") # Doesn't work
            assert message["type"] == "http.request"

            return message

        async def send_log_response(message):
            print("Print: before send()")
            logger.warn("Log: before send()")
            await send(message)
            print("Print: after send()")
            logger.warn("Log: after send()")


        start_time = time.time()
        await self.app(scope, receive_logging_request_body_size, send_log_response)
        process_time = time.time() - start_time

        print(f"Print: Runtime {process_time}")

app.add_middleware(LogRequestResponseMiddleware)

@app.api_route("/{full_path:path}", methods=["GET", "POST", "PUT", "PATCH", "DELETE"])
async def fallback_routes(request: Request, full_path: str):
    print(f"full_path matcher: {full_path}")
    return {"message": "ok"}

Output:

full_path matcher: api
Print: before send()
Log: before send()
Print: after send()
Log: after send()
Print: before send()
Log: before send()
Print: after send()
Log: after send()
Print: Runtime 0.0007669925689697266

[ldo]

I hit this issue with both uvicorn and hypercorn. Here’s one way to configure Python logging to get around it:

LOGGING_NAME = "my_test_server"

def get_logger() :
    "retrieves the global logger instance, suitably configuring" \
    " it as necessary."
    logger = logging.getLogger(LOGGING_NAME)
    try :
        loglevel = int(os.getenv("LOGLEVEL", ""))
        if loglevel < 0 :
            raise ValueError("invalid loglevel")
        #end if
    except ValueError :
        loglevel = logging.INFO
    #end try
    logger.setLevel(loglevel)
    if not logger.hasHandlers() :
        # hypercorn seems to quietly ignore my log messages,
        # so I insert my own logging setup to get around this.
        stderr_handler = logging.StreamHandler(sys.stderr)
        stderr_handler.setFormatter(logging.Formatter(fmt = "%(levelname)-8s: %(message)s"))
        logger.addHandler(stderr_handler)
        logger.propagate = False
    #end if
    return \
        logger
#end get_logger

On the first call, it will configure the logger object before returning it; on subsequent calls, it will return the same already-configured logger object.

[ldo]

Here’s a slightly improved version, that does all the setup just once:

def get_logger() :
    "retrieves the global logger instance, suitably configuring" \
    " it as necessary."
    logger = logging.getLogger(LOGGING_NAME)
    if not logger.hasHandlers() :
        try :
            loglevel = int(os.getenv("LOGLEVEL", ""))
            if loglevel < 0 :
                raise ValueError("invalid loglevel")
            #end if
        except ValueError :
            loglevel = logging.INFO
        #end try
        logger.setLevel(loglevel)
        stderr_handler = logging.StreamHandler(sys.stderr)
        stderr_handler.setFormatter(logging.Formatter(fmt = "%(levelname)-8s: %(message)s"))
        logger.addHandler(stderr_handler)
        logger.propagate = False
    #end if
    return \
        logger
#end get_logger

[sedmicha]

Same issue. I tried following the docs to no avail and until I finally found this. There should really be a way to configure the logger that doesn't involve modifying the source code of hypercorn.

[Paillat-dev]

Here is my solution:

    class CustomLogger(HypercornLogger):
        def __init__(self, *args, **kwargs) -> None:
            super().__init__(*args, **kwargs)
            if self.error_logger:
                patch(self.error_logger)
            if self.access_logger:
                patch(self.access_logger)
    app_config = Config()
    app_config.logger_class = CustomLogger