Loggerを使用している場合にFakeFSを使ったらNotImplementedErrorが発生する

Intro

FakeFS

• https://github.com/defunkt/fakefs
• https://rubygems.org/gems/fakefs

tee_loggerというGemのテストをしていて、RSpecでFakeFS使ったらはまったのでメモしておく。

require 'logger'
require 'fakefs'

Logger.new('log.log') # => NotImplementedError: NotImplementedError

原因

NotImplementedError: NotImplementedError
{your_app_path}/vendor/bundle/ruby/2.2.0/gems/fakefs-0.6.7/lib/fakefs/file.rb:462:in `flock'

flockはFakeFSではエラーを返すように実装されている。
https://github.com/defunkt/fakefs/blob/master/lib/fakefs/file.rb#L461

    def flock(*)
      fail NotImplementedError
    end

なぜにLogger.newで怒られるのかというと、ログファイルを文字列で指定したため、Loggerの中でファイル作成、オープンした際にflockを実行しているため。

対応

とりあえず下記のようにして回避した。
file.sync = trueはファイルを閉じるかfile.flushとかしないとファイルに書き込まれないため。
Loggerの中でファイル操作した場合も@dev.sync = trueとかlogdev.sync = trueとかしてる。

require 'logger'
require 'fakefs'

file = File.open('log.log', 'w+')
file.sync  = true
logger = Logger.new(file)
logger.debug 'hello'

Loggerのソースを追ってみる

まずLogger.newで下記のinitializeが実行される。
https://github.com/ruby/ruby/blob/ruby_2_2/lib/logger.rb#L311

  def initialize(logdev, shift_age = 0, shift_size = 1048576)
    @progname = nil
    @level = DEBUG
    @default_formatter = Formatter.new
    @formatter = nil
    @logdev = nil
    if logdev
      @logdev = LogDevice.new(logdev, :shift_age => shift_age,
        :shift_size => shift_size)
    end
  end

で、LogDevice.newで下記のinitialize
https://github.com/ruby/ruby/blob/ruby_2_2/lib/logger.rb#L578

    def initialize(log = nil, opt = {})
      @dev = @filename = @shift_age = @shift_size = nil
      @mutex = LogDeviceMutex.new
      if log.respond_to?(:write) and log.respond_to?(:close)
        @dev = log
      else
        @dev = open_logfile(log)
        @dev.sync = true
        @filename = log
        @shift_age = opt[:shift_age] || 7
        @shift_size = opt[:shift_size] || 1048576
        @next_rotate_time = next_rotate_time(Time.now, @shift_age) unless @shift_age.is_a?(Integer)
      end
    end

logdevにファイル名の文字列を渡しているのでlogも文字列。
よってif log.respond_to?(:write) and log.respond_to?(:close)はfalseなのでopen_logfileが実行される。
https://github.com/ruby/ruby/blob/ruby_2_2/lib/logger.rb#L626

    def open_logfile(filename)
      begin
        open(filename, (File::WRONLY | File::APPEND))
      rescue Errno::ENOENT
        create_logfile(filename)
      end
    end

で、ファイルが存在しないのでrescueでcrate_logfileの実行になり
https://github.com/ruby/ruby/blob/ruby_2_2/lib/logger.rb#L626

    def create_logfile(filename)
      begin
        logdev = open(filename, (File::WRONLY | File::APPEND | File::CREAT | File::EXCL))
        logdev.flock(File::LOCK_EX)
        logdev.sync = true
        add_log_header(logdev)
        logdev.flock(File::LOCK_UN)
      rescue Errno::EEXIST
        # file is created by another process
        logdev = open_logfile(filename)
        logdev.sync = true
      end
      logdev
    end

で、flock。

未確認事項

https://github.com/ruby/ruby/blob/ruby_2_2/lib/logger.rb#L680
上記でもflockが見えるけど、そこまでは追いかけてません。