☰

nginx 日志轮换期间，gzip 会在每半夜进行软锁，导致内核崩溃

tag-icon • tag-icon ubuntu logrotate gzip linode kernel-panic
nginx 日志轮换期间，gzip 会在每半夜进行软锁，导致内核崩溃

我们的一些服务器在 Ubuntu 18.10 上运行。它们托管一些 Node.JS 服务，这些服务从 nginx 接收 TCP 连接作为上游，以及 Dotnet Core 中的 websocket 实现。从系统管理员的角度来看，这是一个相当简单的设置。

其中一台机器在从 Ubuntu 18.04 升级到 18.10 后最近开始出现异常。几乎每天午夜都会发生内核崩溃。该机器通常可以实时处理大约 10,000 多个连接而不会出现任何问题。这是一个非常强大的设置。

从 syslog （ryk是我的 sudoer 用户）：

Jun 29 00:00:02 localhost CRON[23415]: (ryk) CMD (/home/ryk/dev/downloadadscript.sh)
Jun 29 00:00:02 localhost CRON[23419]: (ryk) CMD (cd /home/ryk/ampcache && node narcity.index.js 200)
Jun 29 00:00:02 localhost CRON[23420]: (ryk) CMD (cd /home/ryk/ampcache && node mtlblog.index.js 200)
Jun 29 00:00:02 localhost CRON[23421]: (root) CMD (test -x /usr/bin/certbot -a \! -d /run/systemd/system && perl -e 'sleep int(rand(43200))' && certbot -q renew)
Jun 29 00:00:02 localhost CRON[23426]: (ryk) CMD (/home/ryk/dev/uploadsbackup.sh)
Jun 29 00:00:02 localhost CRON[23412]: (CRON) info (No MTA installed, discarding output)
Jun 29 00:00:04 localhost CRON[23409]: (CRON) info (No MTA installed, discarding output)
Jun 29 00:00:04 localhost CRON[23408]: (CRON) info (No MTA installed, discarding output)
Jun 29 00:00:05 localhost logrotate[23418]: error: destination /var/log/nginx/access.log.1.gz already exists, renaming to /var/log/nginx/access.log.1.gz-2019062900.backup
Jun 29 00:00:11 localhost CRON[23413]: (CRON) info (No MTA installed, discarding output)
Jun 29 00:00:58 localhost kernel: [65787.092653] watchdog: BUG: soft lockup - CPU#11 stuck for 26s! [node:8764]
Jun 29 00:00:58 localhost kernel: [65787.092695] watchdog: BUG: soft lockup - CPU#3 stuck for 30s! [node:8715]
Jun 29 00:00:58 localhost kernel: [65787.092735] watchdog: BUG: soft lockup - CPU#8 stuck for 32s! [gzip:23478]
Jun 29 00:00:58 localhost kernel: [65787.092739] Modules linked in:
Jun 29 00:00:58 localhost kernel: [65787.092746] watchdog: BUG: soft lockup - CPU#12 stuck for 27s! [node:23489]
Jun 29 00:00:58 localhost kernel: [65787.092752]  joydev
Jun 29 00:00:58 localhost kernel: [65787.092758] watchdog: BUG: soft lockup - CPU#1 stuck for 37s! [nginx:29255]
Jun 29 00:00:58 localhost kernel: [65787.092763] watchdog: BUG: soft lockup - CPU#10 stuck for 41s! [nginx:29256]
Jun 29 00:00:58 localhost kernel: [65787.092765] Modules linked in:
Jun 29 00:00:58 localhost kernel: [65787.092768] watchdog: BUG: soft lockup - CPU#13 stuck for 37s! [node:3327]
Jun 29 00:00:58 localhost kernel: [65787.092770]  input_leds
Jun 29 00:00:58 localhost kernel: [65787.092773] Modules linked in:
Jun 29 00:00:58 localhost kernel: [65787.092775]  joydev

