python - Python 2.7 错误地使用 TCP 聚合系统日志消息，与 UDP 一起工作正常

Question

使用 Linux Mint 19.1 附带的 Python 2.7.15rc1，我将一些数据系统记录到 rsyslog 8.32.0-1ubuntu4。通过 TCP 执行此操作会错误地将多个日志消息连接到 /var/log/syslog 中的一行中，而 UDP 正确地不会执行此聚合。

为了可靠性，我想使用 TCP 而不是 UDP，但我需要非串联输出。

如果我将程序中的一行从：

socktype = socket.SOCK_DGRAM

...至：

socktype = socket.SOCK_STREAM

...然后事情开始奇怪地连接起来。一行代码是从已知良好代码复制问题所需的唯一代码更改。

这就是我获取日志处理程序的方式：

handler = logging.handlers.SysLogHandler(address=address, socktype=socktype)

良好情况下的日志消息（使用 UDP）看起来像（对于 EG）：

Jun 11 15:59:25 2019-06-11 15: 59:25,870|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading xgb_factory
Jun 11 15:59:25 2019-06-11 15: 59:25,871|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading lgb_factory
Jun 11 15:59:25 2019-06-11 15: 59:25,871|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading rf_factory
Jun 11 15:59:39 2019-06-11 15: 59:39,161|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading xgb_factory
Jun 11 15:59:39 2019-06-11 15: 59:39,161|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading lgb_factory
Jun 11 15:59:39 2019-06-11 15: 59:39,162|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading rf_factory

坏情况下的日志消息（使用 TCP）看起来像（对于 EG）：

Jun 11 11:55:04 2019-06-11 11: 53:43,139|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading xgb_factory#000<14>2019-06-11 11:53:43,140|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading lgb_factory#000<14>2019-06-11 11:53:43,141|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading rf_factory#000<14>2019-06-11 11:53:57,842|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading xgb_factory#000<14>2019-06-11 11:53:57,843|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading lgb_factory#000<14>2019-06-11 11:53:57,843|_|INFO|_|dstromberg-inspiron-5570|_|domain.classifier.factories.classifier_academy|_|classifier_academy.py|_|load|_|132|_|loading rf_factory

在 TCP 情况下，时间戳总是有那个虚假的空间（ASCII 32，在“2019-06-11 11:53:43,139”中的小时后），并且多条消息被连接成一条消息。这些消息似乎与以下内容相结合：“#000<14>”。#000 部分是一致的，但数字部分（在这种情况下为 14）会随着发生率的变化而变化。不过，它总是一个很小的整数。

这是 SyslogHandler 中的错误吗？这是一个已知问题吗？除了切换到UDP之外，有谁知道修复？

我正在做的唯一甚至有点不寻常的事情（除了基于 TCP 的系统日志）是添加一个过滤器来添加一个（docker）主机名。看起来像：

class ContainerFilter(logging.Filter):
    """This is a filter that just adds the container name (hostname)."""

    def __init__(self, name='', container_id=None):
        """Initialize."""
        super(ContainerFilter, self).__init__(name)
        self.container_id = container_id

    def filter(self, record):
        """Set record's metric and container_id attributes, if available."""
        record.container = self.container_id
        return True

filter_ = ContainerFilter(container_id=_DOCKER_CONTAINER_ID)
handler.addFilter(filter_)

我认为成为 Nagle 的事情发生的太多了。

关于 TCP 与 UDP - 我喜欢 TCP 的可靠性，而且我喜欢它在它不工作时，有一个异常而不是仅仅丢弃消息。

另外：我知道 Python 2.x 很快就会不受支持，但是这个特定的代码将在 2.xa 上出现一段时间。

标签： pythonloggingtcpudpsyslog