7

I have an application running in Kubernetes in google cloud. The application is written in python using fastapi. Logs from that application are visible via google cloud logging, however their "serverity" appears to be incorrectly translated: While fastapi's access logs are correctly written with "INFO" severity, any messages written from custom loggers appear as errors, even if they were written by a logger.info call.

I pass the following logging config to uvicorn via the --log-config command line option:

{
  "version": 1,
  "disable_existing_loggers": false,
  "formatters": {
    "simple": {
      "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
    },
    "default": {
      "()": "uvicorn.logging.DefaultFormatter",
      "datefmt": "%Y-%m-%dT%H:%M:%S",
      "format": "[%(asctime)s.%(msecs)04dZ] %(name)s %(levelprefix)s %(message).400s"
    },
    "access": {
      "()": "uvicorn.logging.AccessFormatter",
      "datefmt": "%Y-%m-%dT%H:%M:%S",
      "format": "[%(asctime)s.%(msecs)04dZ] %(name)s %(levelprefix)s %(message)s"
    }
  },
  "handlers": {
    "default": {
      "formatter": "default",
      "class": "logging.StreamHandler",
      "stream": "ext://sys.stderr"
    },
    "access": {
      "formatter": "access",
      "class": "logging.StreamHandler",
      "stream": "ext://sys.stdout"
    }
  },
  "loggers": {
    "uvicorn.error": {
      "level": "INFO",
      "handlers": ["default"],
      "propagate": false
    },
    "uvicorn.access": {
      "level": "INFO",
      "handlers": ["access"],
      "propagate": false
    },
    "uvicorn": {
      "level": "INFO",
      "handlers": ["default"],
      "propagate": false
    },
    "jsonrpc": {
      "level": "INFO",
      "handlers": ["default"],
      "propagate": false
    },
    "api": {
      "level": "INFO",
      "handlers": ["default"],
      "propagate": false
    }
  },
  "root": {
    "level": "INFO",
    "handlers": ["default"]
  }
}

All the uvicorn* loggers are correctly handled, but the jsonrpc and api loggers always show as "ERROR" in google cloud.

Following the documentation for google-cloud-logging, I use the following to setup cloud logging:

import google.cloud.logging

client = google.cloud.logging.Client()
client.setup_logging()

What am I missing? Is anything wrong with my configuration file? Is this expected or known behavior?

Edit: It appears that part of the issue here is the streams that the console handlers go to. Switching the default handler to go to stdout and adding an error handler that prints to stderr seems to solve the problem.

Ingo
  • 1,103
  • 8
  • 17
  • Have you tried this [solution](https://stackoverflow.com/a/59751054/19486986)? – Javier Roger Jul 11 '22 at 09:19
  • Thanks @JavierRoger, but that doesn't really do what I want. For one, I would need to set up stackdriver and fluentd to get this to work and secondly, it seems to select severity based on stderr/stdout, meaning that warnings would still be either info or error depending on where they get sent. – Ingo Jul 11 '22 at 11:52
  • Also having this issue. ``` import logging logging.basicConfig(level=logging.INFO) logger = logging.getLogger(__name__) logging.info("informational message") # shows as error in google cloud logs ``` even though it's clearly an info message, not an error: "INFO:root:informational message" – Alex Choi Aug 04 '22 at 15:06
  • @AlexChoi it's a year later, did you fix this? I'm thinking of using print() over logger... – bmiller May 16 '23 at 23:08
  • @bmiller, it's working now. I am not entirely sure what I did, but I made a change a few months back on the default logger to go to stdout and I added an extra error logger that goes to stderr. The date of that commit fits well with when it started working and I stopped thinking about it. Sorry for not reporting back. – Ingo Jun 12 '23 at 13:17

0 Answers0