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
--masterfrom UWSGI start options "fixes" the problem. - UWSGI options like:
--touch-logreopen,--log-reopen,--vacuum,--max-requests=10don't help. - Various soft-reload techniques like
echo r > /tmp/yourfifoor
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?