Refactor: improve plugin logging xp

logstash-core/lib/logstash/plugin.rb

@@ -19,7 +19,6 @@
 require "logstash/plugins/ecs_compatibility_support"
 require "concurrent"
 require "logstash/plugins/event_factory_support"
-require "securerandom"
 
 require_relative 'plugin_metadata'
 
@@ -65,18 +64,11 @@ def eql?(other)
   end
 
   def initialize(params={})
-    @logger = self.logger
-    @deprecation_logger = self.deprecation_logger
-    # need to access settings statically because plugins are initialized in config_ast with no context.
-    settings = LogStash::SETTINGS
-    @slow_logger = self.slow_logger(settings.get("slowlog.threshold.warn").to_nanos,
-                                    settings.get("slowlog.threshold.info").to_nanos,
-                                    settings.get("slowlog.threshold.debug").to_nanos,
-                                    settings.get("slowlog.threshold.trace").to_nanos)
     @params = LogStash::Util.deep_clone(params)
     # The id should always be defined normally, but in tests that might not be the case
     # In the future we may make this more strict in the Plugin API
-    @params["id"] ||= "#{self.class.config_name}_#{SecureRandom.uuid}"
+    @params["id"] ||= LogStash::Plugins::PluginFactory.generate_plugin_id
+    __initialize_logging # after id is generated
   end
 
   # Return a uniq ID for this plugin configuration, by default
@@ -191,4 +183,32 @@ def execution_context=(new_context)
   def execution_context
     @execution_context || LogStash::ExecutionContext::Empty
   end
+
+  # override Loggable (self.class.logger) delegating methods :
+
+  attr_reader :logger
+  attr_reader :deprecation_logger
+  attr_reader :slow_logger
+
+  private
+
+  def __initialize_logging
+    @logger = LogStash::Logging::PluginLogger.new(self)
+    @deprecation_logger = self.class.deprecation_logger
+    # need to access settings statically because plugins are initialized in config_ast with no context.
+    settings = LogStash::SETTINGS
+    @slow_logger = self.class.slow_logger(settings.get("slowlog.threshold.warn").to_nanos,
+                                          settings.get("slowlog.threshold.info").to_nanos,
+                                          settings.get("slowlog.threshold.debug").to_nanos,
+                                          settings.get("slowlog.threshold.trace").to_nanos)
+  end
+
+  # 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
+
 end # class LogStash::Plugin

logstash-core/spec/logstash/config/mixin_spec.rb

@@ -37,7 +37,7 @@
     end
 
     it "should not log the password" do
-      expect(LogStash::Logging::Logger).to receive(:new).with(anything).and_return(double_logger)
+      expect(LogStash::Logging::PluginLogger).to receive(:new).with(anything).and_return(double_logger)
       expect(double_logger).to receive(:warn) do |arg1,arg2|
           message = 'You are using a deprecated config setting "old_opt" set in test_deprecated. Deprecated settings will continue to work, but are scheduled for removal from logstash in the future. this is old school If you have any questions about this, please visit the #logstash channel on freenode irc.'
           expect(arg1).to eq(message)

logstash-core/spec/logstash/java_pipeline_spec.rb

@@ -507,10 +507,16 @@ def flush(options)
       pipeline.close
     end
 
-    it "should use LIR provided IDs" do
-      expect(pipeline.inputs.first.id).to eq(pipeline.lir.input_plugin_vertices.first.id)
-      expect(pipeline.filters.first.id).to eq(pipeline.lir.filter_plugin_vertices.first.id)
-      expect(pipeline.outputs.first.id).to eq(pipeline.lir.output_plugin_vertices.first.id)
+    it "should generate plugin ids" do
+      input_id = pipeline.inputs.first.id
+      filter_id = pipeline.filters.first.id
+      output_id = pipeline.outputs.first.id
+      [ input_id, filter_id, output_id ].each do |plugin_id|
+        expect(plugin_id).to match /([0-9]|[a-f])+/
+      end
+      expect( input_id ).to_not eq filter_id
+      expect( input_id ).to_not eq output_id
+      expect( output_id ).to_not eq filter_id
     end
   end
 

logstash-core/spec/logstash/plugin_spec.rb

@@ -411,8 +411,8 @@ def register; end
     context "when the id is not provided provided" do
       subject { plugin.new(config) }
 
-      it "return a human readable ID" do
-        expect(subject.id).to match(/^simple_plugin_/)
+      it "generates an id" do
+        expect(subject.id).to match /([0-9]|[a-f])+/
       end
     end
   end

logstash-core/src/main/java/org/logstash/RubyUtil.java

@@ -72,6 +72,7 @@
 import org.logstash.log.DeprecationLoggerExt;
 import org.logstash.log.LoggableExt;
 import org.logstash.log.LoggerExt;
+import org.logstash.log.PluginLoggerExt;
 import org.logstash.log.SlowLoggerExt;
 import org.logstash.plugins.HooksRegistryExt;
 import org.logstash.plugins.UniversalPluginExt;