然后，内核转储无法读取，直到 19 分钟后重新启动。

syslog 内核崩溃转储屏幕截图

Jun 29 00:19:53 localhost kernel: [    0.000000] Linux version 4.18.0-25-generic (buildd@lcy01-amd64-025) (gcc version 8.3.0 (Ubuntu 8.3.0-6ubuntu1~18.10.1)) #26-Ubuntu SMP Mon Jun 24 09:32:08 UTC 2019 (Ubuntu 4.18.0-25.26-generic 4.18.20)
Jun 29 00:19:53 localhost kernel: [    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.18.0-25-generic root=/dev/sda ro console=ttyS0,19200n8 net.ifnames=0

我们使用默认logrotate例程来确保日志具有适当的大小，并对其进行压缩以便存档。对于nginx，它每天都会运行。我们的nginx配置不存储访问日志，除了一条根本不繁忙的路由。压缩前，这些日志的大小永远不会超过 20MB。

从/etc/logrotate.d/nginx：

/var/log/nginx/*.log {
    daily
    missingok
    rotate 14
    compress
    delaycompress
    notifempty
    create 0640 www-data adm
    sharedscripts
    prerotate
        if [ -d /etc/logrotate.d/httpd-prerotate ]; then \
            run-parts /etc/logrotate.d/httpd-prerotate; \
        fi \
    endscript
    postrotate
        invoke-rc.d nginx rotate >/dev/null 2>&1
    endscript
}

午夜时分会同时发生几件事，但 16 个 CPU 足以为所有这些任务提供足够的动力。

  • 向 AMP 缓存发送 200 个请求以清除最新页面
  • 如果需要，Certbot 将更新 HTTPS 证书
  • logrotate 将会旋转日志
  • rsync 将保存当天上传的图像和文件到备份服务器
  • Node.JS 服务将使 RAM 中的旧缓存条目无效

起初，我尝试将这些任务延迟几分钟，但logrotate仍然gzip会在某个时候导致整个服务器崩溃。

有关服务器的一些信息：

  • 由 Linode 托管
  • 每天处理数百万个请求
  • 16 CPU，64GB 内存
  • 主要流程：NodeJS、Dotnet Core、nginx、一些 C++ 例程
  • 有一个附加磁盘用于备份
  • 白天没有出现延迟峰值或任何异常
  • 我们不运行express服务器，mongoose或其他过度使用的库
  • 大多数请求甚至不会到达任何服务；nginx 将提供缓存/静态文件
  • CPU 低，在缓存失效之前 RAM 使用率通常低于 30％

uname -a

Linux localhost 4.18.0-25-generic #26-Ubuntu SMP 星期一 六月 24 09:32:08 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

知道为什么logrotate或gzip会导致整个机器软锁吗？我遗漏了什么吗？

提前致谢。

更新 #1

我刚刚注意到，根据htop，gzip 压缩日志时发生大量窃取时间（CPU 黄色条）。

更新 #2

今天又发生了一次。这是syslog服务器崩溃前的最后一个输出。

Jun 30 00:00:04 localhost logrotate[18277]: error: destination /var/log/nginx/access.log.1.gz already exists, renaming to /var/log/nginx/access.log.1.gz-2019063000.backup

这是最后的输出/var/log/kern.log

Jun 29 00:00:58 localhost kernel: [65787.092735] watchdog: BUG: soft lockup - CPU#8 stuck for 32s! [gzip:23478]

答案1

您的虚拟机可能位于存在硬件问题的物理服务器上。关闭虚拟机然后重新启动，Linode 应该会在不同的虚拟机管理程序上启动它。

答案2

如果您不使用 joydev，请尝试卸载/删除 joydev 模块。

List module and remove

$ sudo lsmod|grep joydev
$ sudo modprobe -r foo
You can also use the rmmod command, which is simple program to remove a module from the Linux Kernel:
$ sudo rmmod joydev

确保 joydev 模块已被卸载/删除。

相关内容