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:
- 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.
- It's reliably reproducible with python3.6 and python3.10 even with the latest UWSGI 2.0.21 and Flask 2.3.2.
- Removing
--master
from UWSGI start options "fixes" the problem. - UWSGI options like:
--touch-logreopen
,--log-reopen
,--vacuum
,--max-requests=10
don't help. - 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?