Назад | Перейти на главную страницу

gzip softlocks каждую полночь во время ротации журнала nginx, вызывает панику ядра

Некоторые из наших серверов работают на Ubuntu 18.10. На них размещено несколько служб Node.JS, получающих TCP-соединения как восходящие от nginx, а также реализация веб-сокета в Dotnet Core. Это довольно простая установка с точки зрения системного администратора.

Одна из машин в последнее время начала вести себя странно после обновления Ubuntu 18.04 до 18.10. Паника ядра будет происходить почти каждую полночь. Как правило, машина без проблем обрабатывает около 10 000+ подключений в реальном времени. Это довольно мощная установка.

Из системного журнала (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 минут.

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 config не хранит журналы доступа, за исключением одного маршрута, который совсем не занят. До сжатия они никогда не были тяжелее 20 МБ.

Из /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 процессоров должно быть более чем достаточно, чтобы обеспечить достаточно энергии для всех этих задач.

200 запросов отправляются в кеши AMP для очистки последних страниц
Certbot обновит сертификаты HTTPS при необходимости
logrotate будет вращать журналы
rsync сохранит загруженные в этот день изображения и файлы на резервный сервер.
Сервис Node.JS аннулирует старые записи кеша в ОЗУ

Сначала я попытался отложить выполнение этих задач на несколько минут, но logrotate или gzip в какой-то момент все равно удастся вывести из строя весь сервер.

Пара информации о сервере:

Размещено на Linode
Обрабатывает миллионы запросов каждый день
16 ЦП, 64 ГБ ОЗУ
Основные процессы: NodeJS, Dotnet Core, nginx, несколько подпрограмм C ++
К нему подключен дополнительный диск для резервного копирования
В течение дня нет скачков отставания или каких-либо отклонений от нормы
Мы не проводим express сервер mongoose, или другие часто используемые библиотеки
Большинство запросов даже не доходят до какой-либо из служб; nginx будет обслуживать кешированные / статические файлы
Низкий уровень ЦП, оперативная память обычно используется ниже 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 сжимает журналы.

обновление # 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]

Ваша виртуальная машина может находиться на физическом сервере, на котором возникают проблемы с оборудованием. Выключите виртуальную машину, а затем запустите ее снова, и Linode должен запустить ее на другом гипервизоре.

Если вы не используете 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 выгружен / удален.