Refactor: make sure plugin logger sets context

logstash-core/lib/logstash/plugin.rb

@@ -65,18 +65,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}"
+    __initialize_logging # after id is generated
   end
 
   # Return a uniq ID for this plugin configuration, by default
@@ -191,4 +184,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/plugin_spec.rb

@@ -477,6 +477,50 @@ def register; end
 
   end
 
+  describe "logger" do
+
+    let(:plugin_class) do
+      Class.new(LogStash::Filters::Base) do
+        config_name "logger_test"
+        def register; end
+      end
+    end
+
+    let(:config) { { 'id' => 'custom_plugin_id' } }
+
+    let(:plugin) { plugin_class.new(config) }
+
+    it "has a unique logger per plugin instance" do
+      another_plugin = plugin_class.new(config)
+      expect(plugin.logger).not_to be another_plugin.logger
+    end
+
+    context 'existing logging context' do
+
+      let(:logger_impl) do
+        org.apache.logging.log4j.LogManager.getLogger plugin.logger.name
+      end
+
+      before do
+        org.apache.logging.log4j.ThreadContext.put('plugin.id', '__EXISTING__')
+      end
+
+      after do
+        org.apache.logging.log4j.ThreadContext.remove('plugin.id')
+      end
+
+      it "restores existing logging context after logging" do
+        logger_impl.level = org.apache.logging.log4j.Level::TRACE
+        [:trace, :debug, :info, :warn, :error, :fatal].each do |level|
+          plugin.logger.send(level, 'TEST')
+          expect( org.apache.logging.log4j.ThreadContext.get('plugin.id') ).to eql '__EXISTING__'
+        end
+      end
+
+    end
+
+  end
+
   describe "deprecation logger" do
     let(:config) do
       {

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/log/DeprecationLoggerExt.java

@@ -61,9 +61,9 @@ private void initialize(final String loggerName) {
     @JRubyMethod(name = "deprecated", required = 1, optional = 1)
     public IRubyObject rubyDeprecated(final ThreadContext context, final IRubyObject[] args) {
         if (args.length > 1) {
-            logger.deprecated(args[0].asJavaString(), args[1]);
+            logger.deprecated(args[0].toString(), args[1]);
         } else {
-            logger.deprecated(args[0].asJavaString());
+            logger.deprecated(args[0].toString());
         }
         return this;
     }

logstash-core/src/main/java/org/logstash/log/LoggableExt.java

@@ -35,8 +35,8 @@
 
 /**
  * JRuby extension, it's part of log4j wrapping for JRuby.
- * */
-@JRubyModule(name = "Loggable")
+ */
+@JRubyModule(name = "LogStash::Util::Loggable")
 public final class LoggableExt {
 
     private LoggableExt() {
@@ -53,21 +53,21 @@ public static RubyModule included(final ThreadContext context, final IRubyObject
 
     @JRubyMethod
     public static IRubyObject logger(final ThreadContext context, final IRubyObject self) {
-        return self.getSingletonClass().callMethod(context, "logger");
+        return self.getMetaClass().callMethod(context, "logger");
     }
 
     @JRubyMethod(name = "slow_logger", required = 4)
     public static IRubyObject slowLogger(final ThreadContext context, final IRubyObject self,
         final IRubyObject[] args) {
-        return self.getSingletonClass().callMethod(context, "slow_logger", args);
+        return self.getMetaClass().callMethod(context, "slow_logger", args);
     }
 
     @JRubyMethod(name= "deprecation_logger")
     public static IRubyObject deprecationLogger(final ThreadContext context, final IRubyObject self) {
-        return self.getSingletonClass().callMethod(context, "deprecation_logger");
+        return self.getMetaClass().callMethod(context, "deprecation_logger");
     }
 
-    private static String log4jName(final RubyModule self) {
+    static String log4jName(final RubyModule self) {
         String name;
         if (self.getBaseName() == null) { // anonymous module/class
             RubyModule real = self;