Смена журналов Rails ведет к открытию старого журнала и его заполнению

Я помогаю поддерживать веб-сайт Rails. Он запускает JRuby 1.5.5, Rails 2.3.10, на машине Solaris Sparc. У меня проблема, связанная с протоколированием.

Чтобы остановить наши лог файлы, которые становятся слишком большими и заполняют диск, мы используем смену журнала, встроенную в класс Logger. В config/environment/production.rb мы имеем:

config.logger = Logger.new(config.log_path, 10, 100.megabyte)

Который должен вращать лог файлы, когда они достигают 100 мегабайт, и хранить только 10 файлов.

Проблема двояка: Rails не вращает журналы должным образом, и он сохраняет старый файл журнала, чтобы писать ему, - но то, что он пишет, - это просто повторное содержимое нескольких запросов. Поэтому, если я делаю ls -l log, я вижу что-то вроде этого:

-rw-r--r-- 83040892 Oct  4 15:07 production.log
-rw-r--r-- 3303158664 Oct  4 15:07 production.log.0
-rw-r--r-- 104857616 Oct  2 23:13 production.log.1
-rw-r--r-- 104857618 Oct  1 17:12 production.log.2

Обратите внимание, что последний циклический журнал все еще открыт и все еще записывается (запуск pfiles подтверждает, что на сервере Rails все еще есть три файла для записи в журнал). Обратите также внимание, что за два дня он достиг 3 гигабайт, где обычно мы делаем 100 МБ в день. Это связано с тем, что он заполнен повторными запросами. Я не могу легко вставить его здесь, но журнал заполнен тем же самым 1000-строчным списком запросов от 18:50 3 октября (который, я считаю, является точкой, в которой лог повернулся), печатается снова и снова. Из прошлого опыта файл журнала будет продолжать заполнять этот повторяющийся контент до тех пор, пока диск не заполнится.

Является ли log shifting/Rails logging просто сломанным? (Нет ничего странного в использовании нашего лог файла: мы не делаем прямого ведения журнала, все это происходит только из Rails-фреймворка.) Очевидный следующий шаг - попробовать что-то вроде logrotate, но если Rails откажется закрыть старые файлы журналов и пишут хлам им навсегда, я подозреваю, что это не решит мою проблему (потому что журнал никогда не будет закрыт, и, следовательно, дисковое пространство никогда не восстанавливается).

Ответы

Ответ 1

Симптом кажется, что один старый файл журнала все еще используется, хотя вы успешно повернули журналы.

Причина наиболее вероятна, что один или несколько экземпляров или потоков Rails по-прежнему используют старый дескриптор файла.

Решение заключается в том, чтобы все экземпляры Rails полностью перезапускались после того, как журналы были повернуты, поэтому все они используют новый дескриптор/имя файла.

Используйте logrotate вместо config.logger, чтобы повернуть ваши журналы!

Я бы предложил использовать логротат UNIX, чтобы повернуть ваши журналы, а не config.logger. ИМХО, что лучшее решение, более надежное, у вас больше контроля за вращением журнала, и вы можете предоставить некоторые команды после ротации, чтобы перезапустить процессы Rails. (либо через параметр logrotate postrotate или endscript)

Смотрите:

http://www.opencsw.org/packages/logrotate/ (пакет логротата для Solaris)

http://www.thegeekstuff.com/2010/07/logrotate-examples/ (учебное пособие по logrotate с примерами)

http://linux.die.net/man/8/logrotate

Можете ли вы использовать Единорог? - Unicorn имеет встроенную поддержку для повторного открытия всех файлов журналов в вашем приложении через сигнал USR1 - это позволяет logrotate вращать файлы атомарно... - Единорог отслеживает и перезапускает его работников! Вы можете убить рабочих после вращения журнала, и Unicorn перезапустит их, убедившись, что они используют новый файл журнала.

Смотрите: https://github.com/blog/517-unicorn (многие преимущества для Единорога над Монгрелем)

Если вы используете Mongrel и не можете переключиться на Unicorn:

используйте logrotate и перезапустите Mongrels с помощью опции postrotate.

надеюсь, что это поможет.

Ответ 2

Я всегда использовал механизм вращения журнала платформы при работе с файлами журнала Rails. Следуя советам http://www.nullislove.com/2007/09/10/rotating-rails-log-files/ и потому, что я запускаю Пассажир из http://overstimulate.com/articles/logrotate-rails-passenger.

Первый метод использует метод logrotate copytruncate для создания нового файла журнала, поэтому процессы, которые все еще имеют дескриптор, всегда будут записывать в текущий файл журнала.

Другие вещи для проверки на сервере:

  • Убедитесь, что ни один из камней или плагинов не имеет дескриптора Logger внутри контекста ruby.
  • Поскольку вы используете JRuby, убедитесь, что там нет застрявшей/бегущей нити, которая пытается выполнить запрос, но застревает журнал.
  • Как и у Пассажира, периодически повторяйте перезапуск сервера Rails. Я знаю, что это эффективный взлом, но он может работать.

Ответ 3

Нил,

Я не знаю, работает ли это для вашей конкретной ситуации, но у меня была аналогичная проблема, и я думаю, что я просто решил ее. В моем случае у меня было два симптома. Первая из них была той же проблемой, что и вы - мой поворот журнала был завинчен... в частности, файл production.log.1 оставался открытым, и продолжалось ведение журнала до того, как production.log также попадал в журнал. Второй симптом состоял в том, что владельцы журнальных файлов и членство в группах продолжали бы переходить к корневому. Приложение "Мои Rails" развертывается через Capistrano с использованием пользователя "deployer", поэтому я получаю всевозможные аккуратные ошибки всякий раз, когда приложение пытается записать в файл журнала, который больше не принадлежит развертывателю.

Я смущен, чтобы сказать, сколько времени мне понадобилось, чтобы понять, в чем причина обеих проблем. Где-то по пути я обновил cron с помощью приложения crontab как root. Должно быть, это было, когда я возился в командной строке... если бы я просто остался с моим рецептом развертывания через Капистрано, я бы не сделал это непреднамеренно. В любом случае, я, наконец, посмотрел в /var/spool/cron/crontabs, и я нашел две копии моего файла crontab... один для развертывателя и один для root. Таким образом, процессы, с которыми работал cron для моего приложения, дублировались - один выполнялся под управлением и второй под root. Это был второй, который закручивал вещи. Как только я удалил root crontab, все было лучше.

Некоторые предостережения: в моей настройке в корневом crontab не было задач, не связанных с приложением, т.е. это был точный дубликат развертывания crontab... поэтому удаление его не имело побочных эффектов для меня. Кроме того, на моем сервере запущен Ubuntu... путь к вашим crontabs может быть другим.

Надеюсь, что это поможет.

  • Дэвид

Ответ 4

Я думаю, что вы забыли "s" в мегабайтах или вместо этого используйте что-то вроде этого

config.logger = Logger.new(config.log_path, 10, 102400)

также проверьте эту ссылку очень полезно

http://railsillustrated.com/logger-tricks.html