多机多线程NFS日志写入遇OSError及.nfs文件问题排查

用到的代码 #

logger.py #

import logging
from logging.handlers import TimedRotatingFileHandler

FORMAT = '%(asctime)s %(message)s'
log = logging.getLogger(__name__)
log.setLevel(logging.INFO)
handler = TimedRotatingFileHandler('/mnt/NFS-drive/debug.log', when='midnight', backupCount=7)
handler.setFormatter(logging.Formatter(FORMAT))
log.addHandler(handler)

countdown.py #

import time
from logger import log

def countdown(minutes=10, callback=None):
    seconds = minutes * 60

    # Run the countdown loop
    while seconds >= 0:
        # Calculate remaining minutes and seconds
        remaining_minutes = seconds // 60
        remaining_seconds = seconds % 60

        # Print the remaining minutes and seconds
        log.info("Time remaining: {:02d}:{:02d}".format(remaining_minutes, remaining_seconds))

        # Sleep for 1 second
        time.sleep(1)

        # Decrement the seconds
        seconds -= 1

    if callback:
        log.info("Timer finished...")
        callback()

遇到的问题 #

1. 触发Stale file handle错误，报错信息如下：

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/__init__.py", line 1104, in emit
    self.flush()
  File "/usr/lib/python3.10/logging/__init__.py", line 1084, in flush
    self.stream.flush()
OSError: [Errno 116] Stale file handle
Call stack:
  File "/mnt/nf/myscripts/run.py", line 128, in run
    countdown(minutes=5, callback=lambda: log.info("Checking queue for new messages"))
  File "/mnt/nf/myscripts/countdown.py", line 14, in countdown
    log.info("Time remaining: {:02d}:{:02d}".format(remaining_minutes, remaining_seconds))
Message: 'Time remaining: 03:25'
Arguments: ()

2. NFS共享目录中出现大量*.nfs格式的临时文件

原因解析 #

1. Stale file handle错误的根源 #

• 你使用的TimedRotatingFileHandler会在午夜自动将当前日志文件debug.log重命名为归档文件，并创建新的debug.log。但这个轮转逻辑是单机器独立执行的：
• 当其中一台机器完成日志轮转后，其他机器的日志处理器仍持有旧debug.log的文件句柄——这个句柄指向的是已经被重命名的归档文件，而非新创建的debug.log。在NFS协议下，原文件的引用已经失效，此时其他机器尝试通过旧句柄写入/刷新日志，就会触发Stale file handle错误。

2. .nfs文件的产生原因 #

• .nfs文件是NFS协议的临时占位文件：当一个文件被某客户端打开时，另一客户端将该文件删除或重命名，NFS不会立即销毁原文件，而是生成一个.nfs开头的临时文件，用来保留原文件的引用，直到所有打开该文件的客户端都关闭对应的文件句柄，才会彻底清理这个文件。
• 在你的场景中，日志轮转后，旧文件被重命名，但其他机器的脚本仍长期持有旧文件的句柄（因为脚本是持续运行的多线程任务），导致NFS不断生成.nfs文件来保留旧文件，最终大量累积。

内容的提问来源于stack exchange，提问作者Batman