[ruby-talk:444306] Re: Alternative logging solutions

4 Aug 2023

      A super quick and very dirty test of concept:

test.rb has one thread that writes to logger and another thread that
renames the file and sends a HUP signal (representing logrotate).

$ rm /tmp/loggerhup* ; ruby test.rb /tmp/loggerhup & tail -F /tmp/loggerhup
[1] 44773
tail: cannot open '/tmp/loggerhup' for reading: No such file or directory
do
tail: '/tmp/loggerhup' has appeared;  following new file
# Logfile created on 2023-08-04 17:23:46 -0400 by logger.rb/v1.4.2
I, [2023-08-04T17:23:47.795742 #44773]  INFO -- : 1
I, [2023-08-04T17:23:47.952905 #44773]  INFO -- : 2
I, [2023-08-04T17:23:48.051453 #44773]  INFO -- : 3
I, [2023-08-04T17:23:48.274491 #44773]  INFO -- : 4
I, [2023-08-04T17:23:48.359070 #44773]  INFO -- : 5
D, [2023-08-04T17:23:48.797585 #44773] DEBUG -- : Received signal, reopening...
tail: '/tmp/loggerhup' has been replaced;  following new file
# Logfile created on 2023-08-04 17:23:52 -0400 by logger.rb/v1.4.2
I, [2023-08-04T17:23:52.951757 #44773]  INFO -- : 14
I, [2023-08-04T17:23:53.281451 #44773]  INFO -- : 15
I, [2023-08-04T17:23:53.457322 #44773]  INFO -- : 16
I, [2023-08-04T17:23:54.426525 #44773]  INFO -- : 17
D, [2023-08-04T17:23:54.799463 #44773] DEBUG -- : Received signal, reopening...
end
tail: '/tmp/loggerhup' has been replaced;  following new file
# Logfile created on 2023-08-04 17:23:56 -0400 by logger.rb/v1.4.2
I, [2023-08-04T17:23:57.443366 #44773]  INFO -- : 22
I, [2023-08-04T17:23:57.884349 #44773]  INFO -- : 23
I, [2023-08-04T17:23:58.713242 #44773]  INFO -- : 24
^C[1]+  Done                    ruby test.rb /tmp/loggerhup

After the run, no messages are missing:

$ grep . /tmp/loggerhup*
/tmp/loggerhup:# Logfile created on 2023-08-04 17:23:56 -0400 by
logger.rb/v1.4.2
/tmp/loggerhup:I, [2023-08-04T17:23:57.443366 #44773]  INFO -- : 22
/tmp/loggerhup:I, [2023-08-04T17:23:57.884349 #44773]  INFO -- : 23
/tmp/loggerhup:I, [2023-08-04T17:23:58.713242 #44773]  INFO -- : 24
/tmp/loggerhup-005:# Logfile created on 2023-08-04 17:23:46 -0400 by
logger.rb/v1.4.2
/tmp/loggerhup-005:I, [2023-08-04T17:23:47.795742 #44773]  INFO -- : 1
/tmp/loggerhup-005:I, [2023-08-04T17:23:47.952905 #44773]  INFO -- : 2
/tmp/loggerhup-005:I, [2023-08-04T17:23:48.051453 #44773]  INFO -- : 3
/tmp/loggerhup-005:I, [2023-08-04T17:23:48.274491 #44773]  INFO -- : 4
/tmp/loggerhup-005:I, [2023-08-04T17:23:48.359070 #44773]  INFO -- : 5
/tmp/loggerhup-005:D, [2023-08-04T17:23:48.797585 #44773] DEBUG -- :
Received signal, reopening...
/tmp/loggerhup-008:# Logfile created on 2023-08-04 17:23:48 -0400 by
logger.rb/v1.4.2
/tmp/loggerhup-008:I, [2023-08-04T17:23:49.313963 #44773]  INFO -- : 6
/tmp/loggerhup-008:I, [2023-08-04T17:23:50.008360 #44773]  INFO -- : 7
/tmp/loggerhup-008:I, [2023-08-04T17:23:50.131976 #44773]  INFO -- : 8
/tmp/loggerhup-008:D, [2023-08-04T17:23:50.798364 #44773] DEBUG -- :
Received signal, reopening...
/tmp/loggerhup-013:# Logfile created on 2023-08-04 17:23:50 -0400 by
logger.rb/v1.4.2
/tmp/loggerhup-013:I, [2023-08-04T17:23:50.988746 #44773]  INFO -- : 9
/tmp/loggerhup-013:I, [2023-08-04T17:23:51.255564 #44773]  INFO -- : 10
/tmp/loggerhup-013:I, [2023-08-04T17:23:52.133295 #44773]  INFO -- : 11
/tmp/loggerhup-013:I, [2023-08-04T17:23:52.193747 #44773]  INFO -- : 12
/tmp/loggerhup-013:I, [2023-08-04T17:23:52.499093 #44773]  INFO -- : 13
/tmp/loggerhup-013:D, [2023-08-04T17:23:52.798819 #44773] DEBUG -- :
Received signal, reopening...
/tmp/loggerhup-017:# Logfile created on 2023-08-04 17:23:52 -0400 by
logger.rb/v1.4.2
/tmp/loggerhup-017:I, [2023-08-04T17:23:52.951757 #44773]  INFO -- : 14
/tmp/loggerhup-017:I, [2023-08-04T17:23:53.281451 #44773]  INFO -- : 15
/tmp/loggerhup-017:I, [2023-08-04T17:23:53.457322 #44773]  INFO -- : 16
/tmp/loggerhup-017:I, [2023-08-04T17:23:54.426525 #44773]  INFO -- : 17
/tmp/loggerhup-017:D, [2023-08-04T17:23:54.799463 #44773] DEBUG -- :
Received signal, reopening...
/tmp/loggerhup-021:# Logfile created on 2023-08-04 17:23:54 -0400 by
logger.rb/v1.4.2
/tmp/loggerhup-021:I, [2023-08-04T17:23:55.304150 #44773]  INFO -- : 18
/tmp/loggerhup-021:I, [2023-08-04T17:23:56.029091 #44773]  INFO -- : 19
/tmp/loggerhup-021:I, [2023-08-04T17:23:56.160495 #44773]  INFO -- : 20
/tmp/loggerhup-021:I, [2023-08-04T17:23:56.719132 #44773]  INFO -- : 21
/tmp/loggerhup-021:D, [2023-08-04T17:23:56.800298 #44773] DEBUG -- :
Received signal, reopening...

$ cat test.rb
#!/usr/bin/env ruby
require 'logger'
require_relative 'loggerhup'
logger = Logger.new(ARGV[0])
logger.level = Logger::DEBUG
logger.reopen_on_signal
puts 'do'
counter = 0
sleep 1
Thread.new do loop do logger.info(counter+=1); sleep rand end end
sleep 1
Thread.new do loop do File.rename(ARGV[0], "%s-%03d" % [ARGV[0],
counter]) rescue nil; Process.kill('HUP', 0); sleep(2) end end
sleep 10
puts 'end'

$ cat loggerhup.rb
class Logger
  def reopen_on_signal(signal = 'HUP')
    if @_hupq or @_hupt
      warn 'Ignoring repeated call to #reopen_on_signal'
      return
    end

    @_hupq ||= Queue.new
    @_hupt ||= Thread.new do
      loop do
        @_hupq.pop
        debug 'Received signal, reopening...'
        reopen
      end
    end

    Signal.trap(signal) do
      @_hupq.push(nil)
    end
  end
end

Can't call Logger#reopen directly from the signal handler since it uses
a Mutex, hence the Queue hack:

https://bugs.ruby-lang.org/issues/14222#note-3

[ruby-talk:444306] Re: Alternative logging solutions

Frank J. Cameron