Malformed JSON log records

I have a FastAPI application served by Gunicorn that writes contextualized JSON logs to the file sink using patcher. Here is the simplified version of my logger's configuration:

import json
from loguru import logger

def attach_json_log(record):
    log_data = dict(
        timestamp=record["time"].isoformat(),
        application={
            "name": "My App",  # from env variable
            "version": "1.0.0",   # from env variable
        },
        level=record["level"].name,
        message=record["message"],
        extra=record["extra"],
    )
   record["extra"]["_json_"] = json.dumps(log_data)

logger.add(
    "/var/log/app.log",
    level="INFO",
    colorize=False,
    enqueue=True,
    rotation="1 days",
    retention="1 months",
    format=lambda _: "{extra[_json_]}\n",
)
logger.configure(patcher=attach_json_log)

The issue is sometimes the schema of the JSON log records in the log file is not matched with the defined schema. In some cases, some of the fields are missing from the JSON logs or all fields are available but they're filled with the wrong value. The strange thing is in all cases the logs written in the log file are still valid JSON objects and it doesn't make sense at all! For instance, here is a malformed log record that I found in the log file:

{
  "application": {
    "": "SOME OTHER VALUE",
    "name": "SOME OTHER VALUE"
  },
  "extra": {
    "x": null
  }
}

I noticed some issues are already reported for the enqueu=True option on Gunicorn workers. However, since my Gunicorn has 1 worker with 4 threads, I don't think this problem is related to those issues.

Any response would be appreciated. Thank you in advance for your effort.

I don't see anything inherently wrong in your configuration.

Are you sure that no record log is accessed and modified concurrently? Logging is thread-safe, but you must not pass the record to another thread.

Another possibility is that /var/log/app.log is corrupted. Possibly if two different handlers inadvertently happen to log in parallel to the same file. This is a common issue with Guvicorn. You should double-check that there is no problem as such, for example by adding an UUID to the filename.

Apart from that, I must confess that I unfortunately have no other ideas about what might cause such behavior. Unfortunately, without a reproducible example, it's difficult for me to investigate your problem further.

Delgan / loguru

Malformed JSON log records #1182