From 051c4236de9a291b59d7f704e250d03bebb45ad0 Mon Sep 17 00:00:00 2001 From: kares Date: Tue, 27 Jul 2021 09:32:16 +0200 Subject: [PATCH 01/12] Refactor: do not generate singleton_class for Loggable what was meant was likely to do a `self.class.logger` here --- .../src/main/java/org/logstash/log/LoggableExt.java | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/logstash-core/src/main/java/org/logstash/log/LoggableExt.java b/logstash-core/src/main/java/org/logstash/log/LoggableExt.java index caef20eaf05..c188b48f2ba 100644 --- a/logstash-core/src/main/java/org/logstash/log/LoggableExt.java +++ b/logstash-core/src/main/java/org/logstash/log/LoggableExt.java @@ -53,18 +53,18 @@ 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) { From 083513e27175e99117b879904b64561eb0753b20 Mon Sep 17 00:00:00 2001 From: kares Date: Tue, 27 Jul 2021 09:51:36 +0200 Subject: [PATCH 02/12] simplify logging Ruby facade impl + fix trace? --- .../main/java/org/logstash/log/LoggerExt.java | 102 ++++++++++-------- 1 file changed, 57 insertions(+), 45 deletions(-) diff --git a/logstash-core/src/main/java/org/logstash/log/LoggerExt.java b/logstash-core/src/main/java/org/logstash/log/LoggerExt.java index dae0f97de6c..35202c15375 100644 --- a/logstash-core/src/main/java/org/logstash/log/LoggerExt.java +++ b/logstash-core/src/main/java/org/logstash/log/LoggerExt.java @@ -61,6 +61,11 @@ public LoggerExt initialize(final ThreadContext context, final IRubyObject logge return this; } + @JRubyMethod(name = "trace?") + public RubyBoolean isTrace(final ThreadContext context) { + return logger.isTraceEnabled() ? context.tru : context.fals; + } + @JRubyMethod(name = "debug?") public RubyBoolean isDebug(final ThreadContext context) { return logger.isDebugEnabled() ? context.tru : context.fals; @@ -86,68 +91,75 @@ public RubyBoolean isFatal(final ThreadContext context) { return logger.isDebugEnabled() ? context.tru : context.fals; } - @JRubyMethod(name = "trace?") - public RubyBoolean isTrace(final ThreadContext context) { - return logger.isDebugEnabled() ? context.tru : context.fals; + @JRubyMethod + public IRubyObject trace(final IRubyObject msg) { + if (logger.isTraceEnabled()) logger.trace(msg.asJavaString()); + return this; } - @JRubyMethod(name = "debug", required = 1, optional = 1) - public IRubyObject rubyDebug(final ThreadContext context, final IRubyObject[] args) { - if (args.length > 1) { - logger.debug(args[0].asJavaString(), args[1]); - } else { - logger.debug(args[0].asJavaString()); - } + @JRubyMethod + public IRubyObject trace(final IRubyObject msg, final IRubyObject data) { + if (logger.isTraceEnabled()) logger.trace(msg.asJavaString(), data); return this; } - @JRubyMethod(name = "warn", required = 1, optional = 1) - public IRubyObject rubyWarn(final ThreadContext context, final IRubyObject[] args) { - if (args.length > 1) { - logger.warn(args[0].asJavaString(), args[1]); - } else { - logger.warn(args[0].asJavaString()); - } + @JRubyMethod + public IRubyObject debug(final IRubyObject msg) { + if (logger.isDebugEnabled()) logger.debug(msg.asJavaString()); return this; } - @JRubyMethod(name = "info", required = 1, optional = 1) - public IRubyObject rubyInfo(final ThreadContext context, final IRubyObject[] args) { - if (args.length > 1) { - logger.info(args[0].asJavaString(), args[1]); - } else { - logger.info(args[0].asJavaString()); - } + @JRubyMethod + public IRubyObject debug(final IRubyObject msg, final IRubyObject data) { + if (logger.isDebugEnabled()) logger.debug(msg.asJavaString(), data); return this; } - @JRubyMethod(name = "error", required = 1, optional = 1) - public IRubyObject rubyError(final ThreadContext context, final IRubyObject[] args) { - if (args.length > 1) { - logger.error(args[0].asJavaString(), args[1]); - } else { - logger.error(args[0].asJavaString()); - } + @JRubyMethod + public IRubyObject info(final IRubyObject msg) { + if (logger.isInfoEnabled()) logger.info(msg.asJavaString()); return this; } - @JRubyMethod(name = "fatal", required = 1, optional = 1) - public IRubyObject rubyFatal(final ThreadContext context, final IRubyObject[] args) { - if (args.length > 1) { - logger.fatal(args[0].asJavaString(), args[1]); - } else { - logger.fatal(args[0].asJavaString()); - } + @JRubyMethod + public IRubyObject info(final IRubyObject msg, final IRubyObject data) { + if (logger.isInfoEnabled()) logger.info(msg.asJavaString(), data); return this; } - @JRubyMethod(name = "trace", required = 1, optional = 1) - public IRubyObject rubyTrace(final ThreadContext context, final IRubyObject[] args) { - if (args.length > 1) { - logger.trace(args[0].asJavaString(), args[1]); - } else { - logger.trace(args[0].asJavaString()); - } + @JRubyMethod + public IRubyObject warn(final IRubyObject msg) { + logger.warn(msg.asJavaString()); + return this; + } + + @JRubyMethod + public IRubyObject warn(final IRubyObject msg, final IRubyObject data) { + logger.warn(msg.asJavaString(), data); + return this; + } + + @JRubyMethod + public IRubyObject error(final IRubyObject msg) { + logger.error(msg.asJavaString()); + return this; + } + + @JRubyMethod + public IRubyObject error(final IRubyObject msg, final IRubyObject data) { + logger.error(msg.asJavaString(), data); + return this; + } + + @JRubyMethod + public IRubyObject fatal(final IRubyObject msg) { + logger.fatal(msg.asJavaString()); + return this; + } + + @JRubyMethod + public IRubyObject fatal(final IRubyObject msg, final IRubyObject data) { + logger.fatal(msg.asJavaString(), data); return this; } From 761678d963109a6ba6eb99af4afb0c43b6f2d014 Mon Sep 17 00:00:00 2001 From: kares Date: Tue, 27 Jul 2021 10:37:25 +0200 Subject: [PATCH 03/12] Refactor: use asString (CharSequence) where possible also changes the contract from msg.to_str to msg.to_s --- .../main/java/org/logstash/log/LoggerExt.java | 24 +++++++++---------- 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/logstash-core/src/main/java/org/logstash/log/LoggerExt.java b/logstash-core/src/main/java/org/logstash/log/LoggerExt.java index 35202c15375..9148d59f03b 100644 --- a/logstash-core/src/main/java/org/logstash/log/LoggerExt.java +++ b/logstash-core/src/main/java/org/logstash/log/LoggerExt.java @@ -93,73 +93,73 @@ public RubyBoolean isFatal(final ThreadContext context) { @JRubyMethod public IRubyObject trace(final IRubyObject msg) { - if (logger.isTraceEnabled()) logger.trace(msg.asJavaString()); + logger.trace(msg.asString()); return this; } @JRubyMethod public IRubyObject trace(final IRubyObject msg, final IRubyObject data) { - if (logger.isTraceEnabled()) logger.trace(msg.asJavaString(), data); + if (logger.isTraceEnabled()) logger.trace(msg.toString(), data); return this; } @JRubyMethod public IRubyObject debug(final IRubyObject msg) { - if (logger.isDebugEnabled()) logger.debug(msg.asJavaString()); + logger.debug(msg.asString()); return this; } @JRubyMethod public IRubyObject debug(final IRubyObject msg, final IRubyObject data) { - if (logger.isDebugEnabled()) logger.debug(msg.asJavaString(), data); + if (logger.isDebugEnabled()) logger.debug(msg.toString(), data); return this; } @JRubyMethod public IRubyObject info(final IRubyObject msg) { - if (logger.isInfoEnabled()) logger.info(msg.asJavaString()); + logger.info(msg.asString()); return this; } @JRubyMethod public IRubyObject info(final IRubyObject msg, final IRubyObject data) { - if (logger.isInfoEnabled()) logger.info(msg.asJavaString(), data); + if (logger.isInfoEnabled()) logger.info(msg.toString(), data); return this; } @JRubyMethod public IRubyObject warn(final IRubyObject msg) { - logger.warn(msg.asJavaString()); + logger.warn(msg.asString()); return this; } @JRubyMethod public IRubyObject warn(final IRubyObject msg, final IRubyObject data) { - logger.warn(msg.asJavaString(), data); + logger.warn(msg.toString(), data); return this; } @JRubyMethod public IRubyObject error(final IRubyObject msg) { - logger.error(msg.asJavaString()); + logger.error(msg.asString()); return this; } @JRubyMethod public IRubyObject error(final IRubyObject msg, final IRubyObject data) { - logger.error(msg.asJavaString(), data); + logger.error(msg.toString(), data); return this; } @JRubyMethod public IRubyObject fatal(final IRubyObject msg) { - logger.fatal(msg.asJavaString()); + logger.fatal(msg.asString()); return this; } @JRubyMethod public IRubyObject fatal(final IRubyObject msg, final IRubyObject data) { - logger.fatal(msg.asJavaString(), data); + logger.fatal(msg.toString(), data); return this; } From d2d9588b3669c7530fa9d5794326af78b1075bc0 Mon Sep 17 00:00:00 2001 From: kares Date: Tue, 27 Jul 2021 11:06:14 +0200 Subject: [PATCH 04/12] align msg.to_s logging convention change --- .../src/main/java/org/logstash/log/DeprecationLoggerExt.java | 4 ++-- .../src/main/java/org/logstash/log/SlowLoggerExt.java | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/logstash-core/src/main/java/org/logstash/log/DeprecationLoggerExt.java b/logstash-core/src/main/java/org/logstash/log/DeprecationLoggerExt.java index 8dd2e1e2f5d..19670148a06 100644 --- a/logstash-core/src/main/java/org/logstash/log/DeprecationLoggerExt.java +++ b/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; } diff --git a/logstash-core/src/main/java/org/logstash/log/SlowLoggerExt.java b/logstash-core/src/main/java/org/logstash/log/SlowLoggerExt.java index 741200a3246..8f48f2b58af 100644 --- a/logstash-core/src/main/java/org/logstash/log/SlowLoggerExt.java +++ b/logstash-core/src/main/java/org/logstash/log/SlowLoggerExt.java @@ -100,7 +100,7 @@ private RubyHash asData(final ThreadContext context, final IRubyObject pluginPar @JRubyMethod(name = "on_event", required = 4) public IRubyObject onEvent(final ThreadContext context, final IRubyObject[] args) { - String message = args[0].asJavaString(); + String message = args[0].toString(); long eventDurationNanos = ((RubyNumeric)args[3]).getLongValue(); if (warnThreshold >= 0 && eventDurationNanos > warnThreshold) { From 8be02d85a846a32646cb0ff8b5de2e47db2a4362 Mon Sep 17 00:00:00 2001 From: kares Date: Tue, 27 Jul 2021 11:31:39 +0200 Subject: [PATCH 05/12] Refactor: prepare for plugin.logger customization also improves performance of plugin.logger invocations --- logstash-core/lib/logstash/plugin.rb | 29 ++++++++++++++++++++-------- 1 file changed, 21 insertions(+), 8 deletions(-) diff --git a/logstash-core/lib/logstash/plugin.rb b/logstash-core/lib/logstash/plugin.rb index 9c4d445dc59..1a46da1681e 100644 --- a/logstash-core/lib/logstash/plugin.rb +++ b/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,24 @@ 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 = self.class.logger + @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 + end # class LogStash::Plugin From b1916aa062b7fff2ba76e4311c476f36db07a49f Mon Sep 17 00:00:00 2001 From: kares Date: Tue, 27 Jul 2021 12:27:20 +0200 Subject: [PATCH 06/12] javadoc for logger methods + prepare for sub-classing --- .../java/org/logstash/log/LoggableExt.java | 6 +- .../main/java/org/logstash/log/LoggerExt.java | 112 +++++++++++++++++- 2 files changed, 109 insertions(+), 9 deletions(-) diff --git a/logstash-core/src/main/java/org/logstash/log/LoggableExt.java b/logstash-core/src/main/java/org/logstash/log/LoggableExt.java index c188b48f2ba..53cd3b97fd3 100644 --- a/logstash-core/src/main/java/org/logstash/log/LoggableExt.java +++ b/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() { @@ -67,7 +67,7 @@ public static IRubyObject deprecationLogger(final ThreadContext context, final I 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; diff --git a/logstash-core/src/main/java/org/logstash/log/LoggerExt.java b/logstash-core/src/main/java/org/logstash/log/LoggerExt.java index 9148d59f03b..a0d57a78eb6 100644 --- a/logstash-core/src/main/java/org/logstash/log/LoggerExt.java +++ b/logstash-core/src/main/java/org/logstash/log/LoggerExt.java @@ -40,16 +40,16 @@ import java.net.URI; /** - * JRuby extension, it's part of log4j wrapping for JRuby. - * Wrapper log4j Logger as Ruby like class - * */ -@JRubyClass(name = "Logger") + * JRuby extension, that wraps a (native) log4j2 logger. + * Provides a Ruby logger interface for Logstash. + */ +@JRubyClass(name = "LogStash::Logging::Logger") public class LoggerExt extends RubyObject { private static final long serialVersionUID = 1L; private static final Object CONFIG_LOCK = new Object(); - private Logger logger; + Logger logger; public LoggerExt(final Ruby runtime, final RubyClass metaClass) { super(runtime, metaClass); @@ -57,106 +57,206 @@ public LoggerExt(final Ruby runtime, final RubyClass metaClass) { @JRubyMethod public LoggerExt initialize(final ThreadContext context, final IRubyObject loggerName) { - logger = LogManager.getLogger(loggerName.asJavaString()); + initializeLogger(loggerName.asJavaString()); return this; } + void initializeLogger(final String name) { + this.logger = LogManager.getLogger(name); + } + + /** + * {@code logger.trace?} + * @param context JRuby context + * @return true/false + */ @JRubyMethod(name = "trace?") public RubyBoolean isTrace(final ThreadContext context) { return logger.isTraceEnabled() ? context.tru : context.fals; } + /** + * {@code logger.debug?} + * @param context JRuby context + * @return true/false + */ @JRubyMethod(name = "debug?") public RubyBoolean isDebug(final ThreadContext context) { return logger.isDebugEnabled() ? context.tru : context.fals; } + /** + * {@code logger.info?} + * @param context JRuby context + * @return true/false + */ @JRubyMethod(name = "info?") public RubyBoolean isInfo(final ThreadContext context) { return logger.isInfoEnabled() ? context.tru : context.fals; } + /** + * {@code logger.error?} + * @param context JRuby context + * @return true/false + */ @JRubyMethod(name = "error?") public RubyBoolean isError(final ThreadContext context) { return logger.isErrorEnabled() ? context.tru : context.fals; } + /** + * {@code logger.warn?} + * @param context JRuby context + * @return true/false + */ @JRubyMethod(name = "warn?") public RubyBoolean isWarn(final ThreadContext context) { return logger.isWarnEnabled() ? context.tru : context.fals; } + /** + * {@code logger.fatal?} + * @param context JRuby context + * @return true/false + */ @JRubyMethod(name = "fatal?") public RubyBoolean isFatal(final ThreadContext context) { return logger.isDebugEnabled() ? context.tru : context.fals; } + /** + * {@code logger.trace(msg)} + * @param msg a message to log (will be `to_s` converted) + * @return self + */ @JRubyMethod public IRubyObject trace(final IRubyObject msg) { logger.trace(msg.asString()); return this; } + /** + * {@code logger.trace(msg, data)} + * @param msg a message to log (will be `to_s` converted) + * @param data additional contextual data to be logged + * @return self + */ @JRubyMethod public IRubyObject trace(final IRubyObject msg, final IRubyObject data) { if (logger.isTraceEnabled()) logger.trace(msg.toString(), data); return this; } + /** + * {@code logger.debug(msg)} + * @param msg a message to log (will be `to_s` converted) + * @return self + */ @JRubyMethod public IRubyObject debug(final IRubyObject msg) { logger.debug(msg.asString()); return this; } + /** + * {@code logger.debug(msg, data)} + * @param msg a message to log (will be `to_s` converted) + * @param data additional contextual data to be logged + * @return self + */ @JRubyMethod public IRubyObject debug(final IRubyObject msg, final IRubyObject data) { if (logger.isDebugEnabled()) logger.debug(msg.toString(), data); return this; } + /** + * {@code logger.info(msg)} + * @param msg a message to log (will be `to_s` converted) + * @return self + */ @JRubyMethod public IRubyObject info(final IRubyObject msg) { logger.info(msg.asString()); return this; } + /** + * {@code logger.info(msg, data)} + * @param msg a message to log (will be `to_s` converted) + * @param data additional contextual data to be logged + * @return self + */ @JRubyMethod public IRubyObject info(final IRubyObject msg, final IRubyObject data) { if (logger.isInfoEnabled()) logger.info(msg.toString(), data); return this; } + /** + * {@code logger.warn(msg)} + * @param msg a message to log (will be `to_s` converted) + * @return self + */ @JRubyMethod public IRubyObject warn(final IRubyObject msg) { logger.warn(msg.asString()); return this; } + /** + * {@code logger.warn(msg, data)} + * @param msg a message to log (will be `to_s` converted) + * @param data additional contextual data to be logged + * @return self + */ @JRubyMethod public IRubyObject warn(final IRubyObject msg, final IRubyObject data) { logger.warn(msg.toString(), data); return this; } + /** + * {@code logger.error(msg)} + * @param msg a message to log (will be `to_s` converted) + * @return self + */ @JRubyMethod public IRubyObject error(final IRubyObject msg) { logger.error(msg.asString()); return this; } + /** + * {@code logger.error(msg, data)} + * @param msg a message to log (will be `to_s` converted) + * @param data additional contextual data to be logged + * @return self + */ @JRubyMethod public IRubyObject error(final IRubyObject msg, final IRubyObject data) { logger.error(msg.toString(), data); return this; } + /** + * {@code logger.fatal(msg)} + * @param msg a message to log (will be `to_s` converted) + * @return self + */ @JRubyMethod public IRubyObject fatal(final IRubyObject msg) { logger.fatal(msg.asString()); return this; } + /** + * {@code logger.fatal(msg, data)} + * @param msg a message to log (will be `to_s` converted) + * @param data additional contextual data to be logged + * @return self + */ @JRubyMethod public IRubyObject fatal(final IRubyObject msg, final IRubyObject data) { logger.fatal(msg.toString(), data); From b49c46d521ee3609f060c5aeb81f66bfcee12f79 Mon Sep 17 00:00:00 2001 From: kares Date: Tue, 27 Jul 2021 12:27:57 +0200 Subject: [PATCH 07/12] Feat: a custom logger per plugin instance --- logstash-core/lib/logstash/plugin.rb | 2 +- .../src/main/java/org/logstash/RubyUtil.java | 3 + .../org/logstash/log/PluginLoggerExt.java | 195 ++++++++++++++++++ 3 files changed, 199 insertions(+), 1 deletion(-) create mode 100644 logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java diff --git a/logstash-core/lib/logstash/plugin.rb b/logstash-core/lib/logstash/plugin.rb index 1a46da1681e..99e1de079cf 100644 --- a/logstash-core/lib/logstash/plugin.rb +++ b/logstash-core/lib/logstash/plugin.rb @@ -194,7 +194,7 @@ def execution_context private def __initialize_logging - @logger = self.class.logger + @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 diff --git a/logstash-core/src/main/java/org/logstash/RubyUtil.java b/logstash-core/src/main/java/org/logstash/RubyUtil.java index abf86480298..ba9c3b14dc2 100644 --- a/logstash-core/src/main/java/org/logstash/RubyUtil.java +++ b/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); diff --git a/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java b/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java new file mode 100644 index 00000000000..32aef1c8822 --- /dev/null +++ b/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java @@ -0,0 +1,195 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + + +package org.logstash.log; + +import org.jruby.Ruby; +import org.jruby.RubyClass; +import org.jruby.anno.JRubyMethod; +import org.jruby.anno.JRubyModule; +import org.jruby.runtime.ThreadContext; +import org.jruby.runtime.builtin.IRubyObject; + +/** + * A specialized {@link LoggerExt} that injects logging context information. + * + * Ruby interface is exactly the same as with `LogStash::Logging::Logger`. + * + * @since 7.15 + */ +@JRubyModule(name = "LogStash::Logging::PluginLogger") +public class PluginLoggerExt extends LoggerExt { + + private static final long serialVersionUID = 1L; + + static final String PLUGIN_ID_KEY = "plugin.id"; + + private String pluginId; + + public PluginLoggerExt(final Ruby runtime, final RubyClass metaClass) { + super(runtime, metaClass); + } + + @JRubyMethod + public LoggerExt initialize(final ThreadContext context, final IRubyObject plugin) { + initializeLogger(LoggableExt.log4jName(plugin.getMetaClass())); + this.pluginId = plugin.callMethod(context, "id").asJavaString(); + return this; + } + + @Override + public IRubyObject trace(final IRubyObject msg) { + if (logger.isTraceEnabled()) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.trace(msg.asString()); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + } + return this; + } + + @Override + public IRubyObject trace(final IRubyObject msg, final IRubyObject data) { + if (logger.isTraceEnabled()) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.trace(msg.toString(), data); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + } + return this; + } + + @Override + public IRubyObject debug(final IRubyObject msg) { + if (logger.isDebugEnabled()) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.debug(msg.asString()); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + } + return this; + } + + @Override + public IRubyObject debug(final IRubyObject msg, final IRubyObject data) { + if (logger.isDebugEnabled()) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.debug(msg.toString(), data); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + } + return this; + } + + @Override + public IRubyObject info(final IRubyObject msg) { + if (logger.isInfoEnabled()) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.info(msg.asString()); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + } + return this; + } + + @Override + public IRubyObject info(final IRubyObject msg, final IRubyObject data) { + if (logger.isInfoEnabled()) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.info(msg.toString(), data); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + } + return this; + } + + @Override + public IRubyObject warn(final IRubyObject msg) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.warn(msg.asString()); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + + return this; + } + + @Override + public IRubyObject warn(final IRubyObject msg, final IRubyObject data) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.warn(msg.toString(), data); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + + return this; + } + + @Override + public IRubyObject error(final IRubyObject msg) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.error(msg.asString()); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + + return this; + } + + @Override + public IRubyObject error(final IRubyObject msg, final IRubyObject data) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.error(msg.toString(), data); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + + return this; + } + + @Override + public IRubyObject fatal(final IRubyObject msg) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.fatal(msg.asString()); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + + return this; + } + + @Override + public IRubyObject fatal(final IRubyObject msg, final IRubyObject data) { + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + + logger.fatal(msg.toString(), data); + + org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + + return this; + } + +} From 1e35201aed1b27055a61d657a318b41d84cf1cb7 Mon Sep 17 00:00:00 2001 From: kares Date: Tue, 27 Jul 2021 13:55:47 +0200 Subject: [PATCH 08/12] Test: adjust spec to consider PluginLogger --- logstash-core/spec/logstash/config/mixin_spec.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logstash-core/spec/logstash/config/mixin_spec.rb b/logstash-core/spec/logstash/config/mixin_spec.rb index 7928409bb5e..2ab91ed744b 100644 --- a/logstash-core/spec/logstash/config/mixin_spec.rb +++ b/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) From 8d2c4e1f04d6f020a088049ef450b51ec0fd6a94 Mon Sep 17 00:00:00 2001 From: kares Date: Wed, 28 Jul 2021 15:02:00 +0200 Subject: [PATCH 09/12] Chore: keep a todo for plugin.class.logger method --- logstash-core/lib/logstash/plugin.rb | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/logstash-core/lib/logstash/plugin.rb b/logstash-core/lib/logstash/plugin.rb index 99e1de079cf..6f7330fcb4f 100644 --- a/logstash-core/lib/logstash/plugin.rb +++ b/logstash-core/lib/logstash/plugin.rb @@ -204,4 +204,12 @@ def __initialize_logging 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 From d9ec497f3099aa65e5bade5df90dae0b56556d54 Mon Sep 17 00:00:00 2001 From: kares Date: Wed, 4 Aug 2021 13:47:44 +0200 Subject: [PATCH 10/12] only set plugin.id if isn't already set ... for restore to keep the previously set id --- .../org/logstash/log/PluginLoggerExt.java | 59 +++++++++++-------- 1 file changed, 35 insertions(+), 24 deletions(-) diff --git a/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java b/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java index 32aef1c8822..9ad2bef5a1e 100644 --- a/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java +++ b/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java @@ -57,11 +57,11 @@ public LoggerExt initialize(final ThreadContext context, final IRubyObject plugi @Override public IRubyObject trace(final IRubyObject msg) { if (logger.isTraceEnabled()) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.trace(msg.asString()); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); } return this; } @@ -69,11 +69,11 @@ public IRubyObject trace(final IRubyObject msg) { @Override public IRubyObject trace(final IRubyObject msg, final IRubyObject data) { if (logger.isTraceEnabled()) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.trace(msg.toString(), data); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); } return this; } @@ -81,11 +81,11 @@ public IRubyObject trace(final IRubyObject msg, final IRubyObject data) { @Override public IRubyObject debug(final IRubyObject msg) { if (logger.isDebugEnabled()) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.debug(msg.asString()); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); } return this; } @@ -93,11 +93,11 @@ public IRubyObject debug(final IRubyObject msg) { @Override public IRubyObject debug(final IRubyObject msg, final IRubyObject data) { if (logger.isDebugEnabled()) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.debug(msg.toString(), data); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); } return this; } @@ -105,11 +105,11 @@ public IRubyObject debug(final IRubyObject msg, final IRubyObject data) { @Override public IRubyObject info(final IRubyObject msg) { if (logger.isInfoEnabled()) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.info(msg.asString()); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); } return this; } @@ -117,79 +117,90 @@ public IRubyObject info(final IRubyObject msg) { @Override public IRubyObject info(final IRubyObject msg, final IRubyObject data) { if (logger.isInfoEnabled()) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.info(msg.toString(), data); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); } return this; } @Override public IRubyObject warn(final IRubyObject msg) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.warn(msg.asString()); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); return this; } @Override public IRubyObject warn(final IRubyObject msg, final IRubyObject data) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.warn(msg.toString(), data); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); return this; } @Override public IRubyObject error(final IRubyObject msg) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.error(msg.asString()); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); return this; } @Override public IRubyObject error(final IRubyObject msg, final IRubyObject data) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.error(msg.toString(), data); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); return this; } @Override public IRubyObject fatal(final IRubyObject msg) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.fatal(msg.asString()); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); return this; } @Override public IRubyObject fatal(final IRubyObject msg, final IRubyObject data) { - org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + boolean didSet = setPluginId(pluginId); logger.fatal(msg.toString(), data); - org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + removePluginId(didSet); return this; } + private static boolean setPluginId(final String pluginId) { + boolean found = org.apache.logging.log4j.ThreadContext.containsKey(PLUGIN_ID_KEY); + if (found) return false; + org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); + return false; + } + + private static void removePluginId(final boolean didSet) { + if (didSet) org.apache.logging.log4j.ThreadContext.remove(PLUGIN_ID_KEY); + } + } From 2687121d9bdf5455a9006607fa27735a240e62e3 Mon Sep 17 00:00:00 2001 From: kares Date: Thu, 2 Sep 2021 13:16:21 +0200 Subject: [PATCH 11/12] Fix: wrong condition (boolean) return --- .../src/main/java/org/logstash/log/PluginLoggerExt.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java b/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java index 9ad2bef5a1e..30010d2cac5 100644 --- a/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java +++ b/logstash-core/src/main/java/org/logstash/log/PluginLoggerExt.java @@ -196,7 +196,7 @@ private static boolean setPluginId(final String pluginId) { boolean found = org.apache.logging.log4j.ThreadContext.containsKey(PLUGIN_ID_KEY); if (found) return false; org.apache.logging.log4j.ThreadContext.put(PLUGIN_ID_KEY, pluginId); - return false; + return true; } private static void removePluginId(final boolean didSet) { From 11ac7f930331a17ff761f172a3195683b9c07ad6 Mon Sep 17 00:00:00 2001 From: kares Date: Thu, 2 Sep 2021 19:29:30 +0200 Subject: [PATCH 12/12] a quick plugin.logger (context restoration) test --- logstash-core/spec/logstash/plugin_spec.rb | 44 +++++++++++++++++++ .../main/java/org/logstash/log/LoggerExt.java | 11 +++++ 2 files changed, 55 insertions(+) diff --git a/logstash-core/spec/logstash/plugin_spec.rb b/logstash-core/spec/logstash/plugin_spec.rb index 1656a3855b6..34aea4732b3 100644 --- a/logstash-core/spec/logstash/plugin_spec.rb +++ b/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 { diff --git a/logstash-core/src/main/java/org/logstash/log/LoggerExt.java b/logstash-core/src/main/java/org/logstash/log/LoggerExt.java index a0d57a78eb6..eefdb57f5d0 100644 --- a/logstash-core/src/main/java/org/logstash/log/LoggerExt.java +++ b/logstash-core/src/main/java/org/logstash/log/LoggerExt.java @@ -30,6 +30,7 @@ import org.jruby.RubyBoolean; import org.jruby.RubyClass; import org.jruby.RubyObject; +import org.jruby.RubyString; import org.jruby.anno.JRubyClass; import org.jruby.anno.JRubyMethod; import org.jruby.javasupport.JavaUtil; @@ -335,4 +336,14 @@ private static void setLevel(String level, String loggerPath) { } } + /** + * Retrieve this logger's name. + * @param context current context + * @return the name + */ + @JRubyMethod(name = "name") + public RubyString name(final ThreadContext context) { + return context.runtime.newString(logger.getName()); + } + }