Feature/add pipeline id and plugin name to logs #11052

andsel · 2019-08-16T08:50:14Z

No description provided.

jsvd · 2019-08-16T08:54:18Z

@andsel can you rebase against master?

jsvd · 2019-08-16T11:42:17Z

I've tested this locally, and I can only see the pipeline id when running the ruby execution and not the default java execution, can you confirm that?

andsel · 2019-08-16T12:05:44Z

I've tested locally with java execution engine and I've seen the log line with the id. I've added some test log lines (then not committed) into the java_pipeline.rb when the workers are fired up.

[2019-08-16T09:35:44,188][INFO ][logstash.javapipeline    ][another_test] Starting worker loop TODELETE
[2019-08-16T09:35:44,190][INFO ][logstash.javapipeline    ][another_test] Starting worker loop TODELETE
[2019-08-16T09:35:44,194][INFO ][logstash.javapipeline    ][another_test] Starting worker loop TODELETE
[2019-08-16T09:35:44,212][INFO ][logstash.javapipeline    ][another_test] Starting worker loop TODELETE
[2019-08-16T09:35:44,213][INFO ][logstash.javapipeline    ][test] Starting worker loop TODELETE
[2019-08-16T09:35:44,215][INFO ][logstash.javapipeline    ][test] Starting worker loop TODELETE

robbavey

Tested locally, this works as advertised, but as it stands will not set pipeline.id for log entries produced in threads created by a plugin - eg the beats plugin has entries like:

[2019-08-16T11:51:12,811][DEBUG][org.logstash.beats.BeatsHandler] [local: 0:0:0:0:0:0:0:1:5044, remote: 0:0:0:0:0:0:0:1:57963] Received a new payload

This can be remedied by setting the system property -Dlog4j2.isThreadContextMapInheritable to TRUE which uses InheritableThreadLocal for the ThreadContext

Thoughts? (cc @jsvd)

robbavey · 2019-08-16T16:01:15Z

config/log4j2.properties

@@ -4,7 +4,7 @@ name = LogstashPropertiesConfig
 appender.console.type = Console
 appender.console.name = plain_console
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %m%n
+appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-15c{1.}]%notEmpty{[%X{pipeline.id}]} %m%n


Is the change to the logging category from -25c to -15c{1.} something we want to add, add just to console, or leave to another PR?

andsel · 2019-08-16T16:24:34Z

Fixes must be done also to another thread:

logstash/logstash-core/lib/logstash/java_pipeline.rb

Lines 104 to 115 in b8a5fee

    
           @thread = Thread.new do 
        
             begin 
        
               LogStash::Util.set_thread_name("pipeline.#{pipeline_id}") 
        
               run 
        
               @finished_run.make_true 
        
             rescue => e 
        
               close 
        
               logger.error("Pipeline aborted due to error", default_logging_keys(:exception => e, :backtrace => e.backtrace)) 
        
             ensure 
        
               @finished_execution.make_true 
        
             end 
        
           end

andsel · 2019-08-22T15:24:21Z

jenkins test this please

colinsurprenant · 2019-08-22T16:48:59Z

logstash-core/lib/logstash/pipeline.rb

@@ -338,6 +341,8 @@ def worker_loop(batch_size, batch_delay)
      end
      flush_filters_to_batch(batch, :final => false) if signal.flush?
      if batch.filteredSize > 0
+
+        java_import org.apache.logging.log4j.ThreadContext


any reason to have this java_import here?

no, was my typo, the import is already on top of the file

colinsurprenant · 2019-08-22T16:51:25Z

logstash-core/spec/logstash/pipeline_spec.rb

@@ -15,6 +15,7 @@ def register
  end

  def run(queue)
+    @logger.debug("check log4j fish tagging: [" + ThreadContext.get("plugin.id") + "]")


are these debug lines in the spec still necessary or useful?

yes it is need to prove that the ThreadContext contains the fish tag for the plugin, so inside the plugin I log the tag and then in the expect verify that the log contains the tag.

