loguru
loguru copied to clipboard
Delgan
Issues with rotate
I'm aware I could just be misusing loguru, but have noticed some non-intuitive behavior around 'rotation'.
I'm running:
Python 3.7.6 (default, Feb 26 2020, 20:54:15) [GCC 7.3.1 20180712 (Red Hat 7.3.1-6)] on linux
and
loguru 0.5.1
I have a web-app built in bottle that uses the gunicorn webserver and has 6 worker processes.
In my app I have the following code: logger.add("pods.log", rotation="sunday at 03:00")
I think I'm running into problems when I have multiple users on the website simultaneously and gunicorn runs multithreaded copies of the website. This is actually kind of unusual; the site is kind of sandbox and the user volume is really low... we have maybe 5 visitors per day. I have a bunch of single-threaded cron jobs that also rotate their logs like this one does, and it works fine. However this is the only multithreaded program that I have and It seems to create lots more log files than I ask for. Here's what the last few weeks look like:
-rw-r--r-- 1 root root 135829 Oct 31 17:55 pods.2020-10-26_04-57-05_964506.log
-rw-r--r-- 1 root root 6893 Nov 2 20:11 pods.2020-11-01_18-20-42_710982.log
-rw-r--r-- 1 root root 1384 Nov 2 03:23 pods.2020-11-02_03-20-20_265978.log
-rw-r--r-- 1 root root 2900 Nov 2 07:36 pods.2020-11-02_03-42-34_356316.log
-rw-r--r-- 1 root root 3303 Nov 2 20:16 pods.2020-11-02_07-38-17_428417.log
-rw-r--r-- 1 root root 92259 Nov 7 20:07 pods.2020-11-02_08-14-48_165825.log
-rw-r--r-- 1 root root 5989 Nov 10 21:55 pods.2020-11-09_07-38-13_902695.log
-rw-r--r-- 1 root root 4503 Nov 10 00:55 pods.2020-11-09_08-36-40_989960.log
-rw-r--r-- 1 root root 6215 Nov 11 03:45 pods.2020-11-09_17-55-30_725461.log
-rw-r--r-- 1 root root 5524 Nov 11 03:42 pods.2020-11-09_18-03-11_396160.log
-rw-r--r-- 1 root root 4538 Nov 11 06:05 pods.2020-11-10_01-11-39_544732.log
-rw-r--r-- 1 root root 562 Nov 10 01:56 pods.2020-11-10_01-56-49_697171.log
-rw-r--r-- 1 root root 25173 Nov 13 17:08 pods.log
We can see on Nov 11, it created a lot of logs... not sure why; it's not even a Sunday.
Are my expectations wrong or am I doing something wrong?
Regardless -- I love this tool! Thanks for making it!
Hi @cestes. You're not the first one encountering difficulties mixing loguru with gunicorn, unfortunately. :(
Typically, multiple log files instead of one indicates an issue with multiprocessing. For example, looking at this code:
from loguru import logger
import multiprocessing
import time
def worker():
while True:
time.sleep(0.01)
logger.info("Logging...")
logger.add("foo.log", rotation="200 KB")
if __name__ == "__main__":
multiprocessing.set_start_method("spawn")
processes = [multiprocessing.Process(target=worker) for _ in range(4)]
for p in processes:
p.start()
for p in processes:
p.join()
At first, all logs appear in foo.log and it seems to work perfectly. However, as soon as the rotation takes place, several new files are created in which the processes write separately. This happens because actually logger.add() is called each time a process is started, which means your program is effectively logging to multiple handlers and not to the same file.
I don't know if it's the same problem you face with gunicorn, but it could be. Do you call logger.add() in a if __name__ == "__main__" block (so that it's configured only once: in the main process)? Also, maybe the workers were on standby, and only created the file when they was first used, although it was not a Sunday.
There is also this article about configuring loguru with guvicorn, maybe it can help you: Unify Python logging for a Gunicorn/Uvicorn/FastAPI application.
In any case, I will try to help you investigate this problem, do not hesitate to ask me. ;)
Thanks for the quick and thoughtful feedback! My gut tells me this has to do with multiprocessing. In my example above on 11-Nov at around 03:42, two guys on our team were testing and we had the somewhat unusual case of using the multiprocessing feature of bottle/gunicorn. One other time I noticed it, I think we had a classroom of people playing with our app.
I don't call logger.add() from my __main__ . Here's my code:
def main():
logger.add("pods.log", rotation="sunday at 03:00")
logger.info("Program starting")
try:
parser = configparser.ConfigParser()
parser.read('pods.ini')
except:
logger.critical("Error reading config file")
logger.info("Starting web application")
run(host = parser.get('webserver','host'),
port = parser.get('webserver','port'),
debug = parser.getboolean('webserver','debug'),
certfile = parser.get('webserver','certfile'),
keyfile = parser.get('webserver','keyfile'),
server = parser.get('webserver','server'),
timeout = parser.get('webserver','timeout'),
workers = parser.getint('webserver','workers')
)
logger.info("Program stopping")
if __name__ == '__main__':
main()
The run() starts bottle/gunicorn.
If I move logger.add() from main() to __main__ do you think that would help?
Well, you are indirectly calling logger.add() in the if __name__ == '__main__' block as it's part of your main() function. So, moving logger.add() around would not change anything.
I think the problem does come from multiprocessing, but not exactly for the reason I first mentioned.
from loguru import logger
import multiprocessing
import time
def worker():
while True:
time.sleep(0.01)
logger.info("Logging...")
if __name__ == "__main__":
logger.add("foo.log", rotation="200 KB")
multiprocessing.set_start_method("fork")
processes = [multiprocessing.Process(target=worker) for _ in range(4)]
for p in processes:
p.start()
for p in processes:
p.join()
The new processes are probably created using the "fork" method. In the end, the result is the same: each child process ends up with an independent handler but logging to the same file. This means every handler will try to rotate the file separately, causing the duplicated files you're seeing.
What you need is a way to synchronize the workers so that they effectively use one common handler. That way, the rotation will be triggered only once, and then all processes will keep logging to the same shared file.
You should try to use enqueue=True while configuring the logger:
logger.add("pods.log", enqueue=True, rotation="sunday at 03:00")
I also advise you to read this paragraph in the documentation that may help you understand how this parameter works: Compatibility with multiprocessing using enqueue argument.
@cestes Did that fix your problem? Can I close this issue?
I also meet a problem like this, and I have used the parameter equeue=True, the difference is that I add log in gunicorn hood when_ready. when the log rotate, gunicorn crash,. my version is 0.5.3, here is my code:
from loguru import logger
proc_name = "picture_finger_api"
workers = 8
worker_class = 'gevent'
bind = "0.0.0.0:7410"
def when_ready(server):
log_config = {'enqueue': True, 'rotation': '00:00', 'retention': '2 weeks', 'compression': 'tar.gz'}
logger.add('log/app.log', level='DEBUG', **log_config)
crash core file has nothing,like this: #0 0x00007f2388dcf14b in ?? () #1 0x00007f2388df3b94 in ?? () #2 0x0000000000000009 in ?? () #3 0x0000000000000000 in ?? ()
Hi @kylinat2688.
I'm unable to reproduce the issue. Log files is properly rotated and compressed according to my tests.
Can you please provide a minimal reproducible example (feel free to open a new ticket)?
Oh,I have found the bug, gunicorn worker time out when loguru is compressing the log. the log file is big, about 1.8G, gunicorn worker time out with 30s as default. When I modify time out to 0 which means no timeout, It works right, or I remove the compress config, It's also work right. Reproduce code: [email protected]:kylinat2688/loguru_demo.git
But, I also have a question, do loguru compress log in worker process, not in the master process when I config enqueue=True?
@kylinat2688 Thanks for the link to the repository. When enqueue=True, the compression occurs in a separate worker thread started internally by the logger. Theoretically, it should not affect your processes.