☰

为什么 abrt 会接管未崩溃的进程的日志输出？

tag-icon • tag-icon syslog crash
为什么 abrt 会接管未崩溃的进程的日志输出？

简洁版本：

  1. 我有一个长时间运行的进程（Web 代理），它（详细地）记录到 syslog
  2. 某物坏事发生了，abrt介入不知何故
  3. 该过程继续运行...
  4. ...但 syslog 的所有日志消息现在都标记为“abrt:”而不是“xfcproxy[1234]:”
  5. 知道为什么吗？

长版：

这是我们从日志角度看到的示例，“发生了一些事情”，进程继续记录，但 syslog 中的进程名称发生了变化。请注意来自代理的所有消息如何以“uuid=...”开头，我们可以看到此类消息记录在该片段顶部的“xfcproxy[4808]:”下以及该片段底部的“abrt:”下

Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e connection=Open client_ip=192.168.3.21 client_port=40973
Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e connection=Information method=CONNECT path=www.example.com port=443
Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e rule=Destination message="Match made" rule=monitoring uri=www.example.com
Aug 27 07:02:55 proxy1 rsyslogd-2177: imuxsock begins to drop messages from pid 4808 due to rate-limiting
Aug 27 07:02:55 proxy1 abrtd: New client connected
Aug 27 07:02:55 proxy1 abrtd: Directory 'pyhook-2014-08-27-07:02:55-4808' creation detected
Aug 27 07:02:55 proxy1 abrt-server[27032]: Saved Python crash dump of pid 4808 to /var/spool/abrt/pyhook-2014-08-27-07:02:55-4808
Aug 27 07:02:55 proxy1 abrtd: Executable '/var/lib/xfcProxy/bin/xfcProxy.py' doesn't belong to any package and ProcessUnpackaged is set to 'no'
Aug 27 07:02:55 proxy1 abrtd: 'post-create' on '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808' exited with 1
Aug 27 07:02:55 proxy1 abrtd: Deleting problem directory '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808'
Aug 27 07:03:37 proxy1 rsyslogd-2177: imuxsock lost 1642 messages from pid 4808 due to rate-limiting
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 connection=Open client_ip=192.168.3.21 client_port=40976
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 connection=Information method=CONNECT path=www.example.com port=443
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 rule=Destination message="Match made" rule=monitoring uri=www.example.com

使用“ps”我可以看到一直在运行的 PID 4808 仍在运行：

[root@proxy1 log]# ps 4808
  PID TTY      STAT   TIME COMMAND
 4808 ?        S      1:34 python /var/lib/xfcProxy/bin/xfcProxy.py
[root@proxy1 log]#

“imuxsock 开始丢弃消息”有点正常 - 这个守护进程非常健谈（我在这里只显示了一小部分连续的消息子集），除了速率限制问题之外，一系列消息完全可以触发速率限制。

虽然我对 abrt 的了解有限，但它似乎没有崩溃信息，但确实认为该进程的崩溃与日志的时间相关：

[root@proxy1 abrt]# pwd
/var/spool/abrt
[root@proxy1 abrt]# ls -l
total 4
-rw-r--r--. 1 root root  0 Mar 18 15:45 abrt-db
-rw-------  1 root root 33 Aug 27 07:02 last-via-server
[root@proxy1 abrt]# echo `cat last-via-server `
/var/lib/xfcProxy/bin/xfcProxy.py
[root@proxy1 abrt]#

有问题的进程是一个多线程 python 进程 - 我当然愿意接受这样的想法：我没有正确清理线程，从而触发了这种行为。这只是奇怪的行为。

对@Mikel 的澄清：

  • 是的，RHEL 6
  • /var/log/messages 通过 rsyslog。我还没有尝试过journald，并且需要在非生产服务器上重现才能尝试这样的更改。

更新以下赏金期：

恐怕我无法为 E Carter Young 的现有答案授予赏金，原因如下：

  1. 据我通过查看 rsyslog 源得知，imuxsock 速率限制不会触发对进程的任何类型的更改或以任何方式涉及 abrtd。它只是暂时丢弃该流，然后稍后恢复读取。
  2. 进程过度写入 syslog 绝不是缓冲区溢出情况。资源利用率，是的；甚至可能拒绝服务，但仅仅因为它是一个缓冲区并且仅仅因为它非常满并不意味着它是缓冲区溢出。
  3. 所描述的步骤与实际情况不符；具体来说，在步骤 6 中，rsyslog 不是从 abrt 进程获取，而是从原始进程获取；神秘的是为什么它使用 abrt 的名字。
  4. 我也不相信这里存在任何竞争条件。 （快速填充日志缓冲区不是竞争条件）