Probably you are right, I can remove the "compiler way" that insert java code so set/unset the value in the ThreadContext, and move into the doOutput of AbstractOutputDelegatorExt (from OutputDelegatorExt), having a uniform way to set the plugin name for Ruby and Java plugins. What do you think?

colinsurprenant · 2019-08-22T16:54:54Z

logstash-core/src/main/java/org/logstash/config/ir/compiler/DatasetCompiler.java

+        return () -> "org.apache.logging.log4j.ThreadContext.put(\"plugin.id\", \"" + configName + "\")";
+    }
+
+    private static MethodLevelSyntaxElement setPluginIdForLog4j(final AbstractOutputDelegatorExt plugin) {


this code can probably be DRY'ed up for both method signatures?

You are right, I try lower the repetition, the two methods are identical but one work on AbstractFilterDelegatorExt and the other on AbstractOutputDelegatorExt and the two classes hasn't got any common ancestor

colinsurprenant · 2019-08-22T17:02:12Z

Great work @andsel 👏 - left a few inline minor comments.

robbavey

This is awesome @andsel, some really cool stuff in here. I've left a few comments in the code, and also, before committing, can you please update the commit header stating that the plugin is also going to be added, and a commit message giving a little more detail on the changes?

Also, I notice that the plugin.id is only enabled for the Java execution - is this intentional? If so, please add a comment stating that in the commit message.

robbavey · 2019-08-22T16:16:06Z

config/log4j2.properties

@@ -21,7 +21,7 @@ appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
 appender.rolling.policies.time.interval = 1
 appender.rolling.policies.time.modulate = true
 appender.rolling.layout.type = PatternLayout
-appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %-.10000m%n
+appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c]%notEmpty{[%X{pipeline.id}]} %-.10000m%n


plugin.id missing from the file appender

Added, thanks I missed to add to ConsoleAppender

robbavey · 2019-08-22T17:46:43Z

config/jvm.options

@@ -76,3 +76,6 @@

 # Entropy source for randomness
 -Djava.security.egd=file:/dev/urandom
+
+# Copy the logging context from parent threads to children
+-Dlog4j2.isThreadContextMapInheritable


I think this needs to be set to =true to apply - I ran locally and the thread context wasn't inherited unless =true was set

You are right, fixed

robbavey · 2019-08-22T18:49:59Z

logstash-core/src/main/java/org/logstash/config/ir/compiler/DatasetCompiler.java