@@ -477,6 +478,8 @@ public final class RubyUtil {
         final RubyModule loggingModule = LOGSTASH_MODULE.defineOrGetModuleUnder("Logging");
         LOGGER = loggingModule.defineClassUnder("Logger", RUBY.getObject(), LoggerExt::new);
         LOGGER.defineAnnotatedMethods(LoggerExt.class);
+        final RubyClass pluginLoggerClass = loggingModule.defineClassUnder("PluginLogger", LOGGER, PluginLoggerExt::new);
+        pluginLoggerClass.defineAnnotatedMethods(PluginLoggerExt.class);
         SLOW_LOGGER = loggingModule.defineClassUnder(
             "SlowLogger", RUBY.getObject(), SlowLoggerExt::new);
         SLOW_LOGGER.defineAnnotatedMethods(SlowLoggerExt.class);

logstash-core/src/main/java/org/logstash/common/Util.java

@@ -20,6 +20,8 @@
 
 package org.logstash.common;
 
+import org.apache.commons.codec.digest.DigestUtils;
+
 import java.nio.charset.StandardCharsets;
 import java.security.MessageDigest;
 import java.security.NoSuchAlgorithmException;
@@ -41,6 +43,14 @@ public static String digest(String base) {
         return bytesToHexString(hash);
     }
 
+    /**
+     * Generates a short digest from bytes.
+     * @return a hex digest string (16 characters long)
+     */
+    public static String shortDigest(final byte[] bytes) { // using MD5 for speed
+        return new DigestUtils("MD5").digestAsHex(bytes).substring(0, 16);
+    }
+
     public static String bytesToHexString(byte[] bytes) {
         StringBuilder hexString = new StringBuilder();
 

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

@@ -46,7 +46,8 @@ public abstract class AbstractFilterDelegatorExt extends RubyObject {
 
     protected AbstractNamespacedMetricExt metricEvents;
 
-    protected RubyString id;
+    protected String id;
+    private transient RubyString idString;
 
     protected LongCounter eventMetricOut;
 
@@ -60,7 +61,7 @@ public AbstractFilterDelegatorExt(final Ruby runtime, final RubyClass metaClass)
 
     protected void initMetrics(final String id, final AbstractNamespacedMetricExt namespacedMetric) {
         final ThreadContext context = RubyUtil.RUBY.getCurrentContext();
-        this.id = RubyString.newString(context.runtime, id);
+        this.setId(context, id);
         synchronized(namespacedMetric.getMetric()) {
             metricEvents = namespacedMetric.namespace(context, MetricKeys.EVENTS_KEY);
             eventMetricOut = LongCounter.fromRubyBase(metricEvents, MetricKeys.OUT_KEY);
@@ -76,7 +77,7 @@ public IRubyObject register(final ThreadContext context) {
         return context.nil;
     }
 
-    protected abstract void doRegister(final ThreadContext context);
+    protected abstract IRubyObject doRegister(final ThreadContext context);
 
     @JRubyMethod
     public IRubyObject close(final ThreadContext context) {
@@ -120,11 +121,20 @@ public IRubyObject configName(final ThreadContext context) {
 
     protected abstract IRubyObject getConfigName(ThreadContext context);
 
-    @JRubyMethod(name = "id")
-    public IRubyObject getId() {
+    public String getId() {
         return id;
     }
 
+    void setId(ThreadContext context, String id) {
+        this.id = id;
+        this.idString = (RubyString) RubyString.newString(context.runtime, id).freeze(context);
+    }
+
+    @JRubyMethod(name = "id")
+    public IRubyObject id() {
+        return idString == null ? getRuntime().getNil() : idString;
+    }
+
     @JRubyMethod(name = "multi_filter")
     @SuppressWarnings({"unchecked", "rawtypes"})
     public RubyArray multiFilter(final IRubyObject input) {

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

@@ -51,7 +51,8 @@ public abstract class AbstractOutputDelegatorExt extends RubyObject {
 
     private AbstractNamespacedMetricExt metricEvents;
 
-    private RubyString id;
+    private String id;
+    private transient RubyString idString;
 
     private LongCounter eventMetricOut;
 
@@ -90,11 +91,20 @@ public IRubyObject configName(final ThreadContext context) {
         return getConfigName(context);
     }
 
-    @JRubyMethod(name = "id")
-    public IRubyObject getId() {
+    public String getId() {
         return id;
     }
 
+    private void setId(ThreadContext context, String id) {
+        this.id = id;
+        this.idString = (RubyString) RubyString.newString(context.runtime, id).freeze(context);
+    }
+
+    @JRubyMethod(name = "id")
+    public IRubyObject id() {
+        return idString == null ? getRuntime().getNil() : idString;
+    }
+
     @JRubyMethod
     public IRubyObject metric() {
         return metric;
@@ -125,9 +135,9 @@ public IRubyObject multiReceive(final IRubyObject events) {
     }
 
     protected void initMetrics(final String id, final AbstractMetricExt metric) {
-        this.metric = metric;
         final ThreadContext context = RubyUtil.RUBY.getCurrentContext();
-        this.id = RubyString.newString(context.runtime, id);
+        this.setId(context, id);
+        this.metric = metric;
         synchronized (metric) {
             namespacedMetric = metric.namespace(context, context.runtime.newSymbol(id));
             metricEvents = namespacedMetric.namespace(context, MetricKeys.EVENTS_KEY);

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

@@ -26,7 +26,6 @@
 import org.jruby.RubyClass;
 import org.jruby.RubyHash;
 import org.jruby.RubyObject;
-import org.jruby.RubyString;
 import org.jruby.anno.JRubyClass;
 import org.jruby.anno.JRubyMethod;
 import org.jruby.internal.runtime.methods.DynamicMethod;
@@ -35,8 +34,6 @@
 import org.logstash.instrument.metrics.AbstractNamespacedMetricExt;
 import org.logstash.instrument.metrics.counter.LongCounter;
 
-import java.util.UUID;
-
 import static org.logstash.RubyUtil.RUBY;
 
 @JRubyClass(name = "FilterDelegator")
@@ -56,12 +53,11 @@ public final class FilterDelegatorExt extends AbstractFilterDelegatorExt {
 
     @JRubyMethod(name="initialize")
     public IRubyObject initialize(final ThreadContext context, final IRubyObject filter, final IRubyObject id) {
-        this.id = (RubyString) id;
         this.filter = filter;
         filterClass = filter.getSingletonClass().getRealClass();
         filterMethod = filterClass.searchMethod(FILTER_METHOD_NAME);
         final AbstractNamespacedMetricExt namespacedMetric = (AbstractNamespacedMetricExt) filter.callMethod(context, "metric");
-        initMetrics(this.id.asJavaString(), namespacedMetric);
+        initMetrics(id.asJavaString(), namespacedMetric);
         flushes = filter.respondsTo("flush");
         return this;
     }
@@ -75,17 +71,16 @@ public FilterDelegatorExt initForTesting(final IRubyObject filter, RubyObject co
         filterMethod = filter.getMetaClass().searchMethod(FILTER_METHOD_NAME);
         flushes = filter.respondsTo("flush");
         filterClass = configNameDouble.getType();
-        id = RUBY.newString(UUID.randomUUID().toString());
+        this.setId(filter.getRuntime().getCurrentContext(), RubyIntegration.generatePluginId());
         return this;
     }
 
     public FilterDelegatorExt(final Ruby runtime, final RubyClass metaClass) {
         super(runtime, metaClass);
     }
 
-    @Override
-    protected void doRegister(final ThreadContext context) {
-        filter.callMethod(context, "register");
+    protected IRubyObject registerImpl(final ThreadContext context) {
+        return filter.callMethod(context, "register");
     }
 
     @Override
@@ -118,12 +113,22 @@ protected IRubyObject getConfigName(final ThreadContext context) {
         return filterClass.callMethod(context, "config_name");
     }
 
+    @Override
+    public IRubyObject doRegister(final ThreadContext context) {
+        try {
+            org.apache.logging.log4j.ThreadContext.put("plugin.id", getId());
+            return registerImpl(context);
+        } finally {
+            org.apache.logging.log4j.ThreadContext.remove("plugin.id");
+        }
+    }
+
     @Override
     @SuppressWarnings({"rawtypes"})
     protected RubyArray doMultiFilter(final RubyArray batch) {
-        final IRubyObject pluginId = this.getId();
-        org.apache.logging.log4j.ThreadContext.put("plugin.id", pluginId.toString());
         try {
+            org.apache.logging.log4j.ThreadContext.put("plugin.id", getId());
+
             return (RubyArray) filterMethod.call(
                     RUBY.getCurrentContext(), filter, filterClass, FILTER_METHOD_NAME, batch);
         } finally {
@@ -133,7 +138,22 @@ protected RubyArray doMultiFilter(final RubyArray batch) {
 
     @Override
     protected IRubyObject doFlush(final ThreadContext context, final RubyHash options) {
-        return filter.callMethod(context, "flush", options);
+        try {
+            org.apache.logging.log4j.ThreadContext.put("plugin.id", getId());
+            return filter.callMethod(context, "flush", options);
+        } finally {
+            org.apache.logging.log4j.ThreadContext.remove("plugin.id");
+        }
+    }
+
+    @Override
+    public IRubyObject doClose(final ThreadContext context) {
+        try {
+            org.apache.logging.log4j.ThreadContext.put("plugin.id", getId());
+            return doCloseImpl(context);
+        } finally {
+            org.apache.logging.log4j.ThreadContext.remove("plugin.id");
+        }
     }
 
     @Override

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

@@ -89,7 +89,8 @@ protected RubyArray doMultiFilter(final RubyArray batch) {
     }
 
     @Override
-    protected void doRegister(ThreadContext context) {
+    protected IRubyObject doRegister(ThreadContext context) {
+        return context.nil;
     }
 
     @Override