Fix MulticastLogger DEBUG mode #16990

NickLaMuro · 2018-02-12T23:18:02Z

When passing the config/settings data to the .apply_config_value method of Vmdb::Loggers, if the value was set to DEBUG the level wouldn't be changed in the lower level logger to reflect that.

This is because the MulticastLogger is instantiated and defaulted at DEBUG, but the logger it casts to (normally an instance of VMDBLogger) would have it's level defaulted to info. When .apply_config_value is then called, it would compare the old value to the new one, and see it as the same, even though it was different under the covers.

This means when a user attempts to do a $log.debug "my message", the message would then not be applied.

The fix here effectively makes sure we are defaulting the lower level logger to the same log level as the parent, or the MulticastLogger. When .apply_config_value is then eventually called, if the setting is set to DEBUG, nothing will change, but the level will be set properly for the lower level logger. Anything level set higher than DEBUG will function as it has.

Regarding extra tests...

There was also some additional tests added to the new test file, spec/lib/vmdb/loggers_spec.rb, that covered some of the quirks of log levels in a container config. Since $container_log is set to use the lib/vmdb/loggers/container_logger.rb, this means it's #level= method is set to override the default and always set itself to "DEBUG". This is a bit confusing at first glace if you are trying to grok what is happening in lib/vmdb/loggers.rb, as it can seem like the whole thing wouldn't work as expected, and the level for the $container_log would be overwritten with each log type.

Links

PR adding MulticastLogger: Logging to STDOUT in JSON format for containers #15392
Fixes https://bugzilla.redhat.com/show_bug.cgi?id=1544919

bdunne · 2018-02-13T04:36:10Z

lib/vmdb/loggers.rb

@@ -130,7 +130,10 @@ def self.create_loggers
    private_class_method :create_loggers

    def self.create_multicast_logger(log_file_path, logger_class = VMDBLogger)
-      MulticastLogger.new(logger_class.new(log_file_path)).tap do |l|
+      logger_instance = logger_class.new(log_file_path).tap do |logger|
+        logger.level = MulticastLogger::DEBUG


Should this be Logger::DEBUG?

Yeah, no reason why not. I can change in the morning.

bdunne · 2018-02-13T04:39:16Z

spec/lib/vmdb/loggers_spec.rb

+
+def in_container_env(example)
+  old_env = ENV.delete('CONTAINER')
+  ENV['CONTAINER'] = '1'


Usually this is set to "true"

The code has it as effectively a nil check, but I can change it if you would prefer. I have always kept the practice when calling other toggle-able ENV vars has been TOGGLE_SOMETHING=1, but that is just my preference.

Right, we're really just checking to see if the ENV variable is set or unset. But to avoid confusion in case the value becomes important in the future, I'd prefer "true".
https://github.com/ManageIQ/manageiq-pods/blob/master/images/miq-app/Dockerfile#L9

djberg96 · 2018-02-13T14:55:46Z

