Bugs: Browse | Submit New | Admin

[#19709] Log rotation fails in Windows

Date:
2008-04-22 12:43
Priority:
3
Submitted By:
Edvard Majakari (edvardm)
Assigned To:
Shyouhei Urabe (shyouhei)
Category:
Misc / Other Standard Library
State:
Open
Platform:
 
Summary:
Log rotation fails in Windows

Detailed description
In a large Rails project which produces huge log files, we realized that 
the log rotation fails often, resulting in infamous internal server error 500.

We tracked the problem to Ruby logging library, and more specifically 
class Logger::LogDevice#shift_log_age. 

The reason for the bug /seems/ to be the fact that sometimes Windows considers a
file to be in use, even though it has been just released by some process. Eg. open a rather large file in notepad, close
notepad, and try to delete the file and it could fail even though the notepad process no longer exists; after waiting
for a few seconds the file can be deleted.

The fix that appears to work for us was to redefine shift_log_age as follows:

  def shift_log_age
    (@shift_age-3).downto(0) do |i|
      if FileTest.exist?("#{@filename}.#{i}")
        File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
      end
    end
    @dev.close
    attempts = 10
    rename_success = false
    while attempts > 0
      begin
        attempts -= 1
        File.rename("#{@filename}", "#{@filename}.0")
        rename_success = true
        break
      rescue Exception => e # rename failed        
        sleep 1.0
      end
    end
    raise "Renaming #@filename failed!" unless rename_success
    @dev = create_logfile(@filename)
    return true
  end

of course, the solution above is not very clean and should be probably improved
before applying it to logger.rb. 

Add A Comment: Notepad

Please login


Followup

Message
Date: 2012-11-07 14:13
Sender: Herman Munster

I have the same Problem with Ruby 1.9.3 and Windows 7.

The cause is that the log file is open and shall be renamed.
This gives an error "log shifting failed. Permission
denied".

It will work, if the log file is copied to the age_file and then
the logfile is cleaned by using logdev.truncate(0).

My changes to logger.rb are (remove 3 lines, add 2 lines):

    def shift_log_period(period_end)
      postfix = period_end.strftime("%Y%m%d")
# YYYYMMDD
      age_file = "#{@filename}.#{postfix}"
      if FileTest.exist?(age_file)
        # try to avoid filename crash caused by Timestamp
change.
        idx = 0
        # .99 can be overridden; avoid too much file search with
'loop do'
        while idx < 100
          idx += 1
          age_file = "#{@filename}.#{postfix}.#{idx}"
          break unless FileTest.exist?(age_file)
        end
      end
-     @dev.close rescue nil
-     File.rename("#{@filename}", age_file)
-     @dev = create_logfile(@filename)
+     FileUtils.cp(@filename, age_file)
+     reset_logfile(@dev)
      return true

Added a new method to clean the open logfile and add a log
header:
    def reset_logfile(logdev)
      logdev.truncate( 0 )
      logdev.sync = true
      add_log_header(logdev)
    end

The change above (copy/clean instead of rename) should also be
made in the method "shift_log_age", same problem here.

I don't know how to bring this code into standard ruby sources.
Please somebody change the code, so the bug will be fixed.
Date: 2008-11-07 22:46
Sender: Roger Pack

ref: http://redmine.ruby-lang.org/issues/show/713

If this is still a concern then could you submit a new copy to
the new tracker:
http://redmine.ruby-lang.org/
--this tracker is being shelved.
Thanks!
-=R
Date: 2008-04-24 10:53
Sender: Usaku Nakamura

Thank you for your report.
It seems that Windows fxxking spec, and ruby core cannot resolv
this.
Maybe some workarounds like suggested one by Edvard
is necessary.

Urabe-san, who is the most suitable person to assign this bug?
Date: 2008-04-23 07:16
Sender: Edvard Majakari

Oh, and a Windows file indexer was enabled in the specified
drive.
Date: 2008-04-23 07:15
Sender: Edvard Majakari

UPDATE: The exception is 

#<Errno::EACCES: Permission denied -
./script/<snip>/log/development.log or
./script/<snip>/log/development.log.0>

Besides, the solution presented above DOES NOT work unless
line 'raise "Renaming...' is commented out. That way we
lose
a few log messages, but it is much better than crashing the
system.
Date: 2008-04-22 17:41
Sender: Usaku Nakamura

Please tell us the type of exception (maybe Errno::EACCES?).
And, if you use a virus scanner or a file indexer (such as Google
Desktop), please tell us the information, too.

Attached Files:

Name Description Download
No Files Currently Attached

Changes:

Field Old Value Date By
assigned_tousa2008-04-24 10:53usa
assigned_toshyouhei2008-04-22 17:01shyouhei