Extremely cryptic error on FastAPI + Uvicorn application running on Google Cloud Run

[ydennisy]

hi!

I have a very low context and cryptic error, not really sure how to debug, will be happy to get more information if anyone has a suggestion how!

All I can see in the logs is:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 426, in run_asgi
    result = await app(  # type: ignore[func-returns-value]

[Kludex]

Impossible to help with these logs.

[ydennisy]

@Kludex I completely agree and I pointed that out.

Maybe you could help by suggesting how I could garner more information?

[Kludex]

I don't even know how you only see those logs... The full logs should be visible to you.

[ydennisy]

Yeah - I am assuming this is something in the way GCP / Cloud Run is cutting the logs off :(

{
  "textPayload": "Traceback (most recent call last):\n  File \"/usr/local/lib/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py\", line 426, in run_asgi\n    result = await app(  # type: ignore[func-returns-value]",
  "insertId": "650db5e5000ae95e9aad211b",
  "resource": {
    "type": "cloud_run_revision",
    "labels": {
      "location": "europe-west1",
      "project_id": "ag-edgekit-prod",
      "configuration_name": "nexus",
      "service_name": "nexus",
      "revision_name": "nexus-00158-dll"
    }
  },
  "timestamp": "2023-09-22T15:42:29.715102Z",
  "severity": "ERROR",
  "labels": {
    "instanceId": "00fd0ee57bc9630b53e815901ded61049a6ac8c433b340a4b8087efff9257426550f4a7c4263802682b393e1c3f18702d2aafc103790f54c337cb3dc574bd36a1310"
  },
  "logName": "projects/ag-edgekit-prod/logs/run.googleapis.com%2Fstderr",
  "receiveTimestamp": "2023-09-22T15:42:29.804071396Z"
}

I cannot repro this locally it seems to happen under high load only...

Do you have any ideas on how to switch logging output?

[ydennisy]

This was an issue with GCP logging - converting to JSON payload printed the stack trace :)

[MalteMagnussen]

@ydennisy - How did you change the logging?

[MtsumiAly]

Hi @ydennisy how did you convert to JSON payload, I have the same error on cloud run and cannot reproduce locally.

[aelamran]

@Kludex @ydennisy

1. I have the same issue where this same log is appearing as an "error" and then the rest of the traceback as "info".
2. Also, it makes GCP aggregates all errors as "Traceback (most recent call last):" => which doesn't help in differentiating the different errors happening.

What is the workaround that helped? Is it working for both 1) and 2) ?

[bitnahian]

Hi. I've suffered from incorrect logging levels reported in Google Cloud Logging with Uvicorn for a long time. In GCP serverless environments, json logging substantially helps.

I rely on a default_logging.ini file and also use the pythonjsonlogger module.

[loggers]
keys=root, fastapi, gunicorn.access, gunicorn.error, uvicorn.access, uvicorn.error

[handlers]
keys=console

[formatters]
keys=json

[logger_root]
level=INFO
handlers=console

[logger_fastapi]
level=WARNING
handlers=console
propagate=0
qualname=fastapi

[logger_gunicorn.access]
level=INFO
handlers=console
propagate=0
qualname=gunicorn.access

[logger_gunicorn.error]
level=INFO
handlers=console
propagate=0
qualname=gunicorn.error

[logger_uvicorn.access]
level=INFO
handlers=console
propagate=0
qualname=uvicorn.access

[logger_uvicorn.error]
level=INFO
handlers=console
propagate=0
qualname=uvicorn.error


[handler_console]
class=<YOUR-APP>.CustomGoogleCloudStructuredLogHandler
formatter=json
stream=sys.stdout


[formatter_json]
class=pythonjsonlogger.jsonlogger.JsonFormatter

As for the CustomGoogleCloudStructuredLogHandler, I've modified it so that I don't need to run the logging setup() that Google recommends. And I also add a CustomFilter to add tracing details to my logs which you can ignore for the purposes of this discussion.

# Copied from google.cloud.logging_v2.handlers.handlers
"""Exclude internal logs from propagating through handlers"""
EXCLUDED_LOGGER_DEFAULTS = (
    "google.cloud",
    "google.auth",
    "google_auth_httplib2",
    "google.api_core.bidi",
    "werkzeug",
)


class CustomGoogleCloudStructuredLogHandler(
    google.cloud.logging.handlers.StructuredLogHandler
):
    def __init__(self, *args, **kwargs):
        super().__init__(**kwargs, project_id=settings.GOOGLE_CLOUD_PROJECT)
        # self.filters.insert(0, CustomFilter()) You can add custom filters here if you want to
        for logger_name in EXCLUDED_LOGGER_DEFAULTS:
            # prevent excluded loggers from propagating logs to handler
            logger = logging.getLogger(logger_name)
            logger.propagate = False

And then, when you finally run uvicorn pass the log config with the --log-config param.

Logs will start looking a lot more like this.

NOTE - This is using a modified StructuredLogHandler suited for environments where GCP picks up logs from stdout.
This will work in Cloud Run and GKE workloads. Not sure about VMs.

[jamesleeht]

Thanks for this post - I learnt a lot by studying your config