Detect log rotation and release renamed files

[kenhys]

In the previous vesions, there was no way to detect log rotation
event when log file was rotated.

It causes that rotated log file was grabbed by DaemonLogger.
This was unexpected behavior.

This commit fixes by reopening log file correctly.

NOTE: This PR depends on inotify so only linux was supported.

[kenhys]

A bit more work is needed to fix fluent/fluentd#2426 (comment) completely.

[repeatedly]

serverengine has own log rotation mechanizm and it doesn't have this problem, right?
If this problem happens with only external log rotation tool, how about rb-inofity is optional?

[kenhys]

I've changed dependency to optional.

[repeatedly]

Looks good to me with optional approach :)

[kenhys]

I've rebased PR to follow recent master.

[ashie]

I've added CI for with and w/o rb-notify.
All checks are passed.

[ashie]

I've added CI for with and w/o rb-notify.
All checks are passed.

No, still rb-inotify isn't recognized:

Pending:
  ServerEngine::DaemonLogger reopen log when path is renamed
    # not supported except Linux with inotify
    # ./spec/daemon_logger_spec.rb:182
  ServerEngine::DaemonLogger reopen log when path is renamed by external process
    # not supported except Linux with inotify
    # ./spec/daemon_logger_spec.rb:192
  ServerEngine::DaemonLogger reopen logger when file is renamed
    # not supported except Linux with inotify
    # ./spec/daemon_logger_spec.rb:205
  ServerEngine::MultiThreadServer raises SystemExit when all workers exit with specified code by unrecoverable_exit_codes
    # unrecoverable_exit_codes supported only for multi process workers
    # ./spec/multi_process_server_spec.rb:63

[ashie]

Hmm, when I test it on my local environment, sometimes a test stalls.

It seems that it reproduced also on GitHub Actions:
https://github.com/treasure-data/serverengine/pull/106/checks?check_run_id=2652587049

@kenhys Could you take look this?

[kenhys]

In my local environment, IO logger test case seems to stall.
(Not identified the reason yet)

% bundle exec rspec -f documentation 2>&1 | tee ../take12.log

ServerEngine::BlockingFlag
  set and reset
  set! and reset! return whether it toggled the state
  wait_for_set timeout
  wait_for_reset timeout
  wait

ServerEngine::DaemonLogger
  reopen
  reset path
  default level is debug
  level set by int
  level set by string
  unknown level
  rotation
  IO logger

[kenhys]

It may be caused by log.reopen!.

it 'IO logger' do
    io = StringIO.new
    io.should_receive(:write)
    io.should_not_receive(:reopen)

    log = DaemonLogger.new(io)
    log.debug "stdout logging test"
    log.reopen! # <= STALLED HERE
  end

[kenhys]

I've misunderstand rspec workflow.

executing do block, call after (if exists), then show it ... label.
So, 'inter-process locking on rotation' test case is stalling. (next test case for 'IO logger')

[kenhys]

It seems that sometimes Process.waitpid pid2 blocks.

https://github.com/treasure-data/serverengine/blob/master/spec/daemon_logger_spec.rb#L168

[kenhys]

As far as I know, only 'inter-process locking on rotation' test case stalls. (frequency 2-3 stalls/10times)

[kenhys]

As far as I know, only 'inter-process locking on rotation' test case stalls. (frequency 2-3 stalls/10times)

It tend to stall when process(pid2) writes the limit (~30 bytes = log_rotate_age * log_rotate_size), proces(pid2) stucks.

[kenhys]

To clarify the issue:

• master (not stall)
• PR with rb-inotify (sometimes stalls with 'inter-process locking on rotation' test case)
• PR without rb-inotify (not stall)

bundle install --with inotify
bundle exec rspec -f documentation -e inter

[kenhys]

It tend to:

pass:

• @inotify.watch event is fired for process A and Process B (each process close @logdev and reopen it)

stall:

• @inotify.watch event is fired for process A only

[kenhys]

It tend to:

pass:

* `@inotify.watch` event is fired for process A and Process B (each process close @logdev and reopen it)

stall:

* `@inotify.watch` event is fired for process A only

some extent true, but not applied to all cases...

[kenhys]

I'll check the current implementation, again.

[ashie]

I've added a work around, but I'm not sure it's correct fix.
Further verification is needed.

[ashie]

I open another pull request to resolve this issue: #127