@NickLaMuro Looks good to me (though I agree with bdunne's comments).

👍

NickLaMuro · 2018-02-13T16:00:53Z

@djberg96 @bdunne Should be all set.

Fryguy · 2018-02-13T18:59:32Z

spec/lib/vmdb/loggers_spec.rb

@@ -0,0 +1,52 @@
+describe Vmdb::Loggers do
+  let(:log_file) { Rails.root.join("log", "foo.log").to_s }
+  describe "#create_multicast_logger" do


Minor style...please add blank lines around describes to separate them

Also, minor, but since this is a private method, can you clarify that in the describe line? It makes it clearer why you have to do .send below. I usually do something like describe "#create_multicast_logger (private)" do

Sweet, all for this, just assumed rubocop would have yelled at me (feel like it has in the past).

Yeah, I expected rubocop to yell about it too, so I was surprised

Fryguy · 2018-02-13T19:00:28Z

spec/lib/vmdb/loggers_spec.rb

+  end
+end
+
+def in_container_env(example)


Should this definition be inside the describe block? toplevel clearly infects the global namespace, but I think inside of a describe it will be at least isolated. @bdunne Do you remember?

I can try, since it isn't too much effort to do so. Wanted to make sure it was not repeated code, but yeah, I can see if tossing it in a describe isolates things. Couldn't hurt.

Fryguy · 2018-02-13T19:01:23Z

spec/lib/vmdb/loggers_spec.rb

+  ENV['CONTAINER'] = 'true'
+  example.run
+ensure
+  # ENV['x'] = nil deletes the key because ENV accepts only string values


Not sure why this comment is needed...we should always set back to the original value anyway (i.e. this code won't ever say = nil, so no need to explain it)

this code won't ever say = nil, so no need to explain it

Not directly, but in the lines above, where we get the old_env, more often then not, it is probably nil.

Also, I have shamelessly ripped this off from here: d098bc0

So this is not my comment to begin with.

That said, I am fine with removing it if it is a bother, though, seeing as it is now in our codebase about 5 other times, we probably should just make it a helper at this point (not in this PR though).

Ahhh..ok, this is fine then 👍

Fryguy · 2018-02-13T19:01:45Z

spec/lib/vmdb/loggers_spec.rb

+    end
+
+    context "in a container environment" do
+      around(:each) { |example| in_container_env(example) }


The :each is redundant as it's the default, so please remove (same below).

Sure, no prob. Again, though, ripped off from here: d098bc0

Where around(:each) was used.

Fryguy · 2018-02-13T19:08:37Z

Most of my comments are super-minor.

I am concerned that we default to DEBUG in this part of the code, but the MulticastLogger defaults to DEBUG in a different part of the code. If the intention is to keep them linked, then code-wise it feels disconnected. I'm ok with merging for now, as I'm not sure how to resolve that disconnect.

When passing the config/settings data to the `.apply_config_value` method of Vmdb::Loggers, if the value was set to `DEBUG` the level wouldn't be changed in the lower level logger to reflect that. This is because the MulticastLogger is instantiated and defaulted at DEBUG, but the logger it casts to (normally an instance of VMDBLogger) would have it's level defaulted to `info`. When `.apply_config_value` is then called, it would compare the old value to the new one, and see it as the same, even though it was different under the covers. This means when a user attempts to do a `$log.debug "my message"`, the message would then not be applied. The fix here effectively makes sure we are defaulting the lower level logger to the same log level as the parent, or the MulticastLogger. When `.apply_config_value` is then eventually called, if the setting is set to `DEBUG`, nothing will change, but the level will be set properly for the lower level logger. Anything level set higher than DEBUG will function as it has. * * * There was also some additional tests added to the new test file, `spec/lib/vmdb/loggers_spec.rb`, that covered some of the quirks of log levels in a container config. Since `$container_log` is set to use the `lib/vmdb/loggers/container_logger.rb`, this means it's `#level=` method is set to override the default and always set itself to "DEBUG". This is a bit confusing at first glace if you are trying to grok what is happening in `lib/vmdb/loggers.rb`, as it can seem like the whole thing wouldn't work as expected, and the level for the $container_log would be overwritten with each log type.

NickLaMuro · 2018-02-13T19:19:26Z

@Fryguy changes applied, minus the "comment about the comment". Left an explanation and ref about that one. Can change if you feel strongly about it.

miq-bot · 2018-02-13T19:23:03Z

Checked commit NickLaMuro@a7ed2cb 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. 👍

…bug-mode-in-settings Fix MulticastLogger DEBUG mode (cherry picked from commit c6eac38) Fixes https://bugzilla.redhat.com/show_bug.cgi?id=1545292

simaishi · 2018-02-14T14:49:28Z

Gaprindashvili backport details:

$ git log -1
commit 714e133ce5d1ca80a0cde02a8522535b6c4cf8b8
Author: Jason Frey <fryguy9@gmail.com>
Date:   Tue Feb 13 14:57:00 2018 -0500

    Merge pull request #16990 from NickLaMuro/fix-multicast-logger-for-debug-mode-in-settings
    
    Fix MulticastLogger DEBUG mode
    (cherry picked from commit c6eac38f80169447876a07257ebdea479d4d1b4f)
    
    Fixes https://bugzilla.redhat.com/show_bug.cgi?id=1545292

NickLaMuro force-pushed the fix-multicast-logger-for-debug-mode-in-settings branch 2 times, most recently from d8f2361 to 7505e3f Compare February 12, 2018 23:52

bdunne reviewed Feb 13, 2018

View reviewed changes

NickLaMuro force-pushed the fix-multicast-logger-for-debug-mode-in-settings branch from 7505e3f to c68b94c Compare February 13, 2018 15:58

Fryguy reviewed Feb 13, 2018

View reviewed changes

NickLaMuro force-pushed the fix-multicast-logger-for-debug-mode-in-settings branch from c68b94c to a7ed2cb Compare February 13, 2018 19:17

Fryguy approved these changes Feb 13, 2018

View reviewed changes

Fryguy self-assigned this Feb 13, 2018

Fryguy added bug gaprindashvili/yes labels Feb 13, 2018

Fryguy added this to the Sprint 80 Ending Feb 26, 2018 milestone Feb 13, 2018

Fryguy merged commit c6eac38 into ManageIQ:master Feb 13, 2018

simaishi added the blocker label Feb 14, 2018

simaishi added gaprindashvili/backported and removed gaprindashvili/yes labels Feb 14, 2018

Ladas mentioned this pull request Feb 14, 2018

Fix refresh for stack without parameters ManageIQ/manageiq-providers-amazon#410

Merged

NickLaMuro mentioned this pull request Feb 14, 2018

Fix automate specs after MulticastLogger changes #17001

Merged

miha-plesko mentioned this pull request Mar 1, 2018

Apply logger level #16697

Closed

NickLaMuro mentioned this pull request Mar 9, 2018

Fix Default log level for automation log #17130

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix MulticastLogger DEBUG mode #16990

Fix MulticastLogger DEBUG mode #16990

NickLaMuro commented Feb 12, 2018 •

edited

Loading

bdunne Feb 13, 2018

NickLaMuro Feb 13, 2018

bdunne Feb 13, 2018 •

edited

Loading

NickLaMuro Feb 13, 2018

bdunne Feb 13, 2018

djberg96 commented Feb 13, 2018

NickLaMuro commented Feb 13, 2018

Fryguy Feb 13, 2018

Fryguy Feb 13, 2018

NickLaMuro Feb 13, 2018

Fryguy Feb 13, 2018

Fryguy Feb 13, 2018

NickLaMuro Feb 13, 2018

Fryguy Feb 13, 2018

NickLaMuro Feb 13, 2018

Fryguy Feb 13, 2018

Fryguy Feb 13, 2018

NickLaMuro Feb 13, 2018

Fryguy commented Feb 13, 2018

NickLaMuro commented Feb 13, 2018

miq-bot commented Feb 13, 2018

simaishi commented Feb 14, 2018

Fix MulticastLogger DEBUG mode #16990

Fix MulticastLogger DEBUG mode #16990

Conversation

NickLaMuro commented Feb 12, 2018 • edited Loading

Regarding extra tests...

Links

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bdunne Feb 13, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

djberg96 commented Feb 13, 2018

NickLaMuro commented Feb 13, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Fryguy commented Feb 13, 2018

NickLaMuro commented Feb 13, 2018

miq-bot commented Feb 13, 2018

simaishi commented Feb 14, 2018

NickLaMuro commented Feb 12, 2018 •

edited

Loading

bdunne Feb 13, 2018 •

edited

Loading