Format string output to JSON

Question

I'm playing around with FastAPI and Structlog and wanted to test and convert log format from plain text/string to JSON format for better readability and processing by the log aggregator platforms. Facing a case where certain log output are available in JSON but rest in plain string.

Current Output

INFO:     127.0.0.1:62154 - "GET /api/preface HTTP/1.1" 200 OK
INFO:     127.0.0.1:62154 - "GET /loader.json HTTP/1.1" 200 OK
INFO:     127.0.0.1:62155 - "GET /hello_world HTTP/1.1" 200 OK
{"key":"test_key","message":"Push to NFS Success","event":"Testing Fast API..","logger":"test_my_api","filename":"main.py","func_name":"Hello_World","process":23760,"module":"docker","thread":23140,"pathname":"D:\\my_work\\fast_api\\main.py","process_name":"SpawnProcess-1","level":"info","time-iso":"2023-06-30T15:25:03.113400Z"}

Expected Output:

    {
    "level": "INFO",
    "IP": "127.0 .0 .1: 62154",
    "method": "GET",
    "endpoint": "/loader.json",
    "protocol": "HTTP / 1.1",
    "status_code": 200,
    "status": "OK"
}
    {
    "level": "INFO",
    "IP": "127.0 .0 .1: 62155",
    "method": "GET",
    "endpoint": "/api/preface",
    "protocol": "HTTP / 1.1",
    "status_code": 200,
    "status": "OK"
}

 {
    "level": "INFO",
    "IP": "127.0 .0 .1: 62155",
    "method": "GET",
    "endpoint": "/hello_world",
    "protocol": "HTTP / 1.1",
    "status_code": 200,
    "status": "OK"
}
    {"key":"test_key","message":"Push to NFS Success","event":"Testing Fast API..","logger":"test_my_api","filename":"main.py","func_name":"Hello_World","process":23760,"module":"docker","thread":23140,"pathname":"D:\\my_work\\fast_api\\main.py","process_name":"SpawnProcess-1","level":"info","time-iso":"2023-06-30T15:25:03.113400Z"}

What am I missing here ? thanks !

struct.py

import orjson
import structlog
import logging

## Added only the necessary context.
class StructLogTest:
    def __init__(self, logging_level=logging.DEBUG, logger_name="test"):
        self.logging_level = logging_level
        self.logger_name = logger_name
        StructLogTest.logger_name_var = self.logger_name
        self.configure_structlog(self.logging_level, self.logger_name)

    def logger_name(_, __, event_dict):
        event_dict["test_log"] = StructLogTest.logger_name_var
        return event_dict


    @staticmethod
    def configure_structlog(logging_level, logger_name):
        structlog.configure(
            processors=[
                StructLogTest.logger_name,
                structlog.threadlocal.merge_threadlocal,
                structlog.processors.CallsiteParameterAdder(),
                structlog.processors.add_log_level,
                structlog.stdlib.PositionalArgumentsFormatter(),
                structlog.processors.StackInfoRenderer(),
                structlog.processors.format_exc_info,
                structlog.processors.TimeStamper(fmt="iso", utc=True, key="time-iso"),
                structlog.processors.JSONRenderer(serializer=orjson.dumps),
            ],
            wrapper_class=structlog.make_filtering_bound_logger(logging_level),
            context_class=dict,
            logger_factory=structlog.BytesLoggerFactory(),
        )
        return structlog

    def define_Logger(self, *args, **kwargs):
        return structlog.get_logger(*args, **kwargs)

    def info(self, message, *args, **kwargs):
        return structlog.get_logger().info(message, *args, **kwargs)
    
    and other methods so on..


    

main.py

from struct import StructLogTest
from fastapi import APIRouter
import requests
from requests.auth import HTTPBasicAuth
from requests import Response

log = StructLogTest(logger_name="test_my_api")
log = log.get_Logger()

@router.get("/hello_world")
def Hello_World():
    logg = log.bind(key=test_key)
    logg.info(
        "Testing Fast API..",
        message=some_other_meaningful_function.dump(),
    )
    return {" Hello World !! "}

Answer 1

Structlog is an entirely separate logging framework from stdlib logging. It will not configure the stdlib logging framework for you. Uvicorn uses stdlib logging, and you can't change that short of forking and editing the source code to use some other logging framework.

You do have some options here, though. The simplest is just to configure stdlib logging with a json formatter, for example create uvicorn-logconfig.ini:

[loggers]
keys=root, uvicorn, gunicorn

[handlers]
keys=access_handler

[formatters]
keys=json

[logger_root]
level=INFO
handlers=access_handler
propagate=1

[logger_gunicorn]
level=INFO
handlers=access_handler
propagate=0
qualname=gunicorn

[logger_uvicorn]
level=INFO
handlers=access_handler
propagate=0
qualname=uvicorn

[handler_access_handler]
class=logging.StreamHandler
formatter=json
args=()

[formatter_json]
class=pythonjsonlogger.jsonlogger.JsonFormatter

That uses a stdlib json formatter from python-json-logger. Now, run your app with something like:

uvicorn --log-config=uvicorn-logconfig.ini main:router

The logs from uvicorn and from your own application code will render as JSON, the former through stdlib formatters and the latter through structlog processors.

Here's what I saw when starting up your app, making a request to http://127.0.0.1:8000/hello_world to get the "Testing Fast API..." event from structlog, and then shutting down uvicorn with Ctrl+C:

$ uvicorn --log-config=uvicorn-logconfig.ini main:router
{"message": "Started server process [54894]", "color_message": "Started server process [\u001b[36m%d\u001b[0m]"}
{"message": "Waiting for application startup."}
{"message": "Application startup complete."}
{"message": "Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)", "color_message": "Uvicorn running on \u001b[1m%s://%s:%d\u001b[0m (Press CTRL+C to quit)"}
{"test_key":"test_val","message":"some_message","event":"Testing Fast API..","pathname":"/private/tmp/s/main.py","lineno":42,"process_name":"MainProcess","func_name":"Hello_World","filename":"main.py","thread_name":"AnyIO worker thread","thread":12930912256,"module":"main","process":54894,"level":"info","time-iso":"2023-07-02T19:22:58.085382Z"}
{"message": "127.0.0.1:58519 - \"GET /hello_world HTTP/1.1\" 200"}
^C{"message": "Shutting down"}
{"message": "Waiting for application shutdown."}
{"message": "Application shutdown complete."}
{"message": "Finished server process [54894]", "color_message": "Finished server process [\u001b[36m%d\u001b[0m]"}

This is recommended as the simplest approach in structlog's documentation (see the subsection "Don't Integrate" in the Standard Library section):

The most straight-forward option is to configure standard library logging close enough to what structlog is logging and leaving it at that.

Since these are usually log entries from third parties that don’t take advantage of structlog’s features, this is surprisingly often a perfectly adequate approach.

For instance, if you log JSON in production, configure logging to use python-json-logger to make it print JSON too, and then tweak the configuration to match their outputs.

Since stdlib logging is highly configurable, and structlog is also highly flexible, there are other approaches possible to integrate structlog and stdlib more tightly. See Rendering Using structlog-based Formatters Within logging if interested.