Add << method to MulticastLogger

[djberg96]

At the moment, nothing is being logged in the $azure_log. Under the hood, the azure-armrest gem is using the rest-client library (at least for now). The rest-client library relies on << internally for backwards compatibility. Since this isn't defined in the MulticastLogger, nothing is getting logged.

Addresses https://bugzilla.redhat.com/show_bug.cgi?id=1539677

rest-client/rest-client#34 for more information.

To test, add an Azure provider and inspect the azure.log file during/after a refresh.

[bdunne]

@djberg96 Should #<< call #info on itself instead (maybe with a chomp on the message)? With a file-based logger, you'll just get the message written to the file. But in the container world, the output will not be parsable by the EFK stack since it will be in string format.

Also, the return value of this #<< method is different. It normally returns the length of the message, but here it returns a Set.

With CONTAINER=true rails c

Loading development environment (Rails 5.0.6)
irb(main):001:0> $log.info("abc")
{"@timestamp":"2018-01-29T12:11:29.736722 ","hostname":"bdunne-t460p","pid":29863,"tid":"9af114","level":"info","message":"abc"}
=> true
irb(main):002:0> $log << "abc"
abc=> #<Set: {#<VMDBLogger:0x00000005bbfaa8 @progname=nil, @level=1, @default_formatter=#<Logger::Formatter:0x00000005bbfa30 @datetime_format=nil>, @formatter=#<VMDBLogger::Formatter:0x00000005bbf918 @datetime_format=nil>, @logdev=#<Logger::LogDevice:0x00000005bbf9e0 @shift_size=1048576, @shift_age=0, @filename=#<Pathname:/home/bdunne/projects/redhat/manageiq/log/evm.log>, @dev=#<File:/home/bdunne/projects/redhat/manageiq/log/evm.log>, @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x00000005bbf9b8>>, @write_lock=#<Thread::Mutex:0x00000005bbf8f0>, @local_levels={}, @thread_hash_level_key=:"ThreadSafeLogger#48102740@level">, #<Vmdb::Loggers::ContainerLogger:0x000000044d0ab8 @progname=nil, @level=0, @default_formatter=#<Logger::Formatter:0x000000044d07e8 @datetime_format=nil>, @formatter=#<Vmdb::Loggers::ContainerLogger::Formatter:0x000000044d0630 @datetime_format=nil, @hostname="bdunne-t460p">, @logdev=#<Logger::LogDevice:0x000000044d0798 @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x000000044d0748>>, @write_lock=#<Thread::Mutex:0x000000044d06a8>, @local_levels={}, @thread_hash_level_key=:"ThreadSafeLogger#36078940@level">}>
irb(main):003:0> $log.loggers.first << "abc"
=> 3

[NickLaMuro]

Code changes work as expected. I pulled down this branch and tested with and without the method changes.

[NickLaMuro]

I don't know if I agree with rubocop in this particular use case... just saying.

[NickLaMuro]

I know this has been the standard with these tests, but can we possibly just test that the message was written to the file, and not that we expect it to receive a message:

# should probably just make the `StringIO`'s their own `let()` if you decide to do this,
# but putting this all in one place for now for simplicity
it "forwards to the other loggers" do
  logfile1 = logger1.instance_variable_get(:@logdev).dev
  logfile2 = logger2.instance_variable_get(:@logdev).dev
  subject << "test #<< message"

  expect(logfile1.tap(:&rewind).read.lines.last).to eq("test #<< message")
  expect(logfile2.tap(:&rewind).read.lines.last).to eq("test #<< message")
end

I personally try to test without using stubs whenever possible, and it seems like this is a place we could do that without too much trouble.

[NickLaMuro]

Not sure if this is the place to have this discussion, but want to at least start it here, and we can move it where appropriate.

After spending some time messing with this class this morning, I question whether we should be inheriting Logger for this class, especially when using #method_missing for a lot of our functionality (maybe that should go as well).

The reason this bug went unnoticed for so log is that we were inheriting from Logger, and the implementation of Logger#<< is a follows:

def <<(msg)
  unless @logdev.nil?
    @logdev.write(msg)
  end
end

Meaning it was silently throwing away these messages, and we would have no way of knowing about it unless this bug got brought up. Seems like this would have came up sooner if we weren't inheriting from Logger. I wrote a quick patch to do just that:

diff --git a/lib/vmdb/loggers/multicast_logger.rb b/lib/vmdb/loggers/multicast_logger.rb
index 9ce281c..55c849a 100644
--- a/lib/vmdb/loggers/multicast_logger.rb
+++ b/lib/vmdb/loggers/multicast_logger.rb
@@ -1,16 +1,17 @@
 module Vmdb::Loggers
