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

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

Чтобы наши файлы журналов не стали слишком большими и не заполнили диск, мы используем сдвиг журнала, встроенный в класс Logger. В config/environments/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 октября (я полагаю, что это точка, в которой журналы вращались), напечатанные снова и снова. Судя по прошлому опыту, файл журнала будет продолжать заполняться повторяющимся содержимым до тех пор, пока диск не заполнится.

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


ruby-on-rails logging jrubyonrails
person Neil Brown    schedule 04.10.2011    source источник
comment
какой там сервер приложений?   -  person rtdp    schedule 12.10.2011
comment
какому пользователю/группе принадлежат файлы журналов?   -  person Tilo    schedule 17.10.2011
comment
как вы развертываете свое приложение? например капистрано? что вы используете в интерфейсе, например. Апач? NginX? Единорог?   -  person Tilo    schedule 17.10.2011
comment
Это использование Mongrel (за прокси-сервером Apache, но это не имеет значения), файлы журналов принадлежат пользователю, который запускает сервер, мы не используем capistrano (мы просто развертываем вручную).   -  person Neil Brown    schedule 17.10.2011
comment
2.3 устаревает... вы можете подумать об обновлении до 3.0, которая очень стабильна, и использовать Unicorn вместо Mongrel (настоятельно рекомендуется).   -  person Tilo    schedule 17.10.2011

Ответы (4)


arrow_upward
10
arrow_downward

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

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

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

Используйте logrotate вместо config.logger для ротации журналов!

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

Видеть:

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

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

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

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

См.: https://github.com/blog/517-unicorn (множество преимуществ Unicorn по сравнению с Дворняга)

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

используйте logrotate и перезапустите своих дворняг с помощью опции postrotate.

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

person Tilo    schedule 16.10.2011
comment
Я думаю, что ваше предложение logrotate поможет остановить заполнение нашего дискового пространства, и я думаю, что, вероятно, нам придется это сделать. Я думаю, что после этого наши журналы будут довольно бесполезны, потому что все журналы будут заполнены этими повторяющимися запросами, но лучше иметь бесполезные журналы, чем не хватать места на диске (что вызывает простои). - person Neil Brown; 17.10.2011
comment
«1000-строчный блок запросов», который вы видите дублированным, звучит так, как будто Rails сбрасывает буфер на все еще открытый дескриптор файла, возможно, пытаясь убедиться, что никакая информация не потеряна - например. напишите это в оба файла, чтобы быть уверенным - вы не должны видеть такое поведение при использовании logrotate - person Tilo; 17.10.2011

arrow_upward
2
arrow_downward

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

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

Что еще нужно проверить на сервере:

  • Убедитесь, что ни один из гемов или плагинов не имеет дескриптора Logger внутри контекста ruby.
  • Поскольку вы используете JRuby, убедитесь, что где-то нет зависшего/неуправляемого потока, который пытается выполнить запрос, но застревает в журнале.
  • Как и в случае с Passenger, подумайте о перезапуске серверных процессов Rails время от времени. Я знаю, что это эффективный хак, но он может сработать.
person Daemin    schedule 16.10.2011
comment
Я думаю, что ваша вторая пуля, вероятно, является причиной повторного ведения журнала (хотя мы получаем целый массив запросов, повторяющихся в журналах: как я уже сказал, 1000 строк). Но я не уверен, как мне это отследить: потоки в Ruby on Rails не так легко увидеть, и я не совсем уверен, как отладить программу JRuby (особенно на производственном сервере — я никогда не удавалось вызвать проблему локально). - person Neil Brown; 17.10.2011

arrow_upward
2
arrow_downward

Нил,

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

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

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

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

  • Дэйвид
person David L. Bean    schedule 16.10.2011
comment
Это именно то, что могло быть проблемой ... но, к сожалению, я проверил, и у меня нет этой конкретной проблемы. Но предложение приветствуется! - person Neil Brown; 17.10.2011

arrow_upward
0
arrow_downward

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

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

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

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

person Mahesh    schedule 13.10.2011
comment
Нет, 100.megabyte — это псевдоним 100.megabytes (или наоборот). 100.megabyte #=> 104857600 - person Mischa; 13.10.2011