Loguru doesn't remove uncompressed files after compressing them

[dstlmrk]

Hello,

I use this definition for compressing but I expected different behaviour:

handlers.append({
    "rotation": "03:00",
    "compression": "gz",
    "retention": 10 days",
    ...
})

All my raw log files are compressed every night. It's working. But I don't need them (uncompressed files) if they are already compressed. Loguru doesn't remove them and I don't know if it's wanted behaviour. Because now it's not saving any space on disc.

Should I use my custom callable which removes all old uncompromised files?

[Delgan]

Hum... That's not the expected behavior. The .log file should be removed once compression is done.

May I ask you which loguru version you're using please? Are you seeing any error message in your logs (I'm thinking to permission issues for example)? You may try to create a minimal script with rotation="10 kB" and a basic for loop to see if you can reproduce the problem consistently and hence investigate it. 😕

[dstlmrk]

Hi! I will close this issue in next days after test probably. I was getting this traceback in uwsgi log:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/loguru/_handler.py", line 176, in emit
    self._sink.write(str_record)
  File "/usr/local/lib/python3.8/site-packages/loguru/_file_sink.py", line 174, in write
    self._terminate_file(is_rotating=True)
  File "/usr/local/lib/python3.8/site-packages/loguru/_file_sink.py", line 210, in _terminate_file
    self._compression_function(old_path)
  File "/usr/local/lib/python3.8/site-packages/loguru/_file_sink.py", line 66, in compression
    compress_function(path_in, path_out)
  File "/usr/local/lib/python3.8/site-packages/loguru/_file_sink.py", line 53, in copy_compress
    with open(path_in, "rb") as f_in:
FileNotFoundError: [Errno 2] No such file or directory: '/var/log/app/app_2020-09-07_12-34-24_908563.log'

Then I found the issue #220 and there is info about enqueue param. Because my app is multiprocessing it makes sense I need the enqueue=True :)

[dstlmrk]

Ok that is bigger problem than I thought :( If I want have only one logging file for whole app instead of file for each process then I need enqueue=True. But there is problem with killing processes. For this example I created simple web server with Flask and uwsgi:

# main.py

import os
from loguru import logger

print("pid=%s, configure logger" % os.getpid())
logger.remove()
logger.add("file.log", enqueue=True)
logger.info("Logger is configured")

from flask import Flask
application = Flask(__name__)

@application.route('/')
def hello_world():
    pid = os.getpid()
    print(pid)
    logger.info(pid)
    return str(pid)

I can run ti with:

uwsgi --http :9090 --wsgi-file main.py --master --processes 2 --threads 1

Now there are two options:

First option: enqueue=False

It works normally (but it creates logging file for every process). I can choose random process (pstree -p | grep uwsgi) and kill one of them. In uwsgi log I can see:

DAMN ! worker 1 (pid: 81233) died :( trying respawn ...
Respawned uWSGI worker 1 (new pid: 81356)

...and web server is still working. In log files I see logs.

Second option: enqueue=True

I'm trying to kill one of processes. But after killing one process the whole app is not responding and logging is absolutely dead :( I tried this code, but it's not working too:

import atexit

def wait_for_loguru():
    # called in exiting child
    logger.complete()

atexit.register(wait_for_loguru)

[Delgan]

Oh, great you figured out it was related with enqueue and multiprocessing. That's one step forward!

What do you mean by "killing the whole app"?

The code you shared helped me a lot to be able to understand your issue, thanks a lot for that. However, I'm not able to reproduce the bug you're facing. If I start the server with enqueue=True and then kill one of the spawned child process, then it restarted successfully and logs continue to be written. If I kill the parent process, then of course the app can no longer deliver any route.

[dstlmrk]

Sorry I wanted to say "After killing one process the whole app is not responding" :)

I use these versions:

• loguru 0.5.2
• Flask 1.1.2
• uwsgi 2.0.18
• python 3.8.2
• OS: Ubuntu 20.04.1 LTS

There is obvious problem with killing uwsgi workers, because if I press Ctrl+C during running uwsgi I see timeout at the end of log (it takes more than 30 seconds).

*** Starting uWSGI 2.0.18 (64bit) on [Sun Sep 13 18:55:38 2020] ***
compiled with version: 9.2.1 20191008 on 17 March 2020 11:53:04
os: Linux-5.4.0-47-generic #51-Ubuntu SMP Fri Sep 4 19:50:52 UTC 2020
nodename: enterprise
machine: x86_64
clock source: unix
detected number of CPU cores: 8
current working directory: /home/dstlmrk/projekty/dev/loguru-rotation
detected binary path: /home/dstlmrk/.local/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
your processes number limit is 62429
your memory page size is 4096 bytes
detected max file descriptor number: 1024
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uWSGI http bound on :9090 fd 4
uwsgi socket 0 bound to TCP address 127.0.0.1:42139 (port auto-assigned) fd 3
Python version: 3.8.2 (default, Jul 16 2020, 14:00:26)  [GCC 9.3.0]
Python main interpreter initialized at 0x55b22d3c4a50
python threads support enabled
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 218760 bytes (213 KB) for 2 cores
*** Operational MODE: preforking ***
pid=80749, configure logger
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x55b22d3c4a50 pid: 80749 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 80749)
spawned uWSGI worker 1 (pid: 80752, cores: 1)
spawned uWSGI worker 2 (pid: 80753, cores: 1)
spawned uWSGI http 1 (pid: 80754)
^CSIGINT/SIGQUIT received...killing workers...
gateway "uWSGI http 1" has been buried (pid: 80754)
Sun Sep 13 18:56:40 2020 - worker 1 (pid: 80752) is taking too much time to die...NO MERCY !!!
Sun Sep 13 18:56:40 2020 - worker 2 (pid: 80753) is taking too much time to die...NO MERCY !!!
worker 1 buried after 1 seconds
worker 2 buried after 1 seconds
goodbye to uWSGI.

