Rails日志文件切割会使旧日志一直处于开启状态并且填满它。

Question

我帮助维护一个Rails网站。它在Solaris Sparc机器上运行JRruby 1.5.5，Rails 2.3.10版本。我有一个与日志相关的问题。

为了防止日志文件过大并填满磁盘，我们使用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 GB，而通常我们每天只需要100 MB。这是因为它充满了重复的请求。我不能轻松地将其粘贴在这里，但是日志中充满了来自10月3日18:50的相同的1000行请求块，反复打印。根据过去的经验，日志文件将继续用这个重复的内容填充，直到磁盘填满。

日志转移/Rails 日志记录是否存在问题？（我们的日志文件使用没有任何异常：我们不进行任何直接记录，所有内容都来自 Rails 框架。）显然的下一步是尝试类似于 logrotate 的东西，但如果 Rails 拒绝关闭旧日志文件并永远写入垃圾数据，则我怀疑它不会解决我的问题（因为日志永远不会关闭，因此磁盘空间永远无法恢复）。

- Neil Brown

---

哪个应用服务器？ - rtdp

这些日志文件属于哪个用户/组？ - Tilo

你是如何部署你的应用程序的？例如使用Capistrano吗？在前端中你使用什么，例如Apache？NginX？还是Unicorn？ - Tilo

这是使用Mongrel（在Apache代理后面，但这不应该有影响），日志文件属于运行服务器的用户，我们不使用capistrano（我们只是手动部署）。 - Neil Brown

2.3已经有些过时了...您可能需要考虑升级到非常稳定的3.0版本，并使用Unicorn代替Mongrel（强烈推荐）。 - Tilo

Answer 1

症状似乎是，尽管您成功地旋转了日志，但仍然会继续使用一个旧的日志文件。 原因很可能是您的一个或多个Rails实例或线程仍在使用旧的文件句柄。 解决方案是确保在旋转日志后，所有Rails实例都完全重启，以便它们都使用新的文件句柄/名称。 使用logrotate而不是config.logger来旋转日志！

建议使用UNIX logrotate来旋转日志，而不是config.logger。 在我看来，这是更好的解决方案，更可靠，您可以更好地控制日志轮换，并且可以提供一些后轮换命令以重新启动Rails进程（通过logrotate的postrotate或endscript选项）。

参见： http://www.opencsw.org/packages/logrotate/（Solaris的logrotate软件包） 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有很多优势）

如果您正在使用Mongrel并且无法切换到Unicorn：

使用logrotate，并通过postrotate选项重新启动Mongrels。

希望这有所帮助..

- Tilo

---

我认为你的logrotate建议将有助于防止我们的磁盘空间被填满，我想这可能是我们必须要做的。我认为我们的日志之后会变得相当无用，因为日志将充满那些重复的请求，但拥有无用的日志总比磁盘空间不足（导致停机时间）要好。 - Neil Brown

你看到的“1000行请求块”重复，听起来像是Rails在刷新仍然打开的文件句柄上的缓冲区，可能是为了确保没有信息丢失 - 例如将其写入两个文件以确保 - 当使用logrotate时，您不应该看到这种行为。 - Tilo

Answer 2

我在处理Rails日志文件时通常使用平台的日志轮换机制。我遵循了http://www.nullislove.com/2007/09/10/rotating-rails-log-files/和http://overstimulate.com/articles/logrotate-rails-passenger中的建议，因为我也从Passenger运行。

第一种方法使用logrotate的copytruncate方法创建新的日志文件，因此仍然拥有它的进程将始终写入当前日志文件。

服务器上需要检查的其他事项包括：

• 确保没有gem或插件在ruby上下文中拥有Logger的句柄。
• 由于您正在使用JRuby，请确保没有卡住/失控的线程试图完成请求但被卡住记录日志。
• 就像使用Passenger一样，考虑定期重新启动Rails服务器进程。我知道这实际上是一个hack，但它可能有效。

- Dominik Grabiec

---

我认为你的第二个要点可能是重复记录的原因（尽管我们在日志中确实会得到一整个请求体的重复记录：就像我说的，1000行）。但我不确定该如何追踪此问题：在线程方面，在Ruby on Rails中并不容易明显，而且我也不太确定如何调试JRuby程序（特别是在生产服务器上--我从未能够在本地触发该问题）。 - Neil Brown

Answer 3

尼尔，

我不知道这是否适用于你的特定情况，但我遇到了类似的问题，我想我刚刚解决了它。在我的情况下，有两个症状。第一个是与你一样的问题 - 我的日志轮换出了问题……特别是，production.log.1文件被保持打开，并继续记录正在发生的事情，而production.log也在被记录。第二个症状是日志文件的所有权和组成员将不断更改为root。我的Rails应用程序是通过Capistrano部署的，使用“deployer”用户，因此每当应用程序尝试写入不再由deployer拥有的日志文件时，我会收到各种有趣的错误。

我感到尴尬的是，我花了多长时间才意识到两个问题的根源所在。在某个地方，我使用root更新了应用程序的crontab。这可能是当我在命令提示符下进行操作时……如果我只使用Capistrano的部署脚本，我就不会无意中这样做。无论如何，最终我找到了/var/spool/cron/crontabs中的两个副本，一个是deployer的，另一个是root的。因此，cron为我的应用程序启动的进程被复制了一份 - 一个在deployer下运行，另一个在root下运行。正是第二个进程搞砸了一切。删除root的crontab后，一切都好了。

一些注意事项：在我的设置中，root的crontab中没有与应用程序无关的任务，即它与deployer的crontab完全相同……因此，删除它对我来说没有任何副作用。此外，我的服务器正在运行Ubuntu……你的crontabs路径可能不同。

希望这有所帮助。

• 大卫

- David L. Bean

---

这正是可能存在的问题...但不幸的是，我已经检查过了，我没有这个特定的问题。但是，感谢您的建议！ - Neil Brown

Answer 4

我认为你忘记了“兆字节”的“s”，或者可以使用类似这样的东西

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

还有，请查看这个链接，它非常有帮助。

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

- Mahesh

---

不是，“100.megabyte” 是“100.megabytes”的别名（反之亦然）。 “100.megabyte #=> 104857600”。 - Mischa