最近遇到一个django日志相关的问题，之前线上服务的日志用的是，

django FileHandler + logrotate copytruncate

但上周两次在日志rotate的时候挂掉，经过分析应当是日志copy时带来大量的磁盘io、cpu消耗导致了整个机器无响应。当时的处理策略是改用，

django WatchedFileHandler + logrotate create

刚改完后运行良好，但几天下来出现了两次错误，

ValueError: I/O operation on closed file

上面这个error一旦出现则是会导致整个django进程就挂了，因为每个请求多少都会进行log操作，于是都在log这步挂掉，带来了大量500错误。

在上述error之前log中另有一次错误，

IOError: [Errno 13] Permission denied:

从两个错误信息可以得知，django在操作系统执行logrotate时候出现问题，导致log文件关闭后未能打开，而后写log的时候则是一直失败。

分析下WatchedFileHandler源代码，

class WatchedFileHandler(logging.FileHandler):
  def __init__(self, filename, mode='a', encoding=None, delay=0):
      logging.FileHandler.__init__(self, filename, mode, encoding, delay)
      if not os.path.exists(self.baseFilename):
          self.dev, self.ino = -1, -1
      else:
          stat = os.stat(self.baseFilename)
          self.dev, self.ino = stat[ST_DEV], stat[ST_INO]

  def emit(self, record):
      if not os.path.exists(self.baseFilename):
          stat = None
          changed = 1
      else:
          stat = os.stat(self.baseFilename)
          changed = (stat[ST_DEV] != self.dev) or (stat[ST_INO] != self.ino)
      if changed and self.stream is not None:
          self.stream.flush()
          self.stream.close()
          self.stream = self._open()
          if stat is None:
              stat = os.stat(self.baseFilename)
          self.dev, self.ino = stat[ST_DEV], stat[ST_INO]
      logging.FileHandler.emit(self, record)

仔细分析上述代码还是能看出问题所在的，WatchedFileHandler每次会检查log文件是否改变，若改变后则会执行flush + close + open，但若是open操作挂掉，那么下回进入emit函数时self.stream就会是一个closed状态，再也没机会复原。

采用logrotate create进行日志操作时，logrotate会首先rename原来的日志文件，然后创建新的同名文件。在创建文件的那个瞬间，很难说self._open()函数能够执行成功。虽然“Permission denied”这个错误消息有点小不理解，但解决这个问题的方法至此应当明显了。

在self.stream.flush之前判断self.stream是否为closed状态即可，

def emit(self, record):
    ....
    if changed and self.stream is not None:
        if not self.stream.closed:
            self.stream.flush()
            self.stream.close()
      ...
   ...

多加上这么个if判断就可以，虽然那一次“Permission denied”错误可能避免不了，但那之后的flush操作至少能够正常运行。

实际项目中到处是陷阱到处是坑，这次深有体会。