LINUX.ORG.RU
Форум — Admin  

Стопроцентная загрузка одного из ядер процессора непонятным процессом (ogrotate)

 ,


0

2

Добрый день. Наблюдаю какую то дичь на некоторых машинах. Операционные системы - Ubuntu 22.04 и Redos, но набор прикладного софта схож. И подозреваю, что дело именно в прикладном софте, но не могу понять, в чём именно.

После 2-3 дней аптайма вылезает процесс (ogrotate) и грузит одно из ядер. Название процесса именно такое, в скобках. Где то читал, что в скобки ядро заключает зомби процессы, но это не зомби.

Логично по названию (и по частоте появления) предположить, что это какой то мутировавший logrotate. И действительно, journalctl -xeu logrotate.service иногда выдаёт какие то ошибки, но никакой конкретики: 

Subject: Unit process exited
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░ 
░░ An ExecStart= process belonging to unit logrotate.service has exited.
░░ 
░░ The process' exit code is 'killed' and its exit status is 15.
мар 15 10:02:28 Terminal systemd[1]: logrotate.service: Failed with result 'signal'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░ 
░░ The unit logrotate.service has entered the 'failed' state with result 'signal'.
мар 15 10:02:28 Terminal systemd[1]: Failed to start Rotate log files.
░░ Subject: Ошибка юнита logrotate.service
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░ 
░░ Произошел сбой юнита logrotate.service.
░░ 
░░ Результат: failed.

А после этого как ни в чём не бывыло ошибки прекращаются, и дальше в логе только успешные срабатывания.

Пробовал поискать в /etc/logrotate.d непонятные файлы, но вроде там всё стандартно:

ls -l /etc/logrotate.d/
итого 72
-rw-r--r--. 1 root root   91 янв 11  2022 bootlog
-rw-r--r--. 1 root root  130 авг 30  2019 btmp
-rw-r--r--. 1 root root  160 окт  7  2020 chrony
-rw-r--r--. 1 root root   88 сен  1  2023 dnf
-rw-r--r--. 1 root root 1102 ноя  6 18:24 glusterfs
-rw-r--r--. 1 root root  138 ноя  4  2016 iptraf-ng
-rw-r--r--. 1 root root  172 ноя 14  2019 iscsiuiolog
-rw-r--r--. 1 root root  157 янв 18  2023 kadmind
-rw-r--r--. 1 root root  158 янв 18  2023 krb5kdc
-rw-r--r--. 1 root root   69 сен  7  2023 libreswan
-rw-r--r--  1 root root  141 апр  8  2020 lightdm
-rw-r--r--. 1 root root  136 апр 13  2023 ppp
-rw-r--r--. 1 root root  408 окт 29  2020 psacct
-rw-r--r--. 1 root root  226 янв 24  2022 rsyslog
-rw-r--r--. 1 root root  155 ноя  7 11:22 samba
-rw-r--r--. 1 root root  237 фев 16  2023 sssd
-rw-r--r--. 1 root root  100 сен 22 17:21 wpa_supplicant
-rw-r--r--. 1 root root  145 мая  7  2019 wtmp

Уже даже написал скрипт-костыль, который по крону будет прибивать подобные процессы, но хотелось бы разобраться, и по хорошему решить проблему. Буду благодарен за любые подсказки.

Глянь сколько у тебя логи занимают /var/log и прочие, если не сервер ограничь размер, можно и в tmp перенести. Запусти вручную команду из сервиса logrotate и смотри на ошибки

anonymous
()

который по крону будет прибивать подобные процессы

Вы хоть разберитесь, что это за процесс — есть у него родитель, время запуска, исполняемый файл (/proc/PID/exe). А то ещё выясниться, что ogrotate — это из лога, а не из вывода команды ″ps″.

mky ★★★★★
()
Ответ на: комментарий от greenman

Если один человек очепятался, то почему и другой не мог такое же исполнить? Или если один человек словил каку, то почему и другой не мог словить её же? А по начальной диагностике mky выше все правильно написал, добавлять к этому нечего.

anc ★★★★★
()
Последнее исправление: anc (всего исправлений: 1)
Ответ на: комментарий от mky

lrwxrwxrwx 1 root root 0 мар 19 10:39 /proc/46831/exe -> /usr/lib/systemd/systemd

ps -eo pid,lstart,cmd | grep ogrotate 46831 Sun Mar 17 00:00:10 2024 (ogrotate)

ps -o ppid=46831 46831 96858 96859

ps axfu | grep 96858 user1 96858 0.0 0.1 50128 5880 ? S 10:38 0:00 _ sshd: user1@pts/0

[user1@Terminal ~]$ ps axfu | grep 96859 user1 96859 0.0 0.1 218216 5604 pts/0 Ss 10:38 0:00 _ -bash

Получается, либо systemd теперь сам занимается ротацией логов (не удивлюсь), либо это вообще не ротация логов. Не понятно

eol3000
() автор топика
Последнее исправление: eol3000 (всего исправлений: 1)
Ответ на: комментарий от eol3000

Да, это похоже на systemd. Он форкается и переименовывает процесс, отмечая его круглыми скобками. Чтобы не было проблем, он ограничивает имя 10 символами (по длине строки /sbin/init). Видимо, где-то в коде ошибка, раз они обрезают первую букву, а не последнюю.

А почему он начинает много жрать проц непонятно. Посмотрите объём логов, вроде-бы /var/log/journal или /run/systemd/journal.

mky ★★★★★
()
Ответ на: комментарий от eol3000

Посмотрите ″systemctl status logrotate.service″. Там будет указано, какой юнит файл используется. Посмотрите, что там в ″ExecStart=″. По идее, там должен быть обычный logrotate, отдельный бинарник, а не systemd. И этот бинарник из ExecStart у вас кто-то убивает, то есть отправляет ему сигнал SIGTERM, ('killed' and its exit status is 15). И у него должен быть файл, обычный текстовый, logrotate.status, в /var/lib/, или /var/lib/misc/ или /var/lib/logrotate. И по содержимому файла можно понять, вобще ротация логов происходит или нет.

Запускаться этот юнит должен по таймеру, как возникнет жрущий процесс, можно посмотреть время его запуска, время сработки таймера ″systemctl list-timers″, и журнал по logrotate.service. Как-то сопоставить время, может это вобще не связаные события.

Ну ещё всегда можно сделать на этот жрущий процесс ″strace -p PID″, и, через какое-то время нажать Ctrl+C, возможно, в терминале будет куча строк. Может там будут какие имена файлов, может по ним какая бага нагуглится...

mky ★★★★★
()
Последнее исправление: mky (всего исправлений: 1)
Ответ на: комментарий от mky

Спасибо большое за развёрнутый ответ. Выяснил, что это действительно происходит от logrotate:

sudo systemctl status logrotate.service [sudo] пароль для user1: ● logrotate.service - Rotate log files Loaded: loaded (/usr/lib/systemd/system/logrotate.service; static) Active: activating (start) since Sun 2024-03-17 00:00:11 MSK; 1 weeks 3 days ago TriggeredBy: ● logrotate.timer Docs: man:logrotate(8) man:logrotate.conf(5) Main PID: 46831 ((ogrotate)) Tasks: 1 (limit: 4182) Memory: 54.2M CPU: 1w 3d 16h 3min 27.360s CGroup: /system.slice/logrotate.service └─46831 (ogrotate)

Судя по всему, ротации логов не происходит, пока запущен жрущий (ogrotate). В logrotate.status последняя ротация указана 15 марта.

А strace выдаёт огромное количество информации каждую секунду. Честно говоря, мне трудно выделить тут что либо ценное. Вот небольшая часть выдачи, может кому нибудь это что то скажет: read(22, «=4096k,nr_inodes=65536,mode=755,inode64\n212179 429265 0:5 /bus /proc/bus rw,nosuid,noexec shared:8 - devtmpfs devtmpfs rw,size=4096k,nr_inodes=65536,mode=755,inode64\n212178 429264 0:5 /bus /dev/bus rw,nosuid,noexec shared:8 - devtmpfs devtmpfs rw,size=4096k,nr_inodes=65536,mode=755,inode64\n212177 42»…, 1024) = 1024 read(22, «36,mode=755,inode64\n212171 429257 0:5 /bus /proc/bus rw,nosuid,noexec shared:8 - devtmpfs devtmpfs rw,size=4096k,nr_inodes=65536,mode=755,inode64\n212170 429256 0:5 /bus /dev/bus rw,nosuid,noexec shared:8 - devtmpfs devtmpfs rw,size=4096k,nr_inodes=65536,mode=755,inode64\n212169 429255 0:5 /bus /proc/»…, 1024) = 1024 read(22, «212163 429249 0:5 /bus /proc/bus rw,nosuid,noexec shared:8 - devtmpfs devtmpfs rw,size=4096k,nr_inodes=65536,mode=755,inode64\n212162 429248 0:5 /bus /dev/bus rw,nosuid,noexec shared:8 - devtmpfs devtmpfs rw,size=4096k,nr_inodes=65536,mode=755,inode64\n212161 429247 0:5 /bus /proc/bus rw,nosuid,noexec»…, 1024) = 1024 read(22, «us /proc/bus rw,nosuid,noexec shared:8 - devtmpfs devtmpfs rw,size=4096k,nr_inodes=65536,mode=755,inode64\n212154 429240 0:5 /bus /dev/bus rw,nosuid,noexec shared:8 - devtmpfs devtmpfs rw,size=4096k,nr_inodes=65536,mode=755,inode64\n212153 429239 0:5 /bus /proc/bus rw,nosuid,noexec shared:8 - devtmpfs»…, 1024) = 1024

eol3000
() автор топика
Admin