日常辣鸡水文：关于 logging 的进程安全问题#
团队聚餐喝了点酒，作为一个垃圾文档工程师来写一篇日常水文
正文#
现在团队的日志搜集方式从原本的 TCP 直传 logstash 的方式改进为写入一个单文件后，改用 FileBeat 来作为日志搜集的前端。但是这样时常带来一个问题，即日志丢失
嗯，我们线上服务是 Gunicorn 启用多个 Worker 来处理的。这就有个问题了，我们都知道，logging 模块是 Thread Safe 的，在标准的 Log Handler 内部加了一系列锁来确保线程安全，但是 logging 直写文件是不是进程安全的呢？
分析#
我们写文件的方式是用的是 logging 模块中自带的 FileHandler ，首先看看它源码吧
class FileHandler(StreamHandler):
"""
一个将格式化的日志记录写入磁盘文件的处理程序类。
"""
def __init__(self, filename, mode='a', encoding=None, delay=False):
"""
打开指定的文件并将其用作日志记录的流。
"""
# 问题 #27493: 添加对 Path 对象的支持
filename = os.fspath(filename)
# 保持绝对路径，否则使用此路径的派生类在当前目录更改时可能会出错
self.baseFilename = os.path.abspath(filename)
self.mode = mode
self.encoding = encoding
self.delay = delay
if delay:
# 我们不打开流，但我们仍然需要调用 Handler 构造函数来设置级别、格式化程序、锁等。
Handler.__init__(self)
self.stream = None
else:
StreamHandler.__init__(self, self._open())
def close(self):
"""
关闭流。
"""
self.acquire()
try:
try:
if self.stream:
try:
self.flush()
finally:
stream = self.stream
self.stream = None
if hasattr(stream, "close"):
stream.close()
finally:
# 问题 #19523: 无条件调用以防止在设置延迟时发生处理程序泄漏
StreamHandler.close(self)
finally:
self.release()
def _open(self):
"""
使用（原始）模式和编码打开当前基础文件。
返回结果流。
"""
return open(self.baseFilename, self.mode, encoding=self.encoding)
def emit(self, record):
"""
发出记录。
如果在构造函数中指定了延迟，则在调用超类的 emit 之前打开它。
"""
if self.stream is None:
self.stream = self._open()
StreamHandler.emit(self, record)
def __repr__(self):
level = getLevelName(self.level)
return '<%s %s (%s)>' % (self.__class__.__name__, self.baseFilename, level)
嗯，其中关注的点是 _open 方法，以及 emit 方法，首先科普一个背景知识，在我们用 logging 输出日志的时候，logging 模块会调用对应 Handler 中的 handle 方法，在 handle 方法中，会调用 emit 方法输出最后的日志。于是我们如果使用 FileHandler 的话，那么就是先触发 handle 方法的调用，然后触发 emit 方法，在调用 _open 方法获取一个 file point 后，调用父类（更准确的描述书 MRO 上一级）StreamHandler 中 emit 方法。
来看看 StreamHandler 中的 emit 方法吧
class StreamHandler(Handler):
"""
一个将日志记录适当地格式化后写入流的处理程序类。注意，此类不会关闭流，因为可能会使用 sys.stdout 或 sys.stderr。
"""
terminator = '\n'
def __init__(self, stream=None):
"""
初始化处理程序。
如果未指定流，则使用 sys.stderr。
"""
Handler.__init__(self)
if stream is None:
stream = sys.stderr
self.stream = stream
def flush(self):
"""
刷新流。
"""
self.acquire()
try:
if self.stream and hasattr(self.stream, "flush"):
self.stream.flush()
finally:
self.release()
def emit(self, record):
"""
发出记录。
如果指定了格式化程序，则用于格式化记录。
然后将记录写入流，并带有换行符。如果存在异常信息，则使用 traceback.print_exception 格式化并附加到流。如果流具有 'encoding' 属性，则用于确定如何输出到流。
"""
try:
msg = self.format(record)
stream = self.stream
stream.write(msg)
stream.write(self.terminator)
self.flush()
except Exception:
self.handleError(record)
def __repr__(self):
level = getLevelName(self.level)
name = getattr(self.stream, 'name', '')
if name:
name += ' '
return '<%s %s(%s)>' % (self.__class__.__name__, name, level)
嗯很简单，就是调用我们之前获取的 file point 往文件中写入数据
问题就在这里，在 FileHandler 中，_open 函数中调用 open 函数时，所选择的 mode 是 'a' ，也就是通常而言的 O_APPEND 模式。我们知道，通常而言 O_APPEND 可以视作进程安全的，因为 O_APPEND 能够保证内容不被别的 O_APPEND 写操作所覆盖。但是这里为什么会出现日志丢失的情况呢？
原因是在 POSIX 中存在着一种特殊设计，在 《POSIX Programmers Guide》 一书中对此描述如下：
- 小于 PIPE_BUF 字节的写入是原子的；数据不会与其他进程写入同一管道的数据交错。大于 PIPE_BUF 的写入可能以任意方式交错数据。
这段话翻译大概就是，在 POSIX 中存在着一个变量叫做 PIPE_BUF ，这个变量大小为 512 ，在进行写入操作时，如果大小小于 PIPE_BUF 值的写操作，是具有原子性的，即不可被打断，因此不会和其余进程写入的值产生混乱，而如果写入的内容大于 PIPE_BUF ，则操作系统不能保证这一点。
在 Linux 操作系统中，这个值发生了一点变化
- POSIX.1 规定小于 PIPE_BUF 字节的写入必须是原子的：输出数据作为连续序列写入管道。大于 PIPE_BUF 字节的写入可能不是原子的：内核可能会将数据与其他进程写入的数据交错。POSIX.1 要求 PIPE_BUF 至少为 512 字节。（在 Linux 中，PIPE_BUF 为 4096 字节。）
即大于 4K 的写入操作都不能保证其原子性，可能会发生数据紊乱。
而发生数据紊乱后，其日志格式不固定，最终造成解析端没法解析，从而最终日志丢失。
这里我们复现一下，首先测试代码
最后#
这种操作之前从未想过，今天算是打开了新的大门，最后感谢 @依云 前辈的指点 = = 如果没有前辈的提醒，完全想不到即便是 O_APPEND 模式下，数据也不能保证安全。
Reference#
文中参考了两处参考资料，链接如下