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 !! "}

Does [this](https://stackoverflow.com/a/70899261/17865804) answer your question? — Chris, Jul 01 '23 at 12:25
@Chris : Thanks for the link, I'm trying to use structlog library. Expected output is not possible using structlog for the uvicorn logs ?? — Goku, Jul 01 '23 at 16:11
I'm not sure what your goal is, but the "expected output" you provide is not JSON. That means that regular JSON-processing tools won't work with it. — Ulrich Eckhardt, Jul 03 '23 at 06:04
@UlrichEckhardt : I have formatted the expected output. Goal is to print the logs in JSON format instead of string based format, which is a default behavior Uvicorn. Catch is , whether it is possible using `structlog` logging framework ? — Goku, Jul 03 '23 at 06:29
@Goku This is I bet the biggest gotcha of structlog, your application is using structlog but 3rd party libraries are using standard python logger. There is a way to workaround it as explained here: https://www.structlog.org/en/stable/standard-library.html#rendering-using-logging-based-formatters, pay special attention to this sentence: 'If you want all your log entries (i.e. also those not from your application / structlog) to be formatted as JSON, you can use the python-json-logger library:`. I.e. first configure your structlog, then configure standard logging to output via jsonformmater. — Drachenfels, Aug 02 '23 at 11:32

wim · Accepted Answer · 2023-07-02T19:30:33.643

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.

thanks that gave me an idea to develop further. – Goku Jul 04 '23 at 06:49 — Goku, Jul 04 '23 at 06:49

Format string output to JSON

1 Answers1