我认为这个问题太复杂且缺乏数据，它可以归结为多个更简单的问题，可以用更多数据来提出：

  • 如果根据定义 abrtd 在崩溃的进程上触发，为什么它会在不退出的进程上触发？什么代表了足以让 abrtd 参与进来的崩溃？我认为答案在于丢失的日志，但我不认为丢失的日志本身就是答案。没有证据表明 rsyslog 调用 abrtd。
  • 为什么在进程上触发 abrtd 后，rsyslog 开始使用 abrt 作为进程名称（以上一个问题所回答的可证明的方式）？

唉，如果没有更多数据，我今天不愿意提出这些问题。

虽然我不能接受这个答案，但我相信它绝对有价值：

  • abrtd黑名单说明
  • 清晰简洁地讨论我的选择
    • 增加或删除速率限制和混乱日志
    • 改变流程的冗长程度
    • 使用 abrt 将进程列入黑名单，使其永远不会介入

因此，我很高兴当赏金到期时，一半的赏金将归于 E Carter Young 的答案，作为得票最高的答案。

答案1

如果您不希望该进程由 abrtd 处理，请将其添加到 abrtd 黑名单中这个conf文件。 Imuxsock 正在限制日志记录量，因为速率限制已启用。一旦达到限制，abrt 将不再记录真实的进程名称，因为它被告知不要这样做，因此由于进程仍在运行，abrt 显示为替换。看这个博客。您可以考虑使用乌贼

更新
要了解此更新部分，您需要阅读多路复用， 具体来说：

在计算机编程中，它可能指使用单个内存资源（例如文件句柄）来处理多个外部资源（例如磁盘文件）。

违规进程的文件句柄通过管道传输到内存资源中。在正常情况下，大多数服务和流程都有退出代码。一旦达到速率限制，immux 套接字会将控制权转移到 rsyslog 以写入以下行：

由于速率限制，imuxsock 开始丢弃来自 pid 4808 的消息

此时，abrt 假设有问题的进程将退出并带有异常退出代码，并将有问题的进程和任何输出写入/var/spool/abrt/pyhook-(time_date).由于您的脚本没有退出代码，因此在下一次写入日志时，rsyslog 会抓取 imuxsocket 缓冲区中的所有内容，但由于套接字缓冲区从未清空 - 请参阅步骤 5，因为您的进程仍在运行，因此会产生缓冲区问题...黑客通常会将这些情况转化为缓冲区溢出。这些步骤按以下顺序发生：

  1. Imuxsock 向 rsyslog 报告不应报告进程 4808。
  2. abrtd 配置为报告任何奇怪的行为，并启动
  3. rsyslog 尊重该请求。
  4. 您的脚本在 pid 4808 下不断写入日志，报告没有退出代码，因为您是这样设计的。
  5. abrtd 意识到它无法向 rsyslog 提供退出代码，会执行以下操作（因为您的进程不会退出）：

8 月 27 日 07:02:55 proxy1 abrtd：删除问题目录 '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808'

如果报告了退出代码，abrtd 会向您发送错误报告（如果已配置）。看abrtd 手册页，您将看到 6. rsyslog 的内容/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808
，因为它遵循步骤 2，无法报告进程 4808 获取 imux 缓冲区中的最新项目，这恰好是 abrt 进程，因为 abrt 仍在等待来自的退出代码第5步，但由于第5步从未完成......

用编程术语来说，这称为竞争条件。您编写的程序填充日志缓冲区的速度比日志缓冲区写入输出的速度快。因此：

  • 设置 SysSock.RateLimit.Interval > 5 秒，并且 SysSock.RateLimit.Burst > 200
  • 设置 SysSock.RateLimit.Interval = 0 并使日志变得混乱。
  • 使用参数重写程序以设置详细程度
  • 将脚本作为服务运行并在 abrtd 配置中将其列入黑名单

相关内容