-  class MulticastLogger < Logger
-    attr_accessor :loggers
+  class MulticastLogger
+    attr_reader   :level
+    attr_accessor :loggers, :progname, :formatter
 
     def initialize(*loggers)
       require 'set'
       @loggers = Set.new(loggers)
-      @level   = DEBUG
+      @level   = Logger::DEBUG
     end
 
     def level=(new_level)
       loggers.each { |l| l.level = new_level }
-      super
+      @level = new_level
     end
 
     def filename
@@ -18,12 +19,20 @@ module Vmdb::Loggers
     end
 
     def add(*args, &block)
-      severity = args.first || UNKNOWN
+      severity = args.first || Logger::UNKNOWN
       return true if severity < @level
-      loggers.each { |l| l.send(:add, *args, &block) }
+      loggers.each { |l| l.add *args, &block }
       true
     end
 
+    %w[debug info warn error fatal unknown].each do |method|
+      eval <<-DEF
+        def #{method}(progname = nil, &block)
+          add(Logger::#{method.upcase}, nil, progname, &block)
+        end
+      DEF
+    end
+
     def reopen(_logdev = nil)
       raise NotImplementedError, "#{self.class.name} should not be reopened since it is backed by multiple loggers."
     end

I mostly wrote this to get the tests to pass, but the point being is that it isn't that much more code to do it. Arguably I could have gone further and tried to do the same without method_missing (and at this point, I am kinda arguing that we should), but it was a point to make that we could also not need to write our own #<< method like we did in this PR.

Anyway, just curious about your thoughts. Not something we should do in this PR (maybe I will open up an issue about this if we think this is reasonable).

[djberg96]

@bdunne Ok, updated to return the message size, and now it strips the message, too. I'm not sure why you would want to limit the message to info level.

[djberg96]

@NickLaMuro I think it's worthy of a separate discussion at least. I'm somewhat surprised there isn't a multicast logging library out there already that we could use. Is there?

[miq-bot]

Checked commit https://github.com/djberg96/manageiq/commit/3c6df38732881d1e5c353f506471cc2c168a7039 with ruby 2.3.3, rubocop 0.52.0, haml-lint 0.20.0, and yamllint 1.10.0
2 files checked, 0 offenses detected
Everything looks fine. 👍

[NickLaMuro]

@NickLaMuro I think it's worthy of a separate discussion at least.

Alright, I will open up a separate issue in a bit then, and ping a couple of folks about it, and we can continue the discussion there.

I'm somewhat surprised there isn't a multicast logging library out there already that we could use. Is there?

Not sure, though seems like we might be able to leverage something from ActiveSupport if I am not mistaken. I will take a look into that.

[bdunne]

@djberg96 The problem is that << writes plain unformatted text to the logger. In the container environment where EFK stack is the target consumer, if a log message is formatted in JSON format, it will be automatically parsed by Fluentd and searching the logs will be much easier. When the message is plain text, it is much harder to follow. Sending an info message instead will run through the formatter for this case and write JSON to the output. I don't know if info is the correct level, but I think running through the formatter is necessary.

[djberg96]

@bdunne So, how about this then?

loggers.each { |l| l.log(level, msg) }

Instead of specifying "info", just let it log at whatever level it's set to.

[bdunne]

Instead of specifying "info", just let it log at whatever level it's set to.

It feels like we could run into some strange issues if we do that, it would be much more predictable if we decide what level the log messages should be rather than setting it up on the fly.

[NickLaMuro]

@bdunne Correct me if I am wrong, but doesn't this seem like something we should be solving in lib/vmdb/loggers/container_logger.rb and not the MulticastLogger? We can just overwrite the #<< method there and then run it through the ContainerLogger::Formatter?

This feels like the wrong place to be dealing with formatting JSON for a specific logger.

[djberg96]

@bdunne Is @NickLaMuro correct? It does seem logical that the formatting concern for containers should be relegated to ContainerLogger. If necessary, I could update that class separately. What do you think?

[bdunne]

Yep, I'll modify the container logger in a separate PR.

[simaishi]

Gaprindashvili backport details:

$ git log -1
commit fcea608a0fc2fd62f78ab43f2d2cbecb57b17091
Author: Brandon Dunne <[email protected]>
Date:   Tue Jan 30 10:51:53 2018 -0500

    Merge pull request #16904 from djberg96/multicast_logger
    
    Add << method to MulticastLogger
    (cherry picked from commit e121e27d86374ab37df2ac54c6042ec68f8175f8)
    
    Fixes https://bugzilla.redhat.com/show_bug.cgi?id=1540356