0

I'm using the following Flask (2.0.1) app

import logging
from flask import Flask, Blueprint, current_app
from logging.handlers import WatchedFileHandler


_LOG_PATH = "./test.log"

blueprint = Blueprint("dosomething", __name__)

@blueprint.route("/dosomething")
def dosomething():
    current_app.logger.info("do something")
    return "", 200

def create_app():
    app = Flask(__name__)

    app.logger = logging.getLogger()
    app.logger.addHandler(WatchedFileHandler("./test.log"))
    app.logger.setLevel(logging.INFO)

    app.register_blueprint(blueprint)
    return app

run by UWSGI (2.0.20) server started like this:

#!/usr/bin/env bash
source ./env/bin/activate

./env/bin/uwsgi --http=0.0.0.0:8000 \
                --virtualenv=./env \
                --master \
                --mount /='app:create_app()'

I start sending HTTP requests like this:

#!/usr/bin/env bash
while :
do
    curl 'http://localhost:8000/dosomething'
    sleep 0.5
done

After a few seconds I rotate the log file with:

#!/usr/bin/env bash
mv test.log test_$(date -d "today" +"%Y%m%d%H%M%S").log
touch test.log

This is somewhat similar to what logrotate does without copytruncate.

The WatchedFileHandler immediately switches to the newly created file, however the old file's descriptor still stays there until the server gets restarted:

~/Downloads/watched_files_uwsgi
$ sudo lsof -n | grep Downloads/watched_files_uwsgi/test
uwsgi     178885                   eugenesqr    9w      REG                8,4       624    4743480 /home/eugenesqr/Downloads/watched_files_uwsgi/test_20230531174721.log
uwsgi     178891                   eugenesqr    6w      REG                8,4       169    4746295 /home/eugenesqr/Downloads/watched_files_uwsgi/test.log
uwsgi     178892                   eugenesqr    9w      REG                8,4       624    4743480 /home/eugenesqr/Downloads/watched_files_uwsgi/test_20230531174721.log

~/Downloads/watched_files_uwsgi
$ ll /proc/178885/fd
...
l-wx------ 1 eugenesqr eugenesqr 64 May 31 17:47 9 -> /home/eugenesqr/Downloads/watched_files_uwsgi/test_20230531174721.log
...

Even if test_20230531174721.log gets deleted, the space it occupied can't be used:

$ sudo lsof -n | grep Downloads/watched_files_uwsgi/test
uwsgi     178885                   eugenesqr    9w      REG                8,4       624    4743480 /home/eugenesqr/Downloads/watched_files_uwsgi/test_20230531174721.log (deleted)
uwsgi     178891                   eugenesqr    6w      REG                8,4     10322    4746295 /home/eugenesqr/Downloads/watched_files_uwsgi/test.log
uwsgi     178892                   eugenesqr    9w      REG                8,4       624    4743480 /home/eugenesqr/Downloads/watched_files_uwsgi/test_20230531174721.log (deleted)

This becomes a problem with bulky log files and apps, which run without restarts for long periods of time.

Some extra observations:

  1. Logging in a simple python script without UWSGI and Flask works just fine: it immediately switches to a new file and the old file gets properly closed.
  2. It's reliably reproducible with python3.6 and python3.10 even with the latest UWSGI 2.0.21 and Flask 2.3.2.
  3. Removing --master from UWSGI start options "fixes" the problem.
  4. UWSGI options like: --touch-logreopen, --log-reopen, --vacuum, --max-requests=10 don't help.
  5. Various soft-reload techniques like echo r > /tmp/yourfifo or
kill -HUP `cat /tmp/project-master.pid`

appear to be not soft enough, since some of my requests aren't get processed during the reload with errors like: curl: (56) Recv failure: Connection reset by peer

The question: is there a way to free the rotated file's descriptor without adding extra timer-based "cleanup" scripts?

eugenesqr
  • 589
  • 6
  • 19

0 Answers0