There is no waiting with enqueue=False at the end:

*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 74611)
spawned uWSGI worker 1 (pid: 74613, cores: 1)
spawned uWSGI worker 2 (pid: 74614, cores: 1)
spawned uWSGI http 1 (pid: 74615)
^CSIGINT/SIGQUIT received...killing workers...
gateway "uWSGI http 1" has been buried (pid: 74615)
worker 1 buried after 1 seconds
worker 2 buried after 1 seconds
goodbye to uWSGI.

[dstlmrk]

One of my colleagues has the same problem on Mac

[dstlmrk]

Maybe I could create Dockerfile + main.py with this bug if you want :)

[Delgan]

Thank you for details! I can indeed reproduce the problem, the program freezes when I press Ctrl+C.

I'm not sure what causes the problem exactly, but if you configure the logger only if __name__ == "__main__", that seems to fix the issue.

if __name__ == "__main__":
    logger.remove()
    logger.add("file.log", enqueue=True)
    logger.info("Logger is configured")

[dstlmrk]

It seems good but it's not. This code is not executed as expected. Then the behaviour is the same like default loguru settings (no logging to file).

[dstlmrk]

I believe I know where is problem. I created pull request #325. I hope it will helps you :)

[Delgan]

Hi again @dstlmrk!

Quick question about the snippet you shared a few comments above:

# main.py

import os
from loguru import logger

print("pid=%s, configure logger" % os.getpid())
logger.remove()
logger.add("file.log", enqueue=True)
logger.info("Logger is configured")

from flask import Flask
application = Flask(__name__)

Any reason for importing flask after logger.add() / logger.info() and not at the top of the file? I noticed the program sometimes hangs if the import is done earlier. Have you noticed the same thing and if so, have you any idea why it's behaving that strangely?

[dstlmrk]

Hello @Delgan. I spent a few hours but probably I found the problem. It's combination forking and locking the SimpleQueue.

When you are pushing/putting messages to/from SimpleQueue it involves acquiring a lock. And because you can't control the execution of forking in uwsgi there is possibility the lock is copied in an acquired state.

The solution is to don't call logger.info() in master process or don't use enqueue=True probably. I will try more because our production application has still problem with logging.

Read more here: https://pythonspeed.com/articles/python-multiprocessing/

You can try this code. It includes SImpleQueue and forking (because it does uwsgi). You have to find the moment when the lock is copied in an acquired state (the child is completely dead).

import os
import time
import multiprocessing
from threading import Thread
from os import fork, getpid


def queued_writer():
    while True:
        try:
            print(f"[PID={os.getpid()}] queue.get()")
            message = queue.get()
        except Exception:
            print("exception")
            continue

        if message is None:
            break

        if message is True:
            continue

        print(f"[PID={os.getpid()}] write '{message}'")


queue = multiprocessing.SimpleQueue()
thread = Thread(target=queued_writer, daemon=True, name="writer")
thread.start()

queue.put(
    "Lorem ipsum dolor sit amet, consectetuer adipiscing elit."
    "Mauris tincidunt sem sed arcu. Fusce wisi. Aliquam erat volutpat."
    "Praesent id justo in neque elementum ultrices."
    "Morbi scelerisque luctus velit. Mauris metus."
    "Suspendisse sagittis ultrices augue. Pellentesque sapien."
)

if fork():
    while True:
        print("parent")
        time.sleep(1)
else:
    while True:
        print("child")
        time.sleep(1)

[Delgan]

Thank you for taking the time to investigate, it's much more what I was asking for!

However, I am somewhat surprised because the problem you describe was fixed a few months ago! This led to the creation of the _lock_machinery.py file which makes use of os.register_at_fork() to acquire lock before forking and release them once fork is done, preventing possible deadlock in child process.

The article you shared describes the difficulties of mixing multithreading with multiprocessing and why it's discouraged. It was definitely a problem with enqueue=True and internal threading locks used by loguru, as the state is copied into the child process. However, in this case, the SimpleQueue uses a mutiprocessing.Lock and not a threading.Lock. Its state is not copied but shared. This means its state while forking is therefore of little importance, as long as the parent releases it at some point.

To be more specific about the snippet you just shared. By running it multiple times, it indeed happens that the child seems blocked. Here is the twist: it happens because of print() and not because of queue.get()!

As I said, this is a problem experimented and fixed a few months ago: #231 (comment)
If the lock used by print() is acquired during forking, the child will deadlock while writing to stdout.

Maybe all this is closely or remotely associated with the compatibility issues between loguru and uwsgi. But I'm not sure sure, changing the place where import flask is done is enough to make the application buggy! 😕

[dstlmrk]

Yeah but os.register_at_fork() doesn't work in this case. I'm pretty sure the fork is created by C libraries because uwsgi is written in C. You can try it but registered methods are not executed at all. Gunicorn and others uwsgi servers have the same problem. I don't believe it has some solution.

Btw the problem is not print() in child process but queue.get() in queued_writer(). The moment when thread is getting data from a queue and fork is happening is a problem for the app. You can solve it by putting time.sleep(0.1) before fork(). But it helps only once at start because uwsgi usually kills and spawns by forking child processes in time period because of cleaning memory.

[Delgan]

Yes, indeed. When I said that the problem came from print(), I was only referring to the snippet you shared. Removing the print() solves the issue. However, in a context including uwsgi, I'm not sure how it's going. As I already faced some surprises with current_process(), there are maybe some problem with queue.get() too. Too bad uwsgi is not operating well with multiprocessing.