Skip to content

Close second Windows file handle blocking log rename after rollover#14

Open
Mayyhem wants to merge 1 commit into
SpecterOps:mainfrom
Mayyhem:logfix
Open

Close second Windows file handle blocking log rename after rollover#14
Mayyhem wants to merge 1 commit into
SpecterOps:mainfrom
Mayyhem:logfix

Conversation

@Mayyhem
Copy link
Copy Markdown

@Mayyhem Mayyhem commented May 21, 2026

Fix proposed by Codex and tested on Windows 11, Python 3.14.

--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\domainadmin\AppData\Roaming\uv\python\cpython-3.14-windows-x86_64-none\Lib\logging\handlers.py", line 80, in emit
    self.doRollover()
    ~~~~~~~~~~~~~~~^^
  File "C:\Users\domainadmin\Desktop\ohsccm\OpenHound\src\openhound\core\logging.py", line 118, in doRollover
    super().doRollover()
    ~~~~~~~~~~~~~~~~~~^^
  File "C:\Users\domainadmin\AppData\Roaming\uv\python\cpython-3.14-windows-x86_64-none\Lib\logging\handlers.py", line 456, in doRollover
    self.rotate(self.baseFilename, dfn)
    ~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\domainadmin\AppData\Roaming\uv\python\cpython-3.14-windows-x86_64-none\Lib\logging\handlers.py", line 121, in rotate
    os.rename(source, dest)
    ~~~~~~~~~^^^^^^^^^^^^^^
PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: 'C:\\Users\\domainadmin\\AppData\\Local\\openhound\\logs\\openhound.log' -> 'C:\\Users\\domainadmin\\AppData\\Local\\openhound\\logs\\openhound.log.2026-05-20'

Root cause: OpenHound opens the same log file twice during startup.
At import time, logging.py (line 401) runs logger_override.setup(). That setup attaches a rotating handler to the dlt logger at logging.py (line 297), then attaches another rotating handler to the root logger for the same openhound.log at logging.py (line 303). On Windows, TimedRotatingFileHandler cannot rename a file while another open handle still exists. Since the existing log was from 2026-05-20, the first startup log on 2026-05-21 triggers midnight rollover, closes only its own stream, then os.rename() fails because the other handler still has openhound.log open.

Recommended fix:

def _close_handlers(logger: logging.Logger) -> None:
    for handler in logger.handlers[:]:
        logger.removeHandler(handler)
        handler.close()

Use that instead of handlers.clear(), and make only one handler own openhound.log:

# setup()
_close_handlers(self.dlt_logger)
self.dlt_logger.setLevel(getattr(logging, self.level))
self.dlt_logger.propagate = True  # default DLT logs flow to root's single file handler

self.root_logger.setLevel(getattr(logging, self.level))
_close_handlers(self.root_logger)
self.handlers[self.runtime_mode](self.root_logger, self.log_file_path)

Then keep set_handler() for collector-specific DLT logs, but close old handlers first:

# set_handler()
_close_handlers(self.dlt_logger)
self.handlers[self.runtime_mode](self.dlt_logger, valid_path)
self.dlt_logger.propagate = False

For the scheduler/process-pool path, also avoid multiple processes rotating the same file. Best stdlib solution is QueueHandler/QueueListener so one parent listener owns the file handler; simpler fallback is per-process log filenames.

@Mayyhem
Copy link
Copy Markdown
Author

Mayyhem commented May 22, 2026

Still appears to be an issue after last rollover period. Investigating.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant