Logger fails to roll over in a multiprocess environment

[John-Memjet]

Hi

I'm using logger-tt, version 1.6.1, in a multiprocess environment with
Python 3.9.4 on a Windows 10 machine.

I've attached my config file, which is essentially the example one
in the documentation.

After the time the code tries to roll over the log file I the logger-tt module
gets itself into a state where it gives me the following exception trace, on
what looks like every call to the logger. This continues till I shut down and
restart the code. Other than that it works as advertised.

Any suggestions on what I might have done wrong?

10.202.51.66 - - [28/Sep/2021 04:40:26] "POST /?event=up HTTP/1.1" 200 -
--- Logging error ---
Traceback (most recent call last):
File "C:\Python39\lib\logging\handlers.py", line 74, in emit
self.doRollover()
File "C:\Python39\lib\logging\handlers.py", line 403, in doRollover
self.rotate(self.baseFilename, dfn)
File "C:\Python39\lib\logging\handlers.py", line 115, in rotate
os.rename(source, dest)
PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: 'H:\linux-git\91-4-1000-6-3-FSI_Thermal_Sensor\03-software_products\02-products\02-test_server\logs\pyro_server.log' -> 'H:\linux-git\91-4-1000-6-3-FSI_Thermal_Sensor\03-software_products\02-products\02-test_server\logs\pyro_server.log.2021-09-27'
Call stack:
File "C:\Python39\lib\threading.py", line 912, in _bootstrap
self._bootstrap_inner()
File "C:\Python39\lib\threading.py", line 954, in bootstrap_inner
self.run()
File "H:\linux-git\91-4-1000-6-3-FSI_Thermal_Sensor\03-software_products\02-products\02-test_server.windows_venv\lib\site-packages\logger_tt_init.py", line 53, in thread_run_with_exception_logging
self._target(*self._args, **self._kwargs)
File "C:\Python39\lib\socketserver.py", line 683, in process_request_thread
self.finish_request(request, client_address)
File "C:\Python39\lib\socketserver.py", line 360, in finish_request
self.RequestHandlerClass(request, client_address, self)
File "C:\Python39\lib\socketserver.py", line 747, in init
self.handle()
File "H:\linux-git\91-4-1000-6-3-FSI_Thermal_Sensor\03-software_products\02-products\02-test_server.windows_venv\lib\site-packages\logger_tt\core.py", line 240, in handle
self.handle_log_record(record)
File "H:\linux-git\91-4-1000-6-3-FSI_Thermal_Sensor\03-software_products\02-products\02-test_server.windows_venv\lib\site-packages\logger_tt\core.py", line 250, in handle_log_record
handler.handle(record
logging_config.zip
)

[christian212]

Same problem for me on Windows Server 2016. Also in a multiprocess environment

[Dragon2fly]

Hi @John-Memjet
Hi @christian212

Can you guys provide more information related to this problem?

1. What are your setup_logging parameters?
2. When does this error occur? (after you re-run your program, at midnight, ...)
3. How many programs that use logger_tt run at the same time?
4. Do you use threads inside the child process?

And if possible, can you provide a minimal reproducible code for this problem?

[christian212]

Hi @Dragon2fly

1. setup_logging(config_path=(os.path.dirname(__file__) + "/log_config.json"), use_multiprocessing=True)
2. Problem occurs at midnight when the TimedRotatingFileHandler opens the new log file
3. For me it is around 40 processes and 3 threads next to the main thread. But the same problem occurs with only 4 processes, so it's not due to too many processes
4. I don't have any. Just sub-process calls, but this also isn't the problem in my opinion

Regarding the minimal working example: I can provide one if really necessary, but I think the problem will also occur if you spawn 2 processes let them do some stuff and wait for the TimedRotatingFileHandler to open a new file. For debugging purposes it makes sense to set the interval to 1 minute or something like this

log_config.zip

[John-Memjet]

Hi @Dragon2fly

1. My setup_logging is:

setup_logging(
config_path=os.path.join(os.path.dirname('.'), 'logging_config.yaml'),
log_path=os.path.join(os.path.dirname('.'), 'logs', 'pyro_server.log'),
)

My config file was attached to the original post.

2. It occurs at midnight. If I shut down and restart it it works as expected.
3. I'm not using it in any other programs.
4. My app is only using 3 processes. I'm not explicitly starting any threads but the modules I run may.

• 1 running HTTPServer from Pythons standard library, it gets a POST message once every 5 minutes.
• One uses SQLAlchemy to put data into a database, data comes from a queue fed by the HTTPServer process.
• Last process starts up and just waits on a queue. It isn't used at the current level of development except when testing that it actually runs. It is running PySimpleGui to bring up a window when a message is passed to it.

[Dragon2fly]

Hi @christian212

Thanks for your suggestion. I am able to reproduce the problem when set the rollover interval to 10 seconds.

So here is what happens:
When creating child processes, each of the child calls setup_logging again. This call creates handlers and loggers again. TimedRotatingFileHandler opens the log file again. No errors occur at this stage because it doesn't try to modify the file.
When the rolling interval passes, the main process tries to rename the log while all the child still open it, so an error occurs.

The fix is quite easy, just add the delay parameter as below to the log_config file:

handlers:
  console:
    class: logging.StreamHandler
    level: INFO
    formatter: brief
    stream: ext://sys.stdout

  error_file_handler:
    class: logging.handlers.TimedRotatingFileHandler
    level: DEBUG
    formatter: simple
    filename: logs/log.txt
    backupCount: 15
    encoding: utf8
    when: s
    interval: 10
    delay: True                   <-------------- add this

This essentially tells all child processes to not open the log file until they actually need to write to it, which they will never do.

@John-Memjet please try the above fix

[christian212]

Hi @Dragon2fly

thanks for the explanation and the fix, it is working as expected!

[John-Memjet]

Hi @Dragon2fly

Fixed my issue as well. Much appreciate the quick response.