Refactor: make sure plugin logger sets context #13201

kares · 2021-09-02T09:30:50Z

Improves logging experience for the user (commits extracted from #13038).

loosened logger(msg) contract allows for logging any (to_s) message not just strings - just like Log4j2 loggers do
an internal PluginLogger gets introduced to always have a plugin.id logging context
(with logger.debug ... etc.)

Other changes:

fixed logger.trace? (previously delegated to logger.isDebugEnabled())

Breaking changes:

~ low impact

class LogStash::Input::SomePlugin < ...

  def initialize(params)
    logger.info "this would no longer work - previously did but only if not using @logger.info ..."
    super(params)
    # logging after super works fine
  end
...

potential plugin test failures ... mocking such as the following would need updating*:

  expect(LogStash::Codecs::Multiline).to receive(:logger).and_return(Mlc::MultilineLogTracer.new).at_least(:once)

or keeping def class.logger(plugin = self) functional in a backwards compatible way

Why is it important/What is the impact to the user?

Logs are Logstash's primary way of communicating with the user, always having a plugin id logged greatly improves the user (debugging) experience.

Release notes

We improved logging from plugins to always include contextual information (plugin's id) in logs.

What does this PR do?

A new PluginLogger is introduced, which is now unique per plugin instance.

Why is it important/What is the impact to the user?

Users will have better context when going through logs - as they should see the plugin id (which might be user set) more often.

Checklist

My code follows the style guidelines of this project
I have commented my code, particularly in hard-to-understand areas
~~I have made corresponding changes to the documentation~~
~~I have made corresponding change to the default configuration files (and/or docker env variables)~~
I have added tests that prove my fix is effective or that my feature works

Author's Checklist

codec ids (which we care about) use a different format than other plugins e.g.
[DEBUG][logstash.codecs.line ][line_cec86de4-b9b7-44ce-95c4-63423b9f92c3]
to resolve this we we need to do further changes, either:
- align the default id generation in the Plugin base class (concerns testing)
- or change contextualizer to handle CodecClass.new instantiation with an explicit id param

How to test this PR locally

e.g. bin/logstash --log.level debug -e "" will do

Related issues

target check confusing & printed multiple times (on reload) logstash-plugins/logstash-mixin-ecs_compatibility_support#7

Logs

[2021-09-02T13:11:35,570][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"stdin", :type=>"input", :class=>LogStash::Inputs::Stdin}
[2021-09-02T13:11:35,797][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"line", :type=>"codec", :class=>LogStash::Codecs::Line}
[2021-09-02T13:11:36,116][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-09-02T13:11:36,118][DEBUG][logstash.codecs.line     ][line_cec86de4-b9b7-44ce-95c4-63423b9f92c3] config LogStash::Codecs::Line/@id = "line_cec86de4-b9b7-44ce-95c4-63423b9f92c3"
[2021-09-02T13:11:36,120][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-09-02T13:11:36,120][DEBUG][logstash.codecs.line     ][line_cec86de4-b9b7-44ce-95c4-63423b9f92c3] config LogStash::Codecs::Line/@enable_metric = true
[2021-09-02T13:11:36,120][DEBUG][logstash.codecs.line     ][line_cec86de4-b9b7-44ce-95c4-63423b9f92c3] config LogStash::Codecs::Line/@charset = "UTF-8"
[2021-09-02T13:11:36,120][DEBUG][logstash.codecs.line     ][line_cec86de4-b9b7-44ce-95c4-63423b9f92c3] config LogStash::Codecs::Line/@delimiter = "\n"
[2021-09-02T13:11:36,219][DEBUG][logstash.inputs.stdin    ][78126271ac5bff73f6bf0184af4762dae07fc37550e7518c65e53f4a5304e914] config LogStash::Inputs::Stdin/@type = "stdin"
[2021-09-02T13:11:36,220][DEBUG][logstash.inputs.stdin    ][78126271ac5bff73f6bf0184af4762dae07fc37550e7518c65e53f4a5304e914] config LogStash::Inputs::Stdin/@id = "78126271ac5bff73f6bf0184af4762dae07fc37550e7518c65e53f4a5304e914"
[2021-09-02T13:11:36,220][DEBUG][logstash.inputs.stdin    ][78126271ac5bff73f6bf0184af4762dae07fc37550e7518c65e53f4a5304e914] config LogStash::Inputs::Stdin/@enable_metric = true
[2021-09-02T13:11:36,234][DEBUG][logstash.inputs.stdin    ][78126271ac5bff73f6bf0184af4762dae07fc37550e7518c65e53f4a5304e914] config LogStash::Inputs::Stdin/@codec = <LogStash::Codecs::Line id=>"line_cec86de4-b9b7-44ce-95c4-63423b9f92c3", enable_metric=>true, charset=>"UTF-8", delimiter=>"\n">
[2021-09-02T13:11:36,236][DEBUG][logstash.inputs.stdin    ][78126271ac5bff73f6bf0184af4762dae07fc37550e7518c65e53f4a5304e914] config LogStash::Inputs::Stdin/@add_field = {}
[2021-09-02T13:11:36,303][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"stdout", :type=>"output", :class=>LogStash::Outputs::Stdout}
[2021-09-02T13:11:36,326][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"rubydebug", :type=>"codec", :class=>LogStash::Codecs::RubyDebug}
[2021-09-02T13:11:36,347][DEBUG][logstash.codecs.rubydebug][rubydebug_ca944dc6-b28f-4c71-a31f-b3d7ac7d5009] config LogStash::Codecs::RubyDebug/@id = "rubydebug_ca944dc6-b28f-4c71-a31f-b3d7ac7d5009"
[2021-09-02T13:11:36,347][DEBUG][logstash.codecs.rubydebug][rubydebug_ca944dc6-b28f-4c71-a31f-b3d7ac7d5009] config LogStash::Codecs::RubyDebug/@enable_metric = true
[2021-09-02T13:11:36,348][DEBUG][logstash.codecs.rubydebug][rubydebug_ca944dc6-b28f-4c71-a31f-b3d7ac7d5009] config LogStash::Codecs::RubyDebug/@metadata = false
[2021-09-02T13:11:39,524][DEBUG][logstash.outputs.stdout  ][d1bd143ca9c0117499c20d8bac3ca9cfc73bb5eee5fbc5f5246d5862d956a109] config LogStash::Outputs::Stdout/@codec = <LogStash::Codecs::RubyDebug id=>"rubydebug_ca944dc6-b28f-4c71-a31f-b3d7ac7d5009", enable_metric=>true, metadata=>false>
[2021-09-02T13:11:39,525][DEBUG][logstash.outputs.stdout  ][d1bd143ca9c0117499c20d8bac3ca9cfc73bb5eee5fbc5f5246d5862d956a109] config LogStash::Outputs::Stdout/@id = "d1bd143ca9c0117499c20d8bac3ca9cfc73bb5eee5fbc5f5246d5862d956a109"
[2021-09-02T13:11:39,525][DEBUG][logstash.outputs.stdout  ][d1bd143ca9c0117499c20d8bac3ca9cfc73bb5eee5fbc5f5246d5862d956a109] config LogStash::Outputs::Stdout/@enable_metric = true
[2021-09-02T13:11:39,526][DEBUG][logstash.outputs.stdout  ][d1bd143ca9c0117499c20d8bac3ca9cfc73bb5eee5fbc5f5246d5862d956a109] config LogStash::Outputs::Stdout/@workers = 1
[2021-09-02T13:11:39,643][DEBUG][logstash.javapipeline    ] Starting pipeline {:pipeline_id=>"main"}

what was meant was likely to do a `self.class.logger` here

also changes the contract from msg.to_str to msg.to_s

also improves performance of plugin.logger invocations

... for restore to keep the previously set id

kares · 2021-09-02T10:51:25Z

logstash-core/lib/logstash/plugin.rb

+  # TODO do we want to keep this around due plugin specs mocking logger through the class.logger call?!
+  # 
+  # @override LogStash::Util::Loggable.logger
+  # @private
+  # def self.logger(plugin = nil)
+  #   plugin.nil? ? super() : LogStash::Logging::PluginLogger.new(plugin)
+  # end
+


unfortunately, some existing plugin specs assume SomePlugin.logger class method to return the logger used for the plugin instance. the class level call still works (instantiates a new logger) but since we want the logger instance to keep context it needs the plugin instance passed in (for correctness).
my approach would be to deal with the broken specs afterwards and not introduce hacks such as these ...

Suggested change

# TODO do we want to keep this around due plugin specs mocking logger through the class.logger call?!

#

# @override LogStash::Util::Loggable.logger

# @private

# def self.logger(plugin = nil)

# plugin.nil? ? super() : LogStash::Logging::PluginLogger.new(plugin)

# end

kares added 10 commits September 2, 2021 11:18

Refactor: do not generate singleton_class for Loggable

051c423

what was meant was likely to do a `self.class.logger` here

simplify logging Ruby facade impl + fix trace?

083513e

Refactor: use asString (CharSequence) where possible

761678d

also changes the contract from msg.to_str to msg.to_s

align msg.to_s logging convention change

d2d9588

Refactor: prepare for plugin.logger customization

8be02d8

also improves performance of plugin.logger invocations

javadoc for logger methods + prepare for sub-classing

b1916aa

Feat: a custom logger per plugin instance

b49c46d

Test: adjust spec to consider PluginLogger

1e35201

Chore: keep a todo for plugin.class.logger method

8d2c4e1

only set plugin.id if isn't already set

d9ec497

... for restore to keep the previously set id

kares added enhancement v7.16.0 labels Sep 2, 2021

roaksoax added the status:work-in-progress label Sep 2, 2021

kares commented Sep 2, 2021

View reviewed changes

kares requested a review from yaauie September 2, 2021 10:53

kares added 2 commits September 2, 2021 13:16

Fix: wrong condition (boolean) return

2687121

a quick plugin.logger (context restoration) test

11ac7f9

kares removed the v7.16.0 label Nov 2, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactor: make sure plugin logger sets context #13201

Refactor: make sure plugin logger sets context #13201

kares commented Sep 2, 2021 •

edited

Loading

kares Sep 2, 2021

Refactor: make sure plugin logger sets context #13201

Are you sure you want to change the base?

Refactor: make sure plugin logger sets context #13201

Conversation

kares commented Sep 2, 2021 • edited Loading

Why is it important/What is the impact to the user?

Release notes

What does this PR do?

Why is it important/What is the impact to the user?

Checklist

Author's Checklist

How to test this PR locally

Related issues

Logs

kares Sep 2, 2021

Choose a reason for hiding this comment

kares commented Sep 2, 2021 •

edited

Loading