Access Log Files Upon Rotation

[irisk29]

Hello,
I'm trying to implement a simple use case where I log into the stdout and into a file in a FastApi application.
The following code:

def formatter(record):
    print(record)
    # Note this function returns the string to be formatted, not the actual message to be logged
    record["message"] = f"{random.randrange(0, 100)}\n"
    return "{time} | <red>{level}</red> | {extra[trace_id]} | {extra[microservice_name]} | {message}"


fmt = "{time} | <red>{level}</red> | {extra[trace_id]} | {extra[microservice_name]} | {message}"  # Loguru
logger.remove(0)
logger = logger.bind(trace_id=global_vars.trace_id.get(), microservice_name=global_vars.microservice_name.get())
logger.add(f"out-1.log", level="DEBUG", format=formatter, rotation="30 seconds", retention="1 week", colorize=True)
logger.add(sys.stdout, level="DEBUG", format=formatter, colorize=True, diagnose=False)

from fastapi import FastAPI, APIRouter, Depends
from depends import my_depends
from myLogger import logger

app = FastAPI()
router = APIRouter(dependencies=[Depends(my_depends)])


@router.get("/")
def root(name: str):
    logger.info("Got {} as input", name)
    return {"message": name}


app.include_router(router)

import uvicorn
if __name__ == "__main__":
    uvicorn.run("main:app", reload=True)

creates a log file, but after 30 seconds, when it is time to rotate the file and rename the old one with a date in its name, I encounter with
PermissionError: [WinError 32] The process cannot access the file because it is being used by another process out-1.log -> out-1.2024-03-14_21-49-52_733426.log

but if I define the file name like this:

logger.add(f"out-{random.randrange(0, 100)}.log", level="DEBUG", format=formatter, rotation="30 seconds", retention="1 week", colorize=True)

the access and rotation works just fine (although it creates 2 files on startup instead of one)

What am I doing wrong?

[Delgan]

Hey @irisk29.

It's likely an issue with the different process workers invoked by FastAPI. Each time a worker is spawned, the logger is re-configured (because spawning a new process cause the whole Python script to execute again). That implies two processes try to write and rotate the same file in parallel, which cause problems such as the one you faced.

There is no built-in solution for that issue yet. Ideally, we would need to use enqueue=True to synchronize logs across processes, but FastAPI does not provide a way to make worker processes inherit objects such as the logger from the main process.

The safe solution for now it to use one different file per worker.