RFC: Logging Context with Loggable

[yaauie]

Mapping the logs output by logstash plugins to their causes has become
increasingly complex, especially with the advent of multiple pipelines; a
plugin may be instantiated any number of times across one or more pipelines,
and finding which instance is the origin of a particular log message is no
longer trivial.

I would like to introduce the ability for an instance that includes our
Loggable to provide lazy default context to the underlying logger, including
helpful key/value pairs with data like the plugin's id and/or the pipeline's
id; it could also be useful to automatically include :exception if the
logger is invoked while handling an exception.

Given the current state of Javafication, I'm a little unsure where this should
land, and would like conceptual validation before attempting implementation.

---

In my current vision, any ruby object from a class that includes our
Loggable mixin (which currently defines an instance method #logger) will
be able to optionally respond to #logger_context(). This method would be
required to return a Hash that is allowed to be frozen.

The performance cost of doing this would be one additional long-lived proxy
object per instance that includes Loggable, plus potentially one or more
short-lived objects to build the merged context each time the logger is
invoked at or above its configured level.

For example, our Input::Base could implement it as follows, enabling each
log message to include helpful metadata about the pipeline and the plugin to
differentiate each instance, without changes to the plugins themselves:

  attr_reader :logging_context

  def register
    # ...

    @logging_context = {
      :plugin_id   => self.id
    }.freeze
  end

From here, any invocation of the logger within any input would include this context:

logger.warn('oh no!', :position => 7) # => 'oh no! {"plugin_id":"abad1dea", "position": 7}'

And any invocation that occurred while handling an exception could
automatically include the exception's message and backtrace, potentially
mirroring the pattern that is frequently used:

begin
  fail('intentional')
rescue
  logger.error('fubar') # 'fubar {"plugin_id":"abad1dea", "exception":"intentional", "backtrace":[...]}'
end

I have a quick-and-dirty ruby implementation of this logger_context_proxy,
and would appreciate conceptual feedback, as well as ideas of where this could
fit in with the current javafication.

[jsvd]

++ on having better context when logging. Another alternative is to use log4j2's thread context. I had a go at using this about a year ago, it can result in something like this:

pipelines.yml:

- pipeline.id: test
  pipeline.workers: 1
  pipeline.batch.size: 2
  config.string: "input { generator {} } filter { sleep { time => 1 } } output { stdout { codec => dots } }"
- pipeline.id: broken_test
  pipeline.workers: 1
  pipeline.batch.size: 1
  config.string: "input { stdin {} } filter { ruby { code => 'broken' } } output { stdout { codec => dots } }"

[2018-09-17T11:42:02,462][INFO ][l.agent        ] Pipelines running {:count=>2, :running_pipelines=>[:broken_test, :test], :non_running_pipelines=>[]}
[2018-09-17T11:42:02,784][INFO ][l.agent        ] Successfully started Logstash API endpoint {:port=>9600}
....
[2018-09-17T11:42:06,721][ERROR][broken_test][l.f.ruby       ] Ruby exception occurred: undefined local variable or method `broken' for #<LogStash::Filters::Ruby:0x51f6f93f>
...........
^C
[2018-09-17T11:42:16,741][WARN ][l.runner       ] SIGINT received. Shutting down.
....
[2018-09-17T11:42:21,749][WARN ][l.runner       ] Received shutdown signal, but pipeline is still waiting for in-flight events to be processed. Sending another ^C will force quit Logstash, but this may cause
data loss.
[2018-09-17T11:42:21,819][INFO ][test][l.pipeline     ] Pipeline has terminated {:pipeline_id=>"test", :thread=>"#<Thread:0x52dc9540 run>"}
[2018-09-17T11:42:21,950][INFO ][broken_test][l.pipeline     ] Pipeline has terminated {:pipeline_id=>"broken_test", :thread=>"#<Thread:0x150dd259@/tmp/logstash-6.4.0/logstash-core/lib/logstash/pipeline_action/create.rb:46 run>"}

I rebased the code for this and created an experimental wip PR: #9991

Maybe we could combine your logger context strategy + log4j2's thread context to have a good balance of implicit logging metadata + providing logstash's objects with the context for them to use (either in logging or for other purposes)

[andsel]

closed by merging of PR #11074