@@ -196,12 +200,13 @@ private static Closure filterBody(final ValueSyntaxElement outputBuffer,
        final ValueSyntaxElement inputBuffer, final ClassFields fields,
        final AbstractFilterDelegatorExt plugin) {
        final ValueSyntaxElement filterField = fields.add(plugin);
-        final Closure body = Closure.wrap(
+        final Closure body = Closure.wrap(setPluginIdForLog4j(plugin),


What is the use case for settingplugin.Id here as well as in the filter and output delegators?

(Genuine question! I played around with the code a little, and changing values here didn't seem to affect the log entries, but I wasn't exhaustive, so I probably missed something!)

Because method filterDataset invokes filterBody and filterBody sets and unsets the plugin.id in the context, while outputDataset create directly the statements creators, without invoking the filterBody.
So in filterBody, I need to set to make working in filters while in outputDataset for output.

robbavey · 2019-08-22T18:53:15Z

logstash-core/lib/logstash/java_pipeline.rb

@@ -305,6 +309,8 @@ def start_input(plugin)

  def inputworker(plugin)
    Util::set_thread_name("[#{pipeline_id}]<#{plugin.class.config_name}")
+    ThreadContext.put("pipeline.id", pipeline_id)
+    ThreadContext.put("plugin.id", plugin.config_name)


I think here in terms of that we want to populate the plugin.id variable with, I think we might want to have the actual id either instead of, or as well as config_name. Only putting the configName here means that we cannot disambiguate between plugins of the same type in the same pipeline configuration. It be worth including the config name and the plugin.id in the logs - the plugin.id is often not set and may not be particularly illuminating. Thoughts @jsvd?

…ed sub-threads

andsel · 2019-08-23T13:55:51Z

@colinsurprenant @robbavey this PR going to split in 2, one for the pipeline.id and one for the plugin.id

pipeline.id PR: #11075
plugin.id (renamed to plugin.name) PR: #11078

andsel · 2019-08-23T15:36:00Z

I close this because it has been splitted in PR #11075 and PR #11078

andsel force-pushed the feature/add_pipeline_id_to_logs branch from 6735ddc to b8a5fee Compare August 16, 2019 10:12

robbavey reviewed Aug 16, 2019

View reviewed changes

andsel force-pushed the feature/add_pipeline_id_to_logs branch 2 times, most recently from 4b755c1 to 1edd49a Compare August 22, 2019 08:31

elasticsearch-bot self-assigned this Aug 22, 2019

colinsurprenant unassigned elasticsearch-bot Aug 22, 2019

colinsurprenant reviewed Aug 22, 2019

View reviewed changes

robbavey requested changes Aug 22, 2019

View reviewed changes

jsvd and others added 9 commits August 23, 2019 08:59

better thread identification and pipeline thread context setup

68ca759

Added pipeline.id into Log4j's ThreadContext

b0daebd

Added ThreadContext to a missed Thread.new

69b731b

Minor, added log4j2 startup property to propagate sub threads

ea0b3cc

Set the plugin.id during execution of a plugin

b5368a3

Added tests to verify the assignment of log4j fish tag with plugin name

b45d627

Fixed failing test due to missing of in fake test plugins

2ec9707

Fixed lint error (missed serialVersionUID)

bcf876b

Minor, removed unusefull import

8994e1e

andsel force-pushed the feature/add_pipeline_id_to_logs branch from d94463d to 8994e1e Compare August 23, 2019 06:59

andsel added 3 commits August 23, 2019 09:16

Try remove redundancy in generation of fish tag assignment

90c18f6

Minor, added plugin.id also on the file appender

1cadbbb

Fixed log4j flag assignment to propagate ThreadContext to newly creat…

17e5156

…ed sub-threads

andsel changed the title ~~Feature/add pipeline id to logs~~ Feature/add pipeline id and plugin name to logs Aug 23, 2019

andsel closed this Aug 23, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Feature/add pipeline id and plugin name to logs #11052

Feature/add pipeline id and plugin name to logs #11052

andsel commented Aug 16, 2019

jsvd commented Aug 16, 2019

jsvd commented Aug 16, 2019

andsel commented Aug 16, 2019

robbavey left a comment

robbavey Aug 16, 2019

andsel commented Aug 16, 2019

andsel commented Aug 22, 2019

colinsurprenant Aug 22, 2019

andsel Aug 23, 2019

colinsurprenant Aug 22, 2019

andsel Aug 23, 2019

andsel Aug 23, 2019

colinsurprenant Aug 22, 2019

andsel Aug 23, 2019

colinsurprenant commented Aug 22, 2019

robbavey left a comment

robbavey Aug 22, 2019

andsel Aug 23, 2019

robbavey Aug 22, 2019

andsel Aug 23, 2019

robbavey Aug 22, 2019

andsel Aug 23, 2019

robbavey Aug 22, 2019

andsel commented Aug 23, 2019 •

edited

Loading

andsel commented Aug 23, 2019

Feature/add pipeline id and plugin name to logs #11052

Feature/add pipeline id and plugin name to logs #11052

Conversation

andsel commented Aug 16, 2019

jsvd commented Aug 16, 2019

jsvd commented Aug 16, 2019

andsel commented Aug 16, 2019

robbavey left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andsel commented Aug 16, 2019

andsel commented Aug 22, 2019

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

colinsurprenant commented Aug 22, 2019

robbavey left a 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

andsel commented Aug 23, 2019 • edited Loading

andsel commented Aug 23, 2019

andsel commented Aug 23, 2019 •

edited

Loading