Handling logging to file with gunicorn

[fastapi-mvc]

Handling logging to file with gunicorn

[jeanlst]

That sounds like a nice solution, I was looking into trying Grafana Loki actually, but that does sound interesting I might hit up later on that.

I don't really need 1 logfile per worker but From what I have been reading and tried gunicorn logging to file with multiple workers does not work properly (even going on stuff about gunicorn). Take a look: https://docs.python.org/3/howto/logging-cookbook.html#logging-to-a-single-file-from-multiple-processes

I'm probably mistaken, but when I tried a RotatingFileHandler the first log file was fine with the logs from the workers, but every new log file was only being written by one worker. I'm not sure tho if the issue comes from the multiprocessing logging or if indeed everything was being served by only 1 worker. This is the script I used to test my app

async def fetch(idx: int, client: httpx.AsyncClient):
    response = await client.put(url, headers=headers, data=payload, timeout=None)
    return response.elapsed
async def fetch_all(times: int):
    async with httpx.AsyncClient() as client:
        return await asyncio.gather(
            *map(
                fetch,
                list(range(times)),
                itertools.repeat(client),
            )
        )
if __name__ == "__main__":
    loop = asyncio.get_event_loop()
    result = loop.run_until_complete(fetch_all(1000))
    print("avg", sum(result, datetime.timedelta(0)) / len(result))
    print("min", min(result))
    print("max", max(result))

[abnerjacobsen]

Hi @rszamszur @jeanlst

With the help of some information obtained on the internet I was able to customize the fastapi-mvc-example to do the following:

• Use loguru instead of the standard Python logging module to manage system logs. Apparently loguru works better with threads and multiprocessing.
• Capture all logs, even Gunicorn startup logs with the custom log format I intend to use in my application.
• Put the following information in the log lines: PID of the process (gunicorn worker) that generated the log line, x-correlation-id and x-request-id (a necessity of my application and which are generated/obtained by a fastapi middleware )
• Gunicorn's master and workers appear with a friendly name when I run a ps axu

By default I generate the logs in stdout, but I also tested saving the logs in a file and it worked perfectly, even after rotating the file. Each worker continued writing to the same file after loguru's file rotation.

My version of wsgi.py is hardcoded to configure Gunicorn workers and threads as per this post: https://medium.com/building-the-system/gunicorn-3-means-of-concurrency-efbb547674b7 - I don't know if it is the most efficient way, but in my tests it worked fine.

Although not complete, I added a new command to start a uvicorn server only, this is because I like to use its reload feature when I'm developing my code and I couldn't find a way to do this with Gunicorn - apparently it's impossible. The command is:

das_sankhya devserve

I used this information to prepare this demo:

• https://medium.com/building-the-system/gunicorn-3-means-of-concurrency-efbb547674b7
• https://pawamoy.github.io/posts/unify-logging-for-a-gunicorn-uvicorn-app/
• https://github.com/pahntanapat/Unified-FastAPI-Gunicorn-Log
• Delgan/loguru#365
• https://loguru.readthedocs.io/en/stable/api/logger.html#sink
• https://github.com/snok/asgi-correlation-id

And the main changes I made are in these files:

• https://github.com/abnerjacobsen/fastapi-mvc-loguru/blob/main/das_sankhya/wsgi.py
• https://github.com/abnerjacobsen/fastapi-mvc-loguru/blob/main/das_sankhya/core/logs2.py
• https://github.com/abnerjacobsen/fastapi-mvc-loguru/blob/main/das_sankhya/core/gunicorn_logs.py

The repository with my changes is here: https://github.com/abnerjacobsen/fastapi-mvc-loguru

I did several tests with locust running:

locust -f locust/test1.py

and apparently everything worked correctly.

@rszamszur what do you think? can my changes cause some unexpected problem if it is put to run in Kubernetes ?

I don't understand much about Gunicorn's inner workings, I've just been gathering and experimenting with information obtained from the internet and now I would like a more authoritative opinion.

Anyway, congratulations on your project, it's excellent. And thanks for making it available to the community.

[rszamszur]

Logging can be configured by using various flags in the gunicorn.conf.py. In the generated project this file is located in the .config submodule and contains values from: https://github.com/benoitc/gunicorn/blob/master/examples/example_config.py

To configure gunicorn to log to a file you need to change accesslog and errorlog default values.

