https://bugs.ruby-lang.org/
https://bugs.ruby-lang.org/favicon.ico?1711330511
2013-11-25T09:23:15Z
Ruby Issue Tracking System
Ruby master - Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133?journal_id=43135
2013-11-25T09:23:15Z
no6v (Nobuhiro IMAI)
nov@yo.rim.or.jp
<ul></ul><p>After that, the @logdev.dev of process A is "log.0", so <a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: logger rotates log files more than expected (Closed)" href="https://bugs.ruby-lang.org/issues/9133">#9133</a> happens.<br>
I wrote a test for this issue, also fixes <a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: logger rotates log files more than expected (Closed)" href="https://bugs.ruby-lang.org/issues/9133">#9133</a>.</p>
<p>diff --git a/lib/logger.rb b/lib/logger.rb<br>
index c70b091..071594d 100644<br>
--- a/lib/logger.rb<br>
+++ b/lib/logger.rb<br>
@@ -645,7 +645,7 @@ private<br>
File.open(@filename, File::WRONLY | File::APPEND) do |lock|<br>
lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file<br>
ino = lock.stat.ino</p>
<ul>
<li>
<pre><code> if ino == File.stat(@filename).ino
</code></pre>
</li>
</ul>
<ul>
<li>
<pre><code> if ino == File.stat(@filename).ino and ino == @dev.stat.ino
yield # log shifting
else
# log shifted by another process (i-node before locking and i-node after locking are different)
</code></pre>
</li>
</ul>
<p>diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb<br>
index 04bf779..75da962 100644<br>
--- a/test/logger/test_logger.rb<br>
+++ b/test/logger/test_logger.rb<br>
@@ -2,6 +2,7 @@<br>
require 'test/unit'<br>
require 'logger'<br>
require 'tempfile'<br>
+require 'tmpdir'<br>
require_relative '../ruby/envutil'</p>
<p>@@ -542,6 +543,46 @@ class TestLogDevice < Test::Unit::TestCase<br>
end<br>
end</p>
<ul>
<li>
<p>def test_shifting_size_not_rotate_too_much</p>
</li>
<li>
<p>d(@filename).<strong>send</strong>(:add_log_header, @tempfile)</p>
</li>
<li>
<p>header_size = @tempfile.size</p>
</li>
<li>
<p>message = "*" * 99 + "\n"</p>
</li>
<li>
<p>shift_size = header_size + message.size * 3 - 1</p>
</li>
<li>
<p>opt = {shift_age: 1, shift_size: shift_size}</p>
</li>
<li>
<li>
<p>Dir.mktmpdir do |tmpdir|</p>
</li>
<li>
<pre><code> begin
</code></pre>
</li>
<li>
<pre><code> log = File.join(tmpdir, "log")
</code></pre>
</li>
<li>
<pre><code> logdev1 = d(log, opt)
</code></pre>
</li>
<li>
<pre><code> logdev2 = d(log, opt)
</code></pre>
</li>
<li>
<li>
<pre><code> ino = File.stat(log).ino
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev1.dev.stat.ino)
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev2.dev.stat.ino)
</code></pre>
</li>
<li>
<li>
<pre><code> 3.times{logdev1.write(message)}
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev1.dev.stat.ino)
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev2.dev.stat.ino)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev1.write(message)
</code></pre>
</li>
<li>
<pre><code> assert_equal(File.stat(log).ino, logdev1.dev.stat.ino)
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev2.dev.stat.ino)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev2.write(message)
</code></pre>
</li>
<li>
<pre><code> ino = File.stat(log).ino
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev1.dev.stat.ino)
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev2.dev.stat.ino)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev1.write(message)
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev1.dev.stat.ino)
</code></pre>
</li>
<li>
<pre><code> assert_equal(ino, logdev2.dev.stat.ino)
</code></pre>
</li>
<li>
<pre><code> ensure
</code></pre>
</li>
<li>
<pre><code> logdev1.close if logdev1
</code></pre>
</li>
<li>
<pre><code> logdev2.close if logdev2
</code></pre>
</li>
<li>
<pre><code> end
</code></pre>
</li>
<li>
<p>end</p>
</li>
<li>
<p>end</p>
</li>
<li>
<p>private</p>
<p>def run_children(n, args, src)</p>
</li>
</ul>
Ruby master - Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133?journal_id=43136
2013-11-25T09:24:30Z
no6v (Nobuhiro IMAI)
nov@yo.rim.or.jp
<ul></ul><p>no6v (Nobuhiro IMAI) wrote:</p>
<blockquote>
<p>After that, the @logdev.dev of process A is "log.0", so <a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: logger rotates log files more than expected (Closed)" href="https://bugs.ruby-lang.org/issues/9133">#9133</a> happens.<br>
I wrote a test for this issue, also fixes <a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: logger rotates log files more than expected (Closed)" href="https://bugs.ruby-lang.org/issues/9133">#9133</a>.</p>
</blockquote>
<p>Both 9133 above are <a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: logger continues to write in old log file after rotation (Closed)" href="https://bugs.ruby-lang.org/issues/9130">#9130</a>, sorry.</p>
Ruby master - Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133?journal_id=43149
2013-11-26T12:05:31Z
nobu (Nobuyoshi Nakada)
nobu@ruby-lang.org
<ul></ul><p>Probably, you can use <code>File.identical?</code> instead of comparison of ino.</p>
Ruby master - Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133?journal_id=43171
2013-11-26T19:23:03Z
no6v (Nobuhiro IMAI)
nov@yo.rim.or.jp
<ul></ul><p>Thanks for your suggestion. I feel this simple condition seems looking good.<br>
I updated a patch using <code>File.identical?</code>.</p>
<p>diff --git a/lib/logger.rb b/lib/logger.rb<br>
index c70b091..f1c6cbe 100644<br>
--- a/lib/logger.rb<br>
+++ b/lib/logger.rb<br>
@@ -644,8 +644,7 @@ def lock_shift_log<br>
begin<br>
File.open(@filename, File::WRONLY | File::APPEND) do |lock|<br>
lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file</p>
<ul>
<li>
<pre><code> ino = lock.stat.ino
</code></pre>
</li>
<li>
<pre><code> if ino == File.stat(@filename).ino
</code></pre>
</li>
</ul>
<ul>
<li>
<pre><code> if File.identical?(lock, @dev)
yield # log shifting
else
# log shifted by another process (i-node before locking and i-node after locking are different)
</code></pre>
</li>
</ul>
<p>diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb<br>
index 04bf779..04fa4cd 100644<br>
--- a/test/logger/test_logger.rb<br>
+++ b/test/logger/test_logger.rb<br>
@@ -2,6 +2,7 @@<br>
require 'test/unit'<br>
require 'logger'<br>
require 'tempfile'<br>
+require 'tmpdir'<br>
require_relative '../ruby/envutil'</p>
<p>@@ -542,6 +543,44 @@ def test_open_logfile_in_multiprocess<br>
end<br>
end</p>
<ul>
<li>
<p>def test_shifting_size_not_rotate_too_much</p>
</li>
<li>
<p>d(@filename).<strong>send</strong>(:add_log_header, @tempfile)</p>
</li>
<li>
<p>header_size = @tempfile.size</p>
</li>
<li>
<p>message = "*" * 99 + "\n"</p>
</li>
<li>
<p>shift_size = header_size + message.size * 3 - 1</p>
</li>
<li>
<p>opt = {shift_age: 1, shift_size: shift_size}</p>
</li>
<li>
<li>
<p>Dir.mktmpdir do |tmpdir|</p>
</li>
<li>
<pre><code> begin
</code></pre>
</li>
<li>
<pre><code> log = File.join(tmpdir, "log")
</code></pre>
</li>
<li>
<pre><code> logdev1 = d(log, opt)
</code></pre>
</li>
<li>
<pre><code> logdev2 = d(log, opt)
</code></pre>
</li>
<li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev2.dev)
</code></pre>
</li>
<li>
<li>
<pre><code> 3.times{logdev1.write(message)}
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev2.dev)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev1.write(message)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log + ".0", logdev2.dev)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev2.write(message)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev2.dev)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev1.write(message)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev2.dev)
</code></pre>
</li>
<li>
<pre><code> ensure
</code></pre>
</li>
<li>
<pre><code> logdev1.close if logdev1
</code></pre>
</li>
<li>
<pre><code> logdev2.close if logdev2
</code></pre>
</li>
<li>
<pre><code> end
</code></pre>
</li>
<li>
<p>end</p>
</li>
<li>
<p>end</p>
</li>
<li>
<p>private</p>
<p>def run_children(n, args, src)</p>
</li>
</ul>
Ruby master - Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133?journal_id=43174
2013-11-26T22:23:19Z
nobu (Nobuyoshi Nakada)
nobu@ruby-lang.org
<ul></ul><p>(13/11/26 19:23), no6v (Nobuhiro IMAI) wrote:</p>
<blockquote>
<pre><code> File.open(@filename, File::WRONLY | File::APPEND) do |lock|
lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file
</code></pre>
<ul>
<li>
<pre><code> ino = lock.stat.ino
</code></pre>
</li>
<li>
<pre><code> if ino == File.stat(@filename).ino
</code></pre>
</li>
</ul>
<ul>
<li>
<pre><code> if File.identical?(lock, @dev)
</code></pre>
</li>
</ul>
</blockquote>
<p>No needs to compare with @filename?</p>
Ruby master - Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133?journal_id=43189
2013-11-27T12:09:28Z
no6v (Nobuhiro IMAI)
nov@yo.rim.or.jp
<ul></ul><blockquote>
<p>No needs to compare with @filename?</p>
</blockquote>
<pre><code>645 File.open(@filename, File::WRONLY | File::APPEND) do |lock|
646 lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file
647 if File.identical?(lock, @dev)
</code></pre>
<p>Nice catch. The race condition is just between L645 and L646.<br>
I had to respect the logic of the original code.<br>
I updated a patch again. Thanks.</p>
<p>diff --git a/lib/logger.rb b/lib/logger.rb<br>
index c70b091..3c50cb2 100644<br>
--- a/lib/logger.rb<br>
+++ b/lib/logger.rb<br>
@@ -644,8 +644,7 @@ def lock_shift_log<br>
begin<br>
File.open(@filename, File::WRONLY | File::APPEND) do |lock|<br>
lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file</p>
<ul>
<li>
<pre><code> ino = lock.stat.ino
</code></pre>
</li>
<li>
<pre><code> if ino == File.stat(@filename).ino
</code></pre>
</li>
</ul>
<ul>
<li>
<pre><code> if File.identical?(@filename, lock) and File.identical?(lock, @dev)
yield # log shifting
else
# log shifted by another process (i-node before locking and i-node after locking are different)
</code></pre>
</li>
</ul>
<p>diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb<br>
index 04bf779..04fa4cd 100644<br>
--- a/test/logger/test_logger.rb<br>
+++ b/test/logger/test_logger.rb<br>
@@ -2,6 +2,7 @@<br>
require 'test/unit'<br>
require 'logger'<br>
require 'tempfile'<br>
+require 'tmpdir'<br>
require_relative '../ruby/envutil'</p>
<p>@@ -542,6 +543,44 @@ def test_open_logfile_in_multiprocess<br>
end<br>
end</p>
<ul>
<li>
<p>def test_shifting_size_not_rotate_too_much</p>
</li>
<li>
<p>d(@filename).<strong>send</strong>(:add_log_header, @tempfile)</p>
</li>
<li>
<p>header_size = @tempfile.size</p>
</li>
<li>
<p>message = "*" * 99 + "\n"</p>
</li>
<li>
<p>shift_size = header_size + message.size * 3 - 1</p>
</li>
<li>
<p>opt = {shift_age: 1, shift_size: shift_size}</p>
</li>
<li>
<li>
<p>Dir.mktmpdir do |tmpdir|</p>
</li>
<li>
<pre><code> begin
</code></pre>
</li>
<li>
<pre><code> log = File.join(tmpdir, "log")
</code></pre>
</li>
<li>
<pre><code> logdev1 = d(log, opt)
</code></pre>
</li>
<li>
<pre><code> logdev2 = d(log, opt)
</code></pre>
</li>
<li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev2.dev)
</code></pre>
</li>
<li>
<li>
<pre><code> 3.times{logdev1.write(message)}
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev2.dev)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev1.write(message)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log + ".0", logdev2.dev)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev2.write(message)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev2.dev)
</code></pre>
</li>
<li>
<li>
<pre><code> logdev1.write(message)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev1.dev)
</code></pre>
</li>
<li>
<pre><code> assert File.identical?(log, logdev2.dev)
</code></pre>
</li>
<li>
<pre><code> ensure
</code></pre>
</li>
<li>
<pre><code> logdev1.close if logdev1
</code></pre>
</li>
<li>
<pre><code> logdev2.close if logdev2
</code></pre>
</li>
<li>
<pre><code> end
</code></pre>
</li>
<li>
<p>end</p>
</li>
<li>
<p>end</p>
</li>
<li>
<p>private</p>
<p>def run_children(n, args, src)</p>
</li>
</ul>
Ruby master - Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133?journal_id=43518
2013-12-08T20:17:21Z
hsbt (Hiroshi SHIBATA)
hsbt@ruby-lang.org
<ul><li><strong>Assignee</strong> set to <i>nobu (Nobuyoshi Nakada)</i></li></ul><p>Can you commit this?</p>
Ruby master - Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133?journal_id=43666
2013-12-14T14:43:05Z
nobu (Nobuyoshi Nakada)
nobu@ruby-lang.org
<ul><li><strong>Status</strong> changed from <i>Open</i> to <i>Closed</i></li><li><strong>% Done</strong> changed from <i>0</i> to <i>100</i></li></ul><p>This issue was solved with changeset r44203.<br>
Nobuhiro, thank you for reporting this issue.<br>
Your contribution to Ruby is greatly appreciated.<br>
May Ruby be with you.</p>
<hr>
<p>logger.rb: fix extra log ratation</p>
<ul>
<li>lib/logger.rb (lock_shift_log): no need to rotate the log file<br>
if it has been rotated by another process. based on the patch<br>
by no6v (Nobuhiro IMAI) in <a href="/issues/9133">[ruby-core:58620]</a>. [Bug <a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: logger rotates log files more than expected (Closed)" href="https://bugs.ruby-lang.org/issues/9133">#9133</a>]</li>
</ul>