Skip to content

Inter-process locking for log rotation #428

Closed
wants to merge 4 commits into from

4 participants

@sonots
sonots commented Oct 23, 2013

This pull request is actually addressing the same issue with #354.

Current ruby's standard logger errors when we use it with log shifting in multi-process environments. Following is a code snippet to re-produce this problem.

require 'logger'
require 'parallel'

logger = Logger.new("/tmp/test.log", 3, 1024 * 10)
Parallel.map(['a', 'b'], :in_processes => 2) do |letter|
  300000.times do
    logger.info letter * 5000
  end
end

By executing this, logger errors like

log writing failed. closed stream
log shifting failed. closed stream
log writing failed. closed stream
log shifting failed. closed stream
...

Please read my blog post (Japanese) which I wrote before for more details.

This patch is to fix the issue using inter-process locking (flock).

FYI: This patch is a port from ServerEngine's DaemonLogger which we worked for Fluentd. Please see https://github.com/frsyuki/serverengine/issues/9 about discussions on it.

I also issued on bug the tracker https://bugs.ruby-lang.org/issues/9046

@sonots sonots lib/logger.rb: Inter-process locking for log rotation
* lib/logger.rb: Inter-process locking for log rotation
* test/logger/test_logger.rb: ditto.
7e3d8c2
@nurse nurse commented on an outdated diff Oct 23, 2013
lib/logger.rb
end
end
end
+ def lock_shift_log
+ begin
+ retry_limit = 8
+ retry_sleep = 0.1
+ begin
+ lock = File.open(@filename, File::WRONLY | File::APPEND)
@nurse
Ruby Programming Language member
nurse added a note Oct 23, 2013

Why don't you use block?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@nurse nurse commented on an outdated diff Oct 23, 2013
lib/logger.rb
+ lock.flock(File::LOCK_EX)
+ ino = lock.stat.ino
+ if ino == File.stat(@filename).ino
+ yield # log shifting
+ else
+ @dev.close rescue nil
+ @dev = File.open(@filename, File::WRONLY | File::APPEND)
+ @dev.sync = true
+ end
+ ensure
+ lock.flock(File::LOCK_UN)
+ lock.close
+ end
+ rescue Errno::ENOENT => e
+ # @filename file would not exist right after #rename and before #create_logfile
+ raise e if retry_limit <= 0
@nurse
Ruby Programming Language member
nurse added a note Oct 23, 2013

Why re-raise here?
You can simply write

  if retry_limit <= 0
    warn("log rotation inter-process lock failed. #{$!}")
  else
    sleep retry_sleep
    retry_limit -= 1
    retry_sleep *= 2
    retry
  end
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@nurse nurse commented on an outdated diff Oct 23, 2013
lib/logger.rb
+ retry_sleep = 0.1
+ begin
+ lock = File.open(@filename, File::WRONLY | File::APPEND)
+ begin
+ # inter-process locking
+ lock.flock(File::LOCK_EX)
+ ino = lock.stat.ino
+ if ino == File.stat(@filename).ino
+ yield # log shifting
+ else
+ @dev.close rescue nil
+ @dev = File.open(@filename, File::WRONLY | File::APPEND)
+ @dev.sync = true
+ end
+ ensure
+ lock.flock(File::LOCK_UN)
@nurse
Ruby Programming Language member
nurse added a note Oct 23, 2013

this line can be removed because close() unlocks it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@nurse nurse and 1 other commented on an outdated diff Oct 23, 2013
lib/logger.rb
end
end
end
+ def lock_shift_log
+ begin
+ retry_limit = 8
+ retry_sleep = 0.1
+ begin
+ lock = File.open(@filename, File::WRONLY | File::APPEND)
+ begin
+ # inter-process locking
+ lock.flock(File::LOCK_EX)
+ ino = lock.stat.ino
+ if ino == File.stat(@filename).ino
+ yield # log shifting
+ else
+ @dev.close rescue nil
+ @dev = File.open(@filename, File::WRONLY | File::APPEND)
@nurse
Ruby Programming Language member
nurse added a note Oct 23, 2013

Why don't you use create_logfile?

@sonots
sonots added a note Oct 23, 2013

Codes inside else block is executed when another process shifted log files.
So, the new file should already exist. Thus, I felt that I don't need to create a file by calling create_logfile here.

@sonots
sonots added a note Oct 24, 2013

Finally, I used multiprocess-safe versioned open_logfile at here.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@nurse
Ruby Programming Language member
nurse commented Oct 23, 2013

Additionally lib/logger.rb is not multi-process safe at least on open_logfile and create_logfile.

@sonots
sonots commented Oct 23, 2013

@nurse For open_logfile, I came up with only two ways to make it be multi-process safe.