Example:

errorlog = "/var/log/fastapi.errror.log"
accesslog = "/var/log/fastapi.log"

Just make sure that the user which is running the app has rw permissions to the log file you want to write in. Otherwise, you will have the following error:

[2022-01-21 10:30:33 +0100] [4129321] [INFO] Start gunicorn WSGI with ASGI workers.

Error: Error: '/var/log/fastapi.error.log' isn't writable [PermissionError(13, 'Permission denied')]

Resources:

• Gunicorn logging configuration documentation: https://docs.gunicorn.org/en/latest/settings.html#logging
• Example gunicorn.conf.py generated with the project: https://github.com/rszamszur/fastapi-mvc-example/blob/master/fastapi_mvc_example/config/gunicorn.conf.py

Logfile output example:

$ cat fastapi.error.log 
[2022-01-21 10:33:41 +0100] [4134628] [INFO] Starting gunicorn 20.1.0
[2022-01-21 10:33:41 +0100] [4134628] [INFO] Listening at: http://127.0.0.1:8000 (4134628)
[2022-01-21 10:33:41 +0100] [4134628] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2022-01-21 10:33:41 +0100] [4134628] [INFO] Server is ready. Spawning workers
[2022-01-21 10:33:41 +0100] [4134642] [INFO] Booting worker with pid: 4134642
[2022-01-21 10:33:41 +0100] [4134642] [INFO] Worker spawned (pid: 4134642)
[2022-01-21 10:33:41 +0100] [4134642] [INFO] Started server process [4134642]
[2022-01-21 10:33:41 +0100] [4134642] [INFO] Waiting for application startup.
[2022-01-21 10:33:41 +0100] [4134642] [INFO] Application startup complete.
[2022-01-21 10:33:41 +0100] [4134643] [INFO] Booting worker with pid: 4134643
[2022-01-21 10:33:41 +0100] [4134643] [INFO] Worker spawned (pid: 4134643)
[2022-01-21 10:33:41 +0100] [4134643] [INFO] Started server process [4134643]
[2022-01-21 10:33:41 +0100] [4134643] [INFO] Waiting for application startup.
[2022-01-21 10:33:41 +0100] [4134643] [INFO] Application startup complete.
[2022-01-21 10:33:56 +0100] [4134628] [INFO] Handling signal: int
[2022-01-21 10:33:57 +0100] [4134628] [WARNING] Worker with pid 4134643 was terminated due to signal 3
[2022-01-21 10:33:57 +0100] [4134628] [WARNING] Worker with pid 4134642 was terminated due to signal 3
[2022-01-21 10:33:57 +0100] [4134628] [INFO] Shutting down: Master
[2022-01-21 10:34:05 +0100] [4135479] [INFO] Starting gunicorn 20.1.0
[2022-01-21 10:34:05 +0100] [4135479] [INFO] Listening at: http://127.0.0.1:8000 (4135479)
[2022-01-21 10:34:05 +0100] [4135479] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2022-01-21 10:34:05 +0100] [4135479] [INFO] Server is ready. Spawning workers
[2022-01-21 10:34:05 +0100] [4135497] [INFO] Booting worker with pid: 4135497
[2022-01-21 10:34:05 +0100] [4135497] [INFO] Worker spawned (pid: 4135497)
[2022-01-21 10:34:05 +0100] [4135497] [INFO] Started server process [4135497]
[2022-01-21 10:34:05 +0100] [4135497] [INFO] Waiting for application startup.
[2022-01-21 10:34:05 +0100] [4135497] [INFO] Application startup complete.
[2022-01-21 10:34:05 +0100] [4135503] [INFO] Booting worker with pid: 4135503
[2022-01-21 10:34:05 +0100] [4135503] [INFO] Worker spawned (pid: 4135503)
[2022-01-21 10:34:05 +0100] [4135503] [INFO] Started server process [4135503]
[2022-01-21 10:34:05 +0100] [4135503] [INFO] Waiting for application startup.
[2022-01-21 10:34:05 +0100] [4135503] [INFO] Application startup complete.
[2022-01-21 10:34:16 +0100] [4135479] [INFO] Handling signal: int
[2022-01-21 10:34:16 +0100] [4135479] [WARNING] Worker with pid 4135503 was terminated due to signal 3
[2022-01-21 10:34:16 +0100] [4135479] [WARNING] Worker with pid 4135497 was terminated due to signal 3
[2022-01-21 10:34:17 +0100] [4135479] [INFO] Shutting down: Master
$ fastapi.log 
127.0.0.1:43920 - "GET /api/ready HTTP/1.1" 200
127.0.0.1:43920 - "GET /favicon.ico HTTP/1.1" 404
127.0.0.1:43924 - "GET /api/ready HTTP/1.1" 200
127.0.0.1:43926 - "GET /api/ready2 HTTP/1.1" 404

[jeanlst]

Thanks for the response. Still I feel like this falls under the problem that logging in python does not handle multiprocessing which is essentially what gunicorn does. I always use the logconfig-dict to setup logging for my projects and thats what I'm pointing gunicorn to. But from what I have seen it does not work well with multiple workers trying to log to the same files, specially when you use a RotatingFileHandler

[rszamszur]

@jeanlst If I may ask, what is your use case, that you need to a logfile per worker? Maybe I can find some solution for you.

In my experience with web frameworks usually, there is one application log per master-worker regardless of how many child processes there might be. For instance in Ruby on Rails puma by default logs application log into one file despite how many workers you configure.

In the meantime, I'll experiment with gunicorn logging configuration and see what's possible.

Lastly, you might research the topic of structure logging. If you have to store, filter, and read logs from many distributed systems it can be really helpful. Structured logging uses a defined format to add important details to logs and make it easier to interact with them in different ways. Meaning you can easily filter log files by hostname, PID, level, or any other field that you'll define.
Personally, I'm using seq: https://datalust.co/seq for execution logs from my stock exchange bot which is running in-home Kubernetes cluster. Also, each execution is done using multiprocessing. Thanks to structured logging I can easily identify/filter the data I need. Moreover, all logs are being stored in one place.
If you'd be interested I've written a custom logging handler for sending logs to seq. It's not perfect but get the job done.

[rszamszur]

Thanks for the materials! I wasn't even aware there is an issue with writing to a single file from multiple processes in Python. Also, I haven't had a chance to research this topic more. In the past, when posed with a similar problem, I've decided to use structured logging instead and don't worry about log files. Finally, with the gunicorn I guess I've assumed it works out of the box since one can configure logging to a single file in gunicorn.conf.py.

Since I already have some implementation for the Seq logging handler, I might add it to the template. Also, I'll add Seq deployment to Kubernetes application stack t in make dev-env, so it should be much more convenient to test and play with it. However, a significant tradeoff is that a message queue or separate process is needed to send records to the Seq application. Otherwise, you can clog up the network interface, resulting in some record requests lost due to timeout (caused by too many requests). Whereas Grafana Loki seems to have the opposite approach - scraps logs from defined paths and then parses them to some structure.

For now, I'll include seq, to the template: fastapi-mvc/cookiecutter#13
Later on, I might play with Grafana Loki as well and see how that works.

[rszamszur]

Hey @abnerjacobsen

Thanks for the input, that's quality research right there!

Please give me some time to dig into that, and go through the materials you've provided. But, at the first glance loguru could be implemented to the template as an optional logging class to choose from during project generation. Even though it is yet to be matured project, looks very promising (0.6.0 and 11k dayum :) )

---

Although not complete, I added a new command to start a uvicorn server only, this is because I like to use its reload feature when I'm developing my code and I couldn't find a way to do this with Gunicorn - apparently it's impossible.

That's actually a solid idea, already created an issue for that: #31
I'm not sure yet how this should be implemented:

• separate command
• additional flag --reload in serve command. However, simple --reload won't be sufficient with WSGI + ASGI combo.
• automatically based on env FASTAPI_ENV=development FASTAPI_ENV=production similar to Ruby on rails
• other??

@abnerjacobsen any suggestions?

---

can my changes cause some unexpected problem if it is put to run in Kubernetes ?

If those changes don't break the application or the way it's served, then they should cause problems in Kubernetes deployment. For that, integration workflow comes in handy: https://github.com/rszamszur/fastapi-mvc/actions/workflows/integration.yml
Any merge to master will trigger it. It's basically a complete integration test for the fully generated project. This workflow will ensure that generated project:

• virtualized environment (Vagrantfile)
• make install
• make image
• helm chart
• make dev-env - bootstraping minikube cluster with Redis HA cluster

works properly.