Bug 31208

Summary: Пишет мусор в логи
Product: Sisyphus Reporter: Evgenii Terechkov <evg>
Component: rsyslog-journalAssignee: Alexey Shabalin <shaba>
Status: NEW --- QA Contact: qa-sisyphus
Severity: major    
Priority: P3 CC: shaba
Version: unstable   
Hardware: all   
OS: Linux   
Attachments:
Description Flags
кусок /var/log/messages
none
/var/spool/rsyslog/imjournal.state none

Description Evgenii Terechkov 2015-08-18 17:22:31 MSK
Created attachment 6342 [details]
кусок /var/log/messages

При обновлении с rsyslog-8.11.0-alt1 на rsyslog-8.12.0-alt1 почти случайно поймал то, что в хвостах многих лог-файлов появился явно мусор, со старыми таймстампами, от уже давно не используемых программ и т.п. Например, вот как выглядит хвост файла /var/log/cron/info:

=8<=====================================================
Aug 18 17:01:01 thinkpad crond[7215]: (root) CMD (run-parts /etc/cron.hourly)
Aug 18 17:01:01 thinkpad crond[7215]: (root) CMD (run-parts /etc/cron.hourly)
Aug 18 18:01:01 thinkpad crond[11332]: (root) CMD (run-parts /etc/cron.hourly)
Aug 18 18:01:01 thinkpad crond[11332]: (root) CMD (run-parts /etc/cron.hourly)
Aug 18 19:01:01 thinkpad crond[15630]: (root) CMD (run-parts /etc/cron.hourly)
Aug 18 19:01:01 thinkpad crond[15630]: (root) CMD (run-parts /etc/cron.hourly)
Aug 18 20:01:01 thinkpad crond[19713]: (root) CMD (run-parts /etc/cron.hourly)
Aug 18 20:01:01 thinkpad crond[19713]: (root) CMD (run-parts /etc/cron.hourly)
Jul 14 06:36:03 thinkpad crontab[22921]: (evg) LIST (evg)
Jul 14 06:36:08 thinkpad crontab[22934]: (evg) BEGIN EDIT (evg)
Jul 14 06:36:20 thinkpad crontab[22934]: (evg) REPLACE (evg)
Jul 14 06:36:20 thinkpad crontab[22934]: (evg) END EDIT (evg)
Jul 23 06:32:30 thinkpad crontab[18031]: (evg) LIST (evg)
Aug 18 21:01:01 thinkpad crond[12710]: (root) CMD (run-parts /etc/cron.hourly)
=8<=====================================================
двойное протоколирование запуска задач крона здесь связано с тем, что был установлен подпакет rsyslog-journal (без изменения его настроек и без дополнительных ручных настроек). Виден явный мусор в файле. Стал смотреть, что делал, разгадка нашлась быстро - все файлы куда попал мусор имеют время изменения "Aug 18 20:28:09", как раз когда обновлялись rsyslog/rsyslog-journal, а примерно через секунду плагин imjournal пожаловался что начал терять сообщения из-за ограничения скорости. Ещё через минут тринадцать (в 20:41:44) он сообщил, что потерял уже 411218 сообщений. Всё это видно в приложенном файле.

В общем, rsyslog-journal я удалил от греха подальше. Не знаю точно, кто там виноват, но поведение явно нездоровое.
Comment 1 Alexey Shabalin 2015-08-18 18:07:08 MSK
А для каких целей вы его ставили? Чего хотели добиться?
Comment 2 Evgenii Terechkov 2015-08-18 18:34:19 MSK
Исходя из описания, интересно выглядел модуль imjournal.so с точки зрения иметь содержимое журнала в виде чистого текста.

Но по факту установки обнаружил, что всё содержимое пакета это два бинарных модуля и конфиг-файл, загружающий нужный мне модуль. Решил отложить более подробные разборки в механизме работы и поднакопить статистики. И через несколько дней случились описанные грабли :-)

Может конечно я и сделал что-то не то, но это не повод нести чушь в логи в конфигурации изкоробки.
Comment 3 Alexey Shabalin 2015-08-18 22:21:07 MSK
Извиняюсь, я еще сам эти модули не тестировал, руки не дошли.
Обычно достаточно ForwardToSyslog=yes в /etc/systemd/journald.conf, что бы
получить логи в syslog.

Могу предположить следующее:
куда-то пропал  StateFile, соответственно imjournal не знает что он до этого
посылал в логи и решил послать все заново. Пожалуйста, проверьте, если он
вообще.
Как вариант, можно убрать StateFile и указать IgnorePreviousMessages=on.
Comment 4 Evgenii Terechkov 2015-08-19 03:04:56 MSK
Created attachment 6343 [details]
/var/spool/rsyslog/imjournal.state

Такой файл есть, имеет время модификации "Aug 18 20:46" (когда был удалён пакет rsyslog-journal). Только я затрудняюсь оценить его содержимое.