1) Create a file named "#{filename}.lock" to exclusively lock open_logfile. Code looks as below:

def open_logfile(filename)
  open("#{filename}.lock", (File::WRONLY | File::APPEND | File::CREAT)) do |lock|
    lock.flock(File::LOCK_EX)
    if (FileTest.exist?(filename))
      logdev = open(filename, (File::WRONLY | File::APPEND))
    else
      create_logfile(filename)
    end
  end
end

In this case, we have to change the lock filename used for log shifting to #{@filename}.lock too. The bad point of this approach is that the lock file must always exist so that all processes lock the same i-node.

2) Stop add_log_header

If we can remove add_log_header from create_logfile method like,

def create_logfile(filename)
  logdev = open(filename, (File::WRONLY | File::APPEND | File::CREAT))
  logdev.sync = true
-  add_log_header(logdev)
  logdev
end

then I think create_logfile can be a multi-process safe. FYI: ServerEngine::DaemonLogger is taking this approach ... Any thoughts or idea?

@frsyuki
frsyuki commented Oct 23, 2013

@sonots @nurse the reason why it always use open with 'a' mode (File::WRONLY | File::APPEND | File::CREAT) is that create_logfile or open_logfile are not multi-process safe. The behavior is different from existent code because it doesn't call add_log_header. I think it's possible to make add_log_header multi-process safe but it needs more code.

@nurse
Ruby Programming Language member
nurse commented Oct 23, 2013

For this case, specify O_EXCL with O_CREAT.

begin
  lock = open(filename, File::WRONLY | File::APPEND)
  # file is exist
  lock.flock(File::LOCK_EX)
  return lock
rescue Errno::ENOENT
  # file is not exist at that time
  begin
    lock = open(filename, File::WRONLY | File::APPEND | File::CREAT | File::EXCL)
    lock.flock(File::LOCK_EX)
    return lock
  rescue Errno::EEXIST
    # ignore and retry to open the file which is created by another process
  end
  retry
end

// FreeBSD has O_EXLOCK but linux doesn't have it

And add_log_header will be like

    def add_log_header(file)
      file.write(
        "# Logfile created on %s by %s\n" % [Time.now.to_s, Logger::ProgName]
      ) if file.size == 0
    end
@sonots
sonots commented Oct 24, 2013

@nurse I've updated. Could you check sonots@21b038c? Thanks!

@sonots
sonots commented Oct 29, 2013

@nurse ping!

@hsbt
Ruby Programming Language member
hsbt commented Nov 1, 2013

@nurse Can I merge this?

@nurse nurse added a commit that referenced this pull request Nov 1, 2013
@nurse nurse * lib/logger.rb: Inter-process locking for log rotation
  Current implementation fails log rotation on multi process env.
  by sonots <sonots@gmail.com>
  #428 fix GH-428 [Bug #9046]

git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@43511 b2dd03c8-39d4-4d8f-98ff-823fe69b080e
0749adc
@nurse nurse added a commit that closed this pull request Nov 1, 2013
@nurse nurse * lib/logger.rb: Inter-process locking for log rotation
  Current implementation fails log rotation on multi process env.
  by sonots <sonots@gmail.com>
  #428 fix GH-428 [Bug #9046]

git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@43511 b2dd03c8-39d4-4d8f-98ff-823fe69b080e
0749adc
@nurse nurse closed this in 0749adc Nov 1, 2013
@sonots sonots deleted the sonots:process_safe_logger branch Nov 1, 2013
@mmasaki mmasaki pushed a commit to mmasaki/ruby that referenced this pull request Nov 3, 2013
@nurse nurse * lib/logger.rb: Inter-process locking for log rotation
  Current implementation fails log rotation on multi process env.
  by sonots <sonots@gmail.com>
  ruby#428 fix GH-428 [Bug #9046]

git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@43511 b2dd03c8-39d4-4d8f-98ff-823fe69b080e
2cc02cd
@vbatts vbatts added a commit to vbatts/ruby that referenced this pull request Nov 4, 2013
@nurse nurse * lib/logger.rb: Inter-process locking for log rotation
  Current implementation fails log rotation on multi process env.
  by sonots <sonots@gmail.com>
  ruby#428 fix GH-428 [Bug #9046]

git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@43511 b2dd03c8-39d4-4d8f-98ff-823fe69b080e
d4ae7c6
@tenderlove tenderlove pushed a commit to tenderlove/ruby that referenced this pull request Jan 24, 2014
@nurse nurse * lib/logger.rb: Inter-process locking for log rotation
  Current implementation fails log rotation on multi process env.
  by sonots <sonots@gmail.com>
  ruby#428 fix GH-428 [Bug #9046]

git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@43511 b2dd03c8-39d4-4d8f-98ff-823fe69b080e
9fcb73a
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.