Refactor: improve plugin logging xp

[kares]

Release notes

What does this PR do?

Improves logging experience for the user (as a minor side effect LS should be faster to generated plugin ids).

• generated ids won't be recycled -> on a restart new ids are generated even if the configuration did not change
  previously, the id generation mechanism always fell back to walking the AST to generate an id by hashing the tree (EDIT: stricken. We rely on recycled ids)
• generated plugin ids will be shorter (16 characters) instead of 36 hex chars - logs should be easier to read (EDIT: stricken. loosely a breaking change given above)
• 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 w plugin.logger ...
• a (single) explicit generatePluginId implementation
  there's a change to use the same logic in tests -> tested plugin will no longer have the name_... prefix

Other changes:

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

Breaking changes:

• ~ very 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.

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

• TODO do we need to worry about always generating a random id for a codec
  like we did before this got refactored

How to test this PR locally

Related issues

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

Logs

Sample (artificial) logging session (just to demonstrate plugins always log with their id as context):

[2021-07-27T14:32:34,501][INFO ][logstash.codecs.plain    ][955460acfaa1d9f2] REGISTER
[2021-07-27T14:32:34,643][INFO ][logstash.inputs.file     ][0138d563e04582e3] INITIALIZE {"path"=>"/var/log/auth.log", "id"=>"0138d563e04582e3"}
[2021-07-27T14:32:34,746][INFO ][logstash.filters.ruby    ][f569244cde563334] INITIALIZE
[2021-07-27T14:32:37,211][INFO ][logstash.filters.ruby    ][main][f569244cde563334] REGISTER
[2021-07-27T14:32:37,355][INFO ][logstash.javapipeline    ][main] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>16, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>2000, "pipeline.sources"=>["config string"], :thread=>"#<Thread:0x163b0af1 run>"}
[2021-07-27T14:32:38,790][INFO ][logstash.javapipeline    ][main] Pipeline Java execution initialization time {"seconds"=>1.43}
[2021-07-27T14:32:38,840][INFO ][logstash.inputs.file     ][main][0138d563e04582e3] REGISTER
[2021-07-27T14:32:38,943][INFO ][logstash.inputs.file     ][main][0138d563e04582e3] No sincedb_path set, generating one based on the "path" setting {:sincedb_path=>"/home/kares/workspace/work/elastic/logstash/data/plugins/inputs/file/.sincedb_0776ae3d702d482a9bdd8900c6550225", :path=>["/var/log/auth.log"]}
[2021-07-27T14:32:38,974][INFO ][logstash.javapipeline    ][main] Pipeline started {"pipeline.id"=>"main"}
[2021-07-27T14:32:39,000][INFO ][logstash.inputs.file     ][main][0138d563e04582e3] RUN
[2021-07-27T14:32:39,090][INFO ][filewatch.observingtail  ][main] START, creating Discoverer, Watch with file and sincedb collections
[2021-07-27T14:32:39,097][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
[2021-07-27T14:32:39,678][INFO ][logstash.codecs.plain    ][main][955460acfaa1d9f2] DECODE: Jul 27 14:32:38 precision sshd[442003]: Connection closed by 127.0.0.1 port 53520 [preauth]
[2021-07-27T14:32:39,858][INFO ][logstash.filters.ruby    ][main][f569244cde563334] FILTER {"@version"=>"1", "@timestamp"=>2021-07-27T12:32:39.702Z, "message"=>"Jul 27 14:32:38 precision sshd[442003]: Connection closed by 127.0.0.1 port 53520 [preauth]", "host"=>"precision", "path"=>"/var/log/auth.log"}

[yaauie]

generated ids won't be recycled -> on a restart new ids are generated even if the configuration did not change
previously, the id generation mechanism always fell back to walking the AST to generate an id by hashing the tree

Recycling ids across restarts has proven very useful in the past, especially when users don't follow the "best practice" of defining their own plugin ids. It allows us to use captures of the node stats API to compare flow across restarts, especially in larger pipelines.

Is this change intrinsic to ensuring that the logger always has an id?

[kares]

Recycling ids across restarts has proven very useful in the past, especially when users don't follow the "best practice" of defining their own plugin ids. It allows us to use captures of the node stats API to compare flow across restarts, especially in larger pipelines.

Thanks, thought there might be a reason esp. since there was a comment which said smt like "do not walk the AST graph to generate ids as it's slow" and we did it anyway. The annoying thing for me with recycling is that we often get incomplete logs - judging from the generated plugin id I can not tell if it's the same LS instance or a restart has been made ... 😞

Is this change intrinsic to ensuring that the logger always has an id?

We would continue to have 2 ways of auto generating ids - one for manual plugin instantiation, another used w the pipeline.
At the time the plugin logger is setup (as laid out in the PR) an id would be present one way or another.
And shorter ids (if we're fine to have those) should be doable with the AST tree mechanism.

[yaauie]

I would be okay with shorter default ids in 8.0 (or perhaps rethinking ids in general), but a restart across minors or on the same version of Logstash should generate the same ids.

There may be an opportunity to add a pipeline.default_id_format setting or similar that controls id generation as a separate effort. We could then default to a more concise/readable format in a later release of Logstash.

Or we could keep the full-length ids and use log4j formatters to output only the first 16 chars into the log line, which would ensure collisions still get routed to separate files when log-per-pipeline is enabled:

-%notEmpty{[%X{pipeline.id}]}
+%notEmpty{[%maxLen{%X{pipeline.id}}{16}]}

[kares]

Thanks, that's a 🔐 was assuming changing ids would target a minor (7.15) and be acceptable.
Especially since LS lacks on consistency with the id format - regarding codecs (which were kind of the motivator):

<LogStash::Inputs::Elasticsearch id=>"4e805afb4960a70553434dc5d7ffc52f8b2410239d6cfc4372f5a66ea701b94c", codec=><LogStash::Codecs::JSON id=>"json_45212884-952d-4ce8-96a2-e6d87cc19447", ...>

... outputing first 16 chars gets us with: json_45212884-95 but might get weirder the longer the "prefix_" 😞

Also id generation is unnecessarily slow - using a 'slow' hashing alg SHA-256 + secure random while none of that in necessary.

Anyhow, I will try to split the PR effort to only include the new PluginLogger and leave the rest for later.