Bug description
On Windows, Xinference's log rotation crashes every midnight (and on size-based rotation), emitting hundreds of --- Logging error --- tracebacks and disabling log rotation entirely.
Environment
- OS: Windows 10 / 11 (NT)
- Xinference: 3.1.0
- Python: 3.12
- Deployment:
xinference-local with multiple models loaded (bge-m3 + bge-reranker-v2-m3), i.e. several xoscar sub-pool processes each holding the log file open.
Symptom
At midnight (or when a size threshold is hit) the logs fill with:
--- Logging error ---
Traceback (most recent call last):
...
File "...\logging\handlers.py", line ..., in doRollover
self.rotate(self.baseFilename, dfn)
File "...\logging\handlers.py", line ..., in rotate
os.rename(source, dest)
PermissionError: [WinError 32] The process cannot access the file because it is being used by another process.
On a busy host (Hindsight driving high-frequency embedding calls, each triggering a sentence_transformers deprecation warning) this turns into tens of MB of tracebacks per night. The active log file stops rotating / grows unbounded. The service itself keeps running fine.
Root cause
xinference/deploy/utils.py defines SafeRotatingFileHandler / SafeTimedRotatingFileHandler / SafeTimedAndSizeRotatingFileHandler. Their doRollover is serialized across processes via a file lock:
if sys.platform == "win32":
fcntl = None # utils.py line ~28
else:
import fcntl
def _acquire_rotation_lock(self):
if fcntl is None:
return None # <-- on Windows the lock is a NO-OP
...
Because fcntl is None on Windows, _acquire_rotation_lock() returns None, so every xoscar sub-pool calls doRollover concurrently with no serialization. The standard-library rotation then does os.rename(baseFilename, dfn), which fails on Windows whenever any sibling process still holds the log file open → WinError 32. Python's logging module catches that inside its own error handler and prints a full traceback on every subsequent log record, which is what produces the spew.
Suggested fix (cross-platform)
- Cross-process lock that works on Windows. Replace the
fcntl-only lock with a cross-platform one — on Windows use msvcrt.locking (or portalocker) on the existing *.rotate.lock file that the handlers already create.
- Windows-safe
rotate(). When os.rename raises PermissionError / WinError 32, fall back to shutil.copy2(source, dest) + truncate(0) the source in place. The source keeps its inode, so every process that already had it open keeps appending to the (now empty) live log — no data loss, no crash.
- Per-day rotation marker. Add a
<base>.rotated.<YYYY-MM-DD> marker so only one process performs the midnight rotation; a racing second process skips instead of overwriting the freshly-written archive with an empty copy (the copy+truncate fallback alone would otherwise let a delayed process clobber the archive).
Steps to reproduce
- Launch
xinference-local on Windows with ≥2 models loaded (so ≥2 xoscar sub-pools hold the log file open).
- Either wait for midnight, or force a quick size rotation by setting a very small
maxBytes / backupCount.
- Observe
WinError 32 tracebacks in the log and a log file that never rotates.
Bug description
On Windows, Xinference's log rotation crashes every midnight (and on size-based rotation), emitting hundreds of
--- Logging error ---tracebacks and disabling log rotation entirely.Environment
xinference-localwith multiple models loaded (bge-m3 + bge-reranker-v2-m3), i.e. several xoscar sub-pool processes each holding the log file open.Symptom
At midnight (or when a size threshold is hit) the logs fill with:
On a busy host (Hindsight driving high-frequency embedding calls, each triggering a
sentence_transformersdeprecation warning) this turns into tens of MB of tracebacks per night. The active log file stops rotating / grows unbounded. The service itself keeps running fine.Root cause
xinference/deploy/utils.pydefinesSafeRotatingFileHandler/SafeTimedRotatingFileHandler/SafeTimedAndSizeRotatingFileHandler. TheirdoRolloveris serialized across processes via a file lock:Because
fcntlisNoneon Windows,_acquire_rotation_lock()returnsNone, so every xoscar sub-pool callsdoRolloverconcurrently with no serialization. The standard-library rotation then doesos.rename(baseFilename, dfn), which fails on Windows whenever any sibling process still holds the log file open →WinError 32. Python'sloggingmodule catches that inside its own error handler and prints a full traceback on every subsequent log record, which is what produces the spew.Suggested fix (cross-platform)
fcntl-only lock with a cross-platform one — on Windows usemsvcrt.locking(orportalocker) on the existing*.rotate.lockfile that the handlers already create.rotate(). Whenos.renameraisesPermissionError/WinError 32, fall back toshutil.copy2(source, dest)+truncate(0)the source in place. The source keeps its inode, so every process that already had it open keeps appending to the (now empty) live log — no data loss, no crash.<base>.rotated.<YYYY-MM-DD>marker so only one process performs the midnight rotation; a racing second process skips instead of overwriting the freshly-written archive with an empty copy (the copy+truncate fallback alone would otherwise let a delayed process clobber the archive).Steps to reproduce
xinference-localon Windows with ≥2 models loaded (so ≥2 xoscar sub-pools hold the log file open).maxBytes/backupCount.WinError 32tracebacks in the log and a log file that never rotates.