Google Cloud Working not working with Gunicorn

Question

Up until now I've been using uvicorn directly to run a fastapi app running on Render which has google cloud logging enabled as such:

def configure_logging():
    # Reset root logger config
    logging.root.handlers = []
    logging.root.setLevel(level)

    stream_handler = logging.StreamHandler(sys.stdout)
    stream_handler.setFormatter(ConsoleFormatter(fmt=LOG_FORMAT, access_fmt=ACCESS_FORMAT))
    stream_handler.setLevel(level)
    logging.root.addHandler(stream_handler)

    logging.root.info(
            f"/etc/secrets/google-service-account.json exists? {os.path.exists('/etc/secrets/google-service-account.json')}"
    )
    gcp_client = google_logging.Client.from_service_account_json("/etc/secrets/google-service-account.json")
    gcp_client.setup_logging(log_level=level, labels={"source": "render", "external": "true"})

And I have an endpoint like the following to test the logging:

# main.py
logging.configure_logging()
app = FastAPI()
app.include_router(healthcheck_router.router)

# healthcheck_router.py
from fastapi import APIRouter

import logging as py_logging
from logging_tree import printout

from easel.api.common import logging

log = logging.get_logger(__name__)
router = APIRouter()


@router.get("/healthcheck")
async def healthcheck():
    log.info("Test log")
    log.info(f"Py Logging root handlers: {py_logging.root.handlers}")
    printout()
    return {"healthy": True}

This was all working fine with my logs showing up in Google Cloud Logging with the label: 'source': 'render' until I decided to run Gunicorn with Uvicorn workers as they recommend on the fastapi website: https://fastapi.tiangolo.com/deployment/server-workers/

Now with gunicorn i'm running it as follows:

gunicorn --bind '0.0.0.0:10000' -w 1 -k uvicorn.workers.UvicornWorker easel.api.main:app

I can see the logs getting printed to stdout using my ConsoleFormatter totally fine, however the logs arent showing up in Google Cloud Logging (with the label or without)... When I revert it to just using uvicorn it works again, unfortunately running without gunicorn is not possible due to other reasons.

Python v3.8, Uvicorn 0.22.0, Gunicorn v20.1.0, google-cloud-logging v3.5.0

I've tried running a python interpreter on the box and instantiating a logger, that works as expected and my logs show up in GCL.

I've triple checked that the secrets file is present.

I've tried using the logging_tree library to see if for some reason gunicorn is disabling my loggers, however there is no significant difference between the logging tree output with and without gunicorn.

Unfortunately I am not able to run gunicorn locally due to it always crashing with a segfault (seems to be some issue with macos) so i have to rely on debugging this on the running box on Render.

Answer 1

I found the issue.. Its because logging.configure_logging was running in the gunicorn master process, and it contains code to not reconfigure logging if it was already configured.

According to https://pythondev.readthedocs.io/fork.html#:~:text=Forking%20a%20process%20creates%20a,parent%20and%20the%20child%20process when you work a process, all threads but the main threads are immediately killed, and the Google Cloud Logging library by default publishes logs in a background thread, therefore logs were getting collected but never published in the worker processes.

A solution to this is either to always allow reconfiguring logging, or to be careful about disabling log reconfiguration based on the process pid it was configured in (aka allow reconfiguring if it was configured in a different process), or you can just use the SyncTransport in the google library which doesnt use the background worker pool.