Bug 31208 - Пишет мусор в логи
Summary: Пишет мусор в логи
Status: NEW
Alias: None
Product: Sisyphus
Classification: Development
Component: rsyslog-journal (show other bugs)
Version: unstable
Hardware: all Linux
: P3 major
Assignee: Alexey Shabalin
QA Contact: qa-sisyphus
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-08-18 17:22 MSK by Evgenii Terechkov
Modified: 2015-08-19 03:04 MSK (History)
1 user (show)

See Also:


Attachments
кусок /var/log/messages (12.68 KB, text/plain)
2015-08-18 17:22 MSK, Evgenii Terechkov
no flags Details
/var/spool/rsyslog/imjournal.state (125 bytes, text/plain)
2015-08-19 03:04 MSK, Evgenii Terechkov
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
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). Только я затрудняюсь оценить его содержимое.