This is an automated email from the ASF dual-hosted git repository. mmiklavcic pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/metron.git
The following commit(s) were added to refs/heads/master by this push: new 771d66b METRON-2195 Add defensive log level checks when constructing logs is expensive (tigerquoll via mmiklavc) closes apache/metron#1473 771d66b is described below commit 771d66b5a806f9c0f1c53c1782977e00fa26917a Author: tigerquoll <tigerqu...@outlook.com> AuthorDate: Mon Aug 5 10:16:19 2019 -0600 METRON-2195 Add defensive log level checks when constructing logs is expensive (tigerquoll via mmiklavc) closes apache/metron#1473 --- .../spark/function/MessageRouterFunction.java | 9 +- .../metron/rest/generator/SampleDataGenerator.java | 2 +- .../enrichment/SensorEnrichmentUpdateConfig.java | 8 +- .../metron/common/hadoop/SequenceFileIterable.java | 10 +- .../org/apache/metron/common/utils/LazyLogger.java | 94 +++ .../metron/common/utils/LazyLoggerFactory.java | 71 ++ .../apache/metron/common/utils/LazyLoggerImpl.java | 572 ++++++++++++++++ .../configurations/ConfigurationsUpdater.java | 10 +- .../metron/common/utils/LazyLoggerImplTest.java | 759 +++++++++++++++++++++ .../common/utils/LazzyLoggerImplPerfTest.java | 118 ++++ .../adapters/simplehbase/SimpleHBaseAdapter.java | 8 +- .../adapters/stellar/StellarAdapter.java | 2 +- .../java/org/apache/metron/parsers/GrokParser.java | 11 +- .../apache/metron/parsers/asa/BasicAsaParser.java | 12 +- .../apache/metron/parsers/bro/BasicBroParser.java | 8 +- .../java/org/apache/metron/pcap/mr/PcapJob.java | 9 +- .../apache/metron/pcap/utils/FileFilterUtil.java | 12 +- .../writer/hbase/SimpleHbaseEnrichmentWriter.java | 19 +- .../org/apache/metron/writer/hdfs/HdfsWriter.java | 13 +- .../apache/metron/writer/hdfs/SourceHandler.java | 8 +- 20 files changed, 1686 insertions(+), 69 deletions(-) diff --git a/metron-analytics/metron-profiler-spark/src/main/java/org/apache/metron/profiler/spark/function/MessageRouterFunction.java b/metron-analytics/metron-profiler-spark/src/main/java/org/apache/metron/profiler/spark/function/MessageRouterFunction.java index 31734d0..f38ed3b 100644 --- a/metron-analytics/metron-profiler-spark/src/main/java/org/apache/metron/profiler/spark/function/MessageRouterFunction.java +++ b/metron-analytics/metron-profiler-spark/src/main/java/org/apache/metron/profiler/spark/function/MessageRouterFunction.java @@ -20,6 +20,8 @@ package org.apache.metron.profiler.spark.function; import org.apache.metron.common.configuration.profiler.ProfilerConfig; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.profiler.DefaultMessageRouter; import org.apache.metron.profiler.MessageRoute; import org.apache.metron.profiler.MessageRouter; @@ -27,12 +29,9 @@ import org.apache.metron.profiler.clock.Clock; import org.apache.metron.profiler.clock.ClockFactory; import org.apache.metron.profiler.clock.EventTimeOnlyClockFactory; import org.apache.metron.stellar.dsl.Context; -import org.apache.metron.stellar.dsl.StellarFunctions; import org.apache.spark.api.java.function.FlatMapFunction; import org.json.simple.JSONObject; import org.json.simple.parser.JSONParser; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import java.lang.invoke.MethodHandles; import java.util.Collections; @@ -46,7 +45,7 @@ import java.util.Optional; */ public class MessageRouterFunction implements FlatMapFunction<String, MessageRoute> { - protected static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + protected static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); /** * The global configuration used for the execution of Stellar. @@ -112,7 +111,7 @@ public class MessageRouterFunction implements FlatMapFunction<String, MessageRou LOG.trace("Found {} route(s) for a message", routes.size()); } else { - LOG.trace("Ignoring message; timestamp={} not in [{},{}]", timestamp, prettyPrint(begin), prettyPrint(end)); + LOG.trace("Ignoring message; timestamp={} not in [{},{}]", () -> timestamp, () -> prettyPrint(begin), () -> prettyPrint(end)); } } else { diff --git a/metron-interface/metron-rest/src/test/java/org/apache/metron/rest/generator/SampleDataGenerator.java b/metron-interface/metron-rest/src/test/java/org/apache/metron/rest/generator/SampleDataGenerator.java index 8557035..2a5db30 100644 --- a/metron-interface/metron-rest/src/test/java/org/apache/metron/rest/generator/SampleDataGenerator.java +++ b/metron-interface/metron-rest/src/test/java/org/apache/metron/rest/generator/SampleDataGenerator.java @@ -138,7 +138,7 @@ public class SampleDataGenerator { } catch (InterruptedException e) { e.printStackTrace(); } - LOG.info("Emitting " + sensorType + " message " + message); + LOG.info("Emitting {} message {}", sensorType, message); emitToKafka(sensorType, message); } diff --git a/metron-platform/metron-common/src/main/java/org/apache/metron/common/configuration/enrichment/SensorEnrichmentUpdateConfig.java b/metron-platform/metron-common/src/main/java/org/apache/metron/common/configuration/enrichment/SensorEnrichmentUpdateConfig.java index f55957b..08bd629 100644 --- a/metron-platform/metron-common/src/main/java/org/apache/metron/common/configuration/enrichment/SensorEnrichmentUpdateConfig.java +++ b/metron-platform/metron-common/src/main/java/org/apache/metron/common/configuration/enrichment/SensorEnrichmentUpdateConfig.java @@ -28,13 +28,13 @@ import java.util.Map; import org.apache.curator.framework.CuratorFramework; import org.apache.metron.common.Constants; import org.apache.metron.common.configuration.ConfigurationsUtils; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.zookeeper.KeeperException; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; public class SensorEnrichmentUpdateConfig { - protected static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + protected static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); public static class FieldList { Type type; @@ -185,7 +185,7 @@ public class SensorEnrichmentUpdateConfig { } //adding only the ones that we don't already have to the field list if (additionalFields.size() > 0) { - LOG.debug("Adding additional fields: {}", Joiner.on(',').join(additionalFields)); + LOG.debug("Adding additional fields: {}", () -> Joiner.on(',').join(additionalFields)); fieldList.addAll(additionalFields); sourceConfigsChanged.put(kv.getKey(), config); } diff --git a/metron-platform/metron-common/src/main/java/org/apache/metron/common/hadoop/SequenceFileIterable.java b/metron-platform/metron-common/src/main/java/org/apache/metron/common/hadoop/SequenceFileIterable.java index fa666eb..17f2fc7 100644 --- a/metron-platform/metron-common/src/main/java/org/apache/metron/common/hadoop/SequenceFileIterable.java +++ b/metron-platform/metron-common/src/main/java/org/apache/metron/common/hadoop/SequenceFileIterable.java @@ -30,11 +30,11 @@ import org.apache.hadoop.fs.Path; import org.apache.hadoop.io.BytesWritable; import org.apache.hadoop.io.LongWritable; import org.apache.hadoop.io.SequenceFile; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; public class SequenceFileIterable implements Iterable<byte[]> { - private static final Logger LOGGER = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + private static final LazyLogger LOGGER = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); private List<Path> files; private Configuration config; @@ -86,7 +86,7 @@ public class SequenceFileIterable implements Iterable<byte[]> { if (!finished && null == reader) { try { reader = new SequenceFile.Reader(config, SequenceFile.Reader.file(path)); - LOGGER.debug("Writing file: {}", path.toString()); + LOGGER.debug("Writing file: {}", () -> path.toString()); } catch (IOException e) { throw new RuntimeException("Failed to get reader", e); } @@ -110,7 +110,7 @@ public class SequenceFileIterable implements Iterable<byte[]> { } private void close() { - LOGGER.debug("Closing file: {}", path.toString()); + LOGGER.debug("Closing file: {}", () -> path.toString()); finished = true; try { if (reader != null) { diff --git a/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLogger.java b/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLogger.java new file mode 100644 index 0000000..8a98418 --- /dev/null +++ b/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLogger.java @@ -0,0 +1,94 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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 + * <p> + * http://www.apache.org/licenses/LICENSE-2.0 + * <p> + * 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.apache.metron.common.utils; + +import org.slf4j.Logger; +import org.slf4j.Marker; + +import java.util.function.Supplier; + +/** + * Extension of a Logger interface that supports lazy argument evaluation + * Useful when some arguments are costly to evaluate, and you only want to incur + * that cost if the logging level is actually enabled. + * + * Please note this interface is a temporary measure until the move to use SLF4J 2.x + */ +public interface LazyLogger extends Logger { + Logger getLogger(); + + void trace(String format, Supplier<Object> arg); + + void trace(String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void trace(String format, Supplier<Object>... arguments); + + void trace(Marker marker, String format, Supplier<Object> arg); + + void trace(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void trace(Marker marker, String format, Supplier<Object>... arguments); + + void debug(String format, Supplier<Object> arg); + + void debug(String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void debug(String format, Supplier<Object>... arguments); + + void debug(Marker marker, String format, Supplier<Object> arg); + + void debug(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void debug(Marker marker, String format, Supplier<Object>... arguments); + + void info(String format, Supplier<Object> arg); + + void info(String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void info(String format, Supplier<Object>... arguments); + + void info(Marker marker, String format, Supplier<Object> arg); + + void info(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void info(Marker marker, String format, Supplier<Object>... arguments); + + void warn(String format, Supplier<Object> arg); + + void warn(String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void warn(String format, Supplier<Object>... arguments); + + void warn(Marker marker, String format, Supplier<Object> arg); + + void warn(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void warn(Marker marker, String format, Supplier<Object>... arguments); + + void error(String format, Supplier<Object> arg); + + void error(String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void error(String format, Supplier<Object>... arguments); + + void error(Marker marker, String format, Supplier<Object> arg); + + void error(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2); + + void error(Marker marker, String format, Supplier<Object>... arguments); +} diff --git a/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLoggerFactory.java b/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLoggerFactory.java new file mode 100644 index 0000000..d536cde --- /dev/null +++ b/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLoggerFactory.java @@ -0,0 +1,71 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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 + * <p> + * http://www.apache.org/licenses/LICENSE-2.0 + * <p> + * 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.apache.metron.common.utils; + +import org.slf4j.ILoggerFactory; +import org.slf4j.Logger; + +/** + * Factory class for a logger wrapper that supports lazy evaluation of arguments + * Useful when some arguments are costly to evaluate, and you only want to incur + * that cost if the logging level is actually enabled. + */ +public class LazyLoggerFactory { + /** + * Return a logger named according to the name parameter using the statically + * bound {@link ILoggerFactory} instance. + * + * @param name The name of the logger. + * @return logger + */ + public static LazyLogger getLogger(String name) { + final Logger logger = org.slf4j.LoggerFactory.getLogger(name); + if (logger != null) { // explicit NP check to remove guava dependency + return new LazyLoggerImpl(logger); + } else { + throw new NullPointerException(String.format("Logger not returned for class %s", + name == null ? "Null String" : name)); + } + } + + /** + * Return a logger named corresponding to the class passed as parameter, using + * the statically bound {@link ILoggerFactory} instance. + * + * @param clazz the returned logger will be named after clazz + * @return logger + */ + public static LazyLogger getLogger(Class clazz) { + return getLogger(clazz.getName()); + } + + + /** + * Return a lazylogger wrapping the passed Logger instance + * + * @param logger the returned logger will be named after clazz + * @return logger + */ + public static LazyLogger getLogger(Logger logger) { + if (logger != null) { + return new LazyLoggerImpl(logger); + } else { + throw new NullPointerException("Null logger passed"); + } + } +} diff --git a/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLoggerImpl.java b/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLoggerImpl.java new file mode 100644 index 0000000..e7d57db --- /dev/null +++ b/metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLoggerImpl.java @@ -0,0 +1,572 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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 + * <p> + * http://www.apache.org/licenses/LICENSE-2.0 + * <p> + * 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.apache.metron.common.utils; + +import org.slf4j.Logger; +import org.slf4j.Marker; + +import java.util.Arrays; +import java.util.function.Supplier; + +/** + * Wrapper class around a slf4j Logger interface that adds lazy evaluated method arguments + * Useful when some arguments are costly to evaluate, and you only want to incur + * that cost if the logging level is actually enabled. + * We can tag parameterised varargs arguments as safe here because we only assume they are Objects + */ +public class LazyLoggerImpl implements LazyLogger { + private final Logger logger; + + LazyLoggerImpl(final Logger logger) { + if (logger != null) { // Explicitly NP check to remove Guava as a dependency + this.logger = logger; + } else { + throw new NullPointerException("Null logger passed"); + } + } + + @Override + public Logger getLogger() { + return logger; + } + + @Override + public String getName() { + return logger.getName(); + } + + @Override + public boolean isTraceEnabled() { + return logger.isTraceEnabled(); + } + + @Override + public void trace(String msg) { + logger.trace(msg); + } + + @Override + public void trace(String format, Object arg) { + logger.trace(format, arg); + } + + @Override + public void trace(String format, Supplier<Object> arg) { + if (logger.isTraceEnabled()) { + logger.trace(format, arg.get()); + } + } + + @Override + public void trace(String format, Object arg1, Object arg2) { + logger.trace(format, arg1, arg2); + } + + @Override + public void trace(String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isTraceEnabled()) { + logger.trace(format, arg1.get(), arg2.get()); + } + } + + @Override + public void trace(String format, Object... arguments) { + logger.trace(format, arguments); + } + + @Override + @SafeVarargs + public final void trace(String format, Supplier<Object>... arguments) { + if (logger.isTraceEnabled()) { + logger.trace(format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void trace(String msg, Throwable t) { + logger.trace(msg, t); + } + + @Override + public boolean isTraceEnabled(Marker marker) { + return logger.isTraceEnabled(marker); + } + + @Override + public void trace(Marker marker, String msg) { + logger.trace(marker, msg); + } + + @Override + public void trace(Marker marker, String format, Object arg) { + logger.trace(marker, format, arg); + } + + @Override + public void trace(Marker marker, String format, Supplier<Object> arg) { + if (logger.isTraceEnabled(marker)) { + logger.trace(marker, format, arg.get()); + } + } + + @Override + public void trace(Marker marker, String format, Object arg1, Object arg2) { + logger.trace(marker, format, arg1, arg2); + } + + @Override + public void trace(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isTraceEnabled(marker)) { + logger.trace(marker, format, arg1.get(), arg2.get()); + } + } + + @Override + public void trace(Marker marker, String format, Object... arguments) { + logger.trace(marker, format, arguments); + } + + @Override + @SafeVarargs + public final void trace(Marker marker, String format, Supplier<Object>... arguments) { + if (logger.isTraceEnabled(marker)) { + logger.trace(marker, format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void trace(Marker marker, String msg, Throwable t) { + logger.trace(marker, msg, t); + } + + @Override + public boolean isDebugEnabled() { + return logger.isDebugEnabled(); + } + + @Override + public void debug(String msg) { + logger.debug(msg); + } + + @Override + public void debug(String format, Object arg) { + logger.debug(format, arg); + } + + @Override + public void debug(String format, Supplier<Object> arg) { + if (logger.isDebugEnabled()) { + logger.debug(format, arg.get()); + } + } + + @Override + public void debug(String format, Object arg1, Object arg2) { + logger.debug(format, arg1, arg2); + } + + @Override + public void debug(String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isDebugEnabled()) { + logger.debug(format, arg1.get(), arg2.get()); + } + } + + @Override + public void debug(String format, Object... arguments) { + logger.debug(format, arguments); + } + + @Override + @SafeVarargs + public final void debug(String format, Supplier<Object>... arguments) { + if (logger.isDebugEnabled()) { + logger.debug(format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void debug(String msg, Throwable t) { + logger.debug(msg, t); + } + + @Override + public boolean isDebugEnabled(Marker marker) { + return logger.isDebugEnabled(marker); + } + + @Override + public void debug(Marker marker, String msg) { + logger.debug(marker, msg); + } + + @Override + public void debug(Marker marker, String format, Object arg) { + logger.debug(marker, format, arg); + } + + @Override + public void debug(Marker marker, String format, Supplier<Object> arg) { + if (logger.isDebugEnabled(marker)) { + logger.debug(marker, format, arg.get()); + } + } + + @Override + public void debug(Marker marker, String format, Object arg1, Object arg2) { + logger.debug(marker, format, arg1, arg2); + } + + @Override + public void debug(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isDebugEnabled(marker)) { + logger.debug(marker, format, arg1.get(), arg2.get()); + } + } + + @Override + public void debug(Marker marker, String format, Object... arguments) { + logger.debug(marker, format, arguments); + } + + @Override + @SafeVarargs + public final void debug(Marker marker, String format, Supplier<Object>... arguments) { + if (logger.isDebugEnabled(marker)) { + logger.debug(marker, format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void debug(Marker marker, String msg, Throwable t) { + logger.debug(marker, msg, t); + } + + @Override + public boolean isInfoEnabled() { + return logger.isInfoEnabled(); + } + + @Override + public void info(String msg) { + logger.info(msg); + } + + @Override + public void info(String format, Object arg) { + logger.info(format, arg); + } + + @Override + public void info(String format, Supplier<Object> arg) { + if (logger.isInfoEnabled()) { + logger.info(format, arg.get()); + } + } + + @Override + public void info(String format, Object arg1, Object arg2) { + logger.info(format, arg1, arg2); + } + + @Override + public void info(String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isInfoEnabled()) { + logger.info(format, arg1.get(), arg2.get()); + } + } + + @Override + public void info(String format, Object... arguments) { + logger.info(format, arguments); + } + + @Override + @SafeVarargs + public final void info(String format, Supplier<Object>... arguments) { + if (logger.isInfoEnabled()) { + logger.info(format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void info(String msg, Throwable t) { + logger.info(msg, t); + } + + @Override + public boolean isInfoEnabled(Marker marker) { + return logger.isInfoEnabled(marker); + } + + @Override + public void info(Marker marker, String msg) { + logger.info(marker, msg); + } + + @Override + public void info(Marker marker, String format, Object arg) { + logger.info(marker, format, arg); + } + + @Override + public void info(Marker marker, String format, Supplier<Object> arg) { + if (logger.isInfoEnabled(marker)) { + logger.info(marker, format, arg.get()); + } + } + + @Override + public void info(Marker marker, String format, Object arg1, Object arg2) { + logger.info(marker, format, arg1, arg2); + } + + @Override + public void info(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isInfoEnabled(marker)) { + logger.info(marker, format, arg1.get(), arg2.get()); + } + } + + @Override + public void info(Marker marker, String format, Object... arguments) { + logger.info(marker, format, arguments); + } + + @Override + @SafeVarargs + public final void info(Marker marker, String format, Supplier<Object>... arguments) { + if (logger.isInfoEnabled(marker)) { + logger.info(marker, format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void info(Marker marker, String msg, Throwable t) { + logger.info(marker, msg, t); + } + + @Override + public boolean isWarnEnabled() { + return logger.isWarnEnabled(); + } + + @Override + public void warn(String msg) { + logger.warn(msg); + } + + @Override + public void warn(String format, Object arg) { + logger.warn(format, arg); + } + + @Override + public void warn(String format, Supplier<Object> arg) { + if (logger.isWarnEnabled()) { + logger.warn(format, arg.get()); + } + } + + @Override + public void warn(String format, Object... arguments) { + logger.warn(format, arguments); + } + + @Override + @SafeVarargs + public final void warn(String format, Supplier<Object>... arguments) { + if (logger.isWarnEnabled()) { + logger.warn(format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void warn(String format, Object arg1, Object arg2) { + logger.warn(format, arg1, arg2); + } + + @Override + public void warn(String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isWarnEnabled()) { + logger.warn(format, arg1.get(), arg2.get()); + } + } + + @Override + public void warn(String msg, Throwable t) { + logger.warn(msg, t); + } + + @Override + public boolean isWarnEnabled(Marker marker) { + return logger.isWarnEnabled(marker); + } + + @Override + public void warn(Marker marker, String msg) { + logger.warn(marker, msg); + } + + @Override + public void warn(Marker marker, String format, Object arg) { + logger.warn(marker, format, arg); + } + + @Override + public void warn(Marker marker, String format, Supplier<Object> arg) { + if (logger.isWarnEnabled(marker)) { + logger.warn(marker, format, arg.get()); + } + } + + @Override + public void warn(Marker marker, String format, Object arg1, Object arg2) { + logger.warn(marker, format, arg1, arg2); + } + + @Override + public void warn(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isWarnEnabled(marker)) { + logger.warn(marker, format, arg1.get(), arg2.get()); + } + } + + @Override + public void warn(Marker marker, String format, Object... arguments) { + logger.warn(marker, format, arguments); + } + + @Override + @SafeVarargs + public final void warn(Marker marker, String format, Supplier<Object>... arguments) { + if (logger.isWarnEnabled(marker)) { + logger.warn(marker, format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void warn(Marker marker, String msg, Throwable t) { + logger.warn(marker, msg, t); + } + + @Override + public boolean isErrorEnabled() { + return logger.isErrorEnabled(); + } + + @Override + public void error(String msg) { + logger.error(msg); + } + + @Override + public void error(String format, Object arg) { + logger.error(format, arg); + } + + @Override + public void error(String format, Supplier<Object> arg) { + if (logger.isErrorEnabled()) { + logger.error(format, arg.get()); + } + } + + @Override + public void error(String format, Object arg1, Object arg2) { + logger.error(format, arg1, arg2); + } + + @Override + public void error(String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isErrorEnabled()) { + logger.error(format, arg1.get(), arg2.get()); + } + } + + @Override + public void error(String format, Object... arguments) { + logger.error(format, arguments); + } + + @Override + @SafeVarargs + public final void error(String format, Supplier<Object>... arguments) { + if (logger.isErrorEnabled()) { + logger.error(format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void error(String msg, Throwable t) { + logger.error(msg, t); + } + + @Override + public boolean isErrorEnabled(Marker marker) { + return logger.isErrorEnabled(marker); + } + + @Override + public void error(Marker marker, String msg) { + logger.error(marker, msg); + } + + @Override + public void error(Marker marker, String format, Object arg) { + logger.error(marker, format, arg); + } + + @Override + public void error(Marker marker, String format, Supplier<Object> arg) { + if (logger.isErrorEnabled(marker)) { + logger.error(marker, format, arg.get()); + } + } + + @Override + public void error(Marker marker, String format, Object arg1, Object arg2) { + logger.error(marker, format, arg1, arg2); + } + + @Override + public final void error(Marker marker, String format, Supplier<Object> arg1, Supplier<Object> arg2) { + if (logger.isErrorEnabled(marker)) { + logger.error(marker, format, arg1.get(), arg2.get()); + } + } + + @Override + public void error(Marker marker, String format, Object... arguments) { + logger.error(marker, format, arguments); + } + + @Override + @SafeVarargs + public final void error(Marker marker, String format, Supplier<Object>... arguments) { + if (logger.isErrorEnabled(marker)) { + logger.error(marker, format, Arrays.stream(arguments).map(Supplier::get).toArray()); + } + } + + @Override + public void error(Marker marker, String msg, Throwable t) { + logger.error(marker, msg, t); + } +} diff --git a/metron-platform/metron-common/src/main/java/org/apache/metron/common/zookeeper/configurations/ConfigurationsUpdater.java b/metron-platform/metron-common/src/main/java/org/apache/metron/common/zookeeper/configurations/ConfigurationsUpdater.java index 235586e..53aedd7 100644 --- a/metron-platform/metron-common/src/main/java/org/apache/metron/common/zookeeper/configurations/ConfigurationsUpdater.java +++ b/metron-platform/metron-common/src/main/java/org/apache/metron/common/zookeeper/configurations/ConfigurationsUpdater.java @@ -20,8 +20,8 @@ package org.apache.metron.common.zookeeper.configurations; import org.apache.curator.framework.CuratorFramework; import org.apache.metron.common.configuration.ConfigurationType; import org.apache.metron.common.configuration.Configurations; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import java.io.IOException; import java.io.Serializable; @@ -36,7 +36,7 @@ import java.util.function.Supplier; * @param <T> the Type of Configuration */ public abstract class ConfigurationsUpdater<T extends Configurations> implements Serializable { - protected static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + protected static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); private Reloadable reloadable; private Supplier<T> configSupplier; @@ -65,11 +65,11 @@ public abstract class ConfigurationsUpdater<T extends Configurations> implements if (data.length != 0) { String name = path.substring(path.lastIndexOf("/") + 1); if (path.startsWith(getType().getZookeeperRoot())) { - LOG.debug("Updating the {} config: {} -> {}", getType().name(), name, new String(data == null?"".getBytes():data)); + LOG.debug("Updating the {} config: {} -> {}", () -> getType().name(), () -> name, () -> new String(data == null?"".getBytes():data)); update(name, data); reloadCallback(name, getType()); } else if (ConfigurationType.GLOBAL.getZookeeperRoot().equals(path)) { - LOG.debug("Updating the global config: {}", new String(data == null?"".getBytes():data)); + LOG.debug("Updating the global config: {}", () -> new String(data == null?"".getBytes():data)); getConfigurations().updateGlobalConfig(data); reloadCallback(name, ConfigurationType.GLOBAL); } diff --git a/metron-platform/metron-common/src/test/java/org/apache/metron/common/utils/LazyLoggerImplTest.java b/metron-platform/metron-common/src/test/java/org/apache/metron/common/utils/LazyLoggerImplTest.java new file mode 100644 index 0000000..7402c85 --- /dev/null +++ b/metron-platform/metron-common/src/test/java/org/apache/metron/common/utils/LazyLoggerImplTest.java @@ -0,0 +1,759 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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 + * <p> + * http://www.apache.org/licenses/LICENSE-2.0 + * <p> + * 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.apache.metron.common.utils; + +import org.junit.Rule; +import org.junit.Test; +import org.mockito.Mockito; +import org.mockito.junit.MockitoJUnit; +import org.mockito.junit.MockitoRule; +import org.slf4j.Logger; +import org.slf4j.Marker; + +import java.util.Iterator; +import java.util.List; +import java.util.UUID; +import java.util.function.Supplier; +import java.util.stream.Collectors; +import java.util.stream.IntStream; + +import static org.mockito.Mockito.*; + +/** + * This set of mocking tests checks that + * 1. If the log level is disabled then no lambda function is called + * 2. If the log level is enabled, then all passed lamdas are called and parmeters are passed in the correct order + * 3. All methods call their wrapped messages correctly + */ +public class LazyLoggerImplTest { + private static final String logString0 = "logString"; + private static final String logString1 = "logString {}"; + private static final String logString2 = "logString {} {}"; + private static final String logString3 = "logString {} {} {}"; + + // stub Marker + private static final Marker marker = new Marker() { + @Override + public String getName() { + return null; + } + + @Override + public void add(Marker reference) { + + } + + @Override + public boolean remove(Marker reference) { + return false; + } + + @Override + public boolean hasChildren() { + return false; + } + + @Override + public boolean hasReferences() { + return false; + } + + @Override + public Iterator<Marker> iterator() { + return null; + } + + @Override + public boolean contains(Marker other) { + return false; + } + + @Override + public boolean contains(String name) { + return false; + } + }; + + // Stub Exception + private static final Exception exception = new Exception(); + + @Rule + public MockitoRule mockitoRule = MockitoJUnit.rule(); + + private List<UUID> getGuids(int numGuids) { + return IntStream.range(0,numGuids) + .mapToObj( x -> UUID.randomUUID()) + .collect(Collectors.toList()); + } + + private LazyLogger getDisabledLogger() { + final Logger loggerMock = mock(Logger.class); + return LazyLoggerFactory.getLogger(loggerMock); + } + + private LazyLogger getTraceEnabledLogger() { + final LazyLogger lazyLogger = getDisabledLogger(); + Mockito.when(lazyLogger.getLogger().isTraceEnabled()).thenReturn(true); + Mockito.when(lazyLogger.getLogger().isTraceEnabled(any(Marker.class))).thenReturn(true); + return lazyLogger; + } + + private LazyLogger getDebugEnabledLogger() { + final LazyLogger lazyLogger = getDisabledLogger(); + Mockito.when(lazyLogger.getLogger().isDebugEnabled()).thenReturn(true); + Mockito.when(lazyLogger.getLogger().isDebugEnabled(any(Marker.class))).thenReturn(true); + return lazyLogger; + } + + private LazyLogger getInfoEnabledLogger() { + final LazyLogger lazyLogger = getDisabledLogger(); + Mockito.when(lazyLogger.getLogger().isInfoEnabled()).thenReturn(true); + Mockito.when(lazyLogger.getLogger().isInfoEnabled(any(Marker.class))).thenReturn(true); + return lazyLogger; + } + + private LazyLogger getWarnEnabledLogger() { + final LazyLogger lazyLogger = getDisabledLogger(); + Mockito.when(lazyLogger.getLogger().isWarnEnabled()).thenReturn(true); + Mockito.when(lazyLogger.getLogger().isWarnEnabled(any(Marker.class))).thenReturn(true); + return lazyLogger; + } + + private LazyLogger getErrorEnabledLogger() { + final LazyLogger lazyLogger = getDisabledLogger(); + Mockito.when(lazyLogger.getLogger().isErrorEnabled()).thenReturn(true); + Mockito.when(lazyLogger.getLogger().isErrorEnabled(any(Marker.class))).thenReturn(true); + return lazyLogger; + } + + @SuppressWarnings("unchecked") // We assume all objects are of type Object + private Supplier<Object> getMockedSupplier() { + return mock(Supplier.class); + } + + + @Test + public void traceEnabled1() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getTraceEnabledLogger(); + logger.isTraceEnabled(); + Mockito.verify(logger.getLogger()).isTraceEnabled(); + + logger.isTraceEnabled(marker); + Mockito.verify(logger.getLogger()).isTraceEnabled(marker); + + logger.trace(logString0); + Mockito.verify(logger.getLogger()).trace(logString0); + + logger.trace(logString0, exception); + Mockito.verify(logger.getLogger()).trace(logString0,exception); + + logger.trace(logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).trace(logString1, guids.get(0)); + + logger.trace(marker, logString0); + Mockito.verify(logger.getLogger()).trace(marker, logString0); + + logger.trace(marker, logString0, exception); + Mockito.verify(logger.getLogger()).trace(marker, logString0, exception); + + logger.trace(marker, logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).trace(marker, logString1, guids.get(0)); + + } + + @Test + public void traceEnabled1Lambda() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getTraceEnabledLogger(); + logger.trace(logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).trace(logString1, guids.get(0)); + + logger.trace(marker, logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).trace(marker, logString1, guids.get(0)); + } + + @Test + public void traceDisabled1Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.trace(logString1, supplier); + Mockito.verify(supplier, never()).get(); + + logger.trace(marker, logString1, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void traceEnabled2() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getTraceEnabledLogger(); + logger.trace(logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()) + .trace(logString2, guids.get(0), guids.get(1)); + + logger.trace(marker, logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()) + .trace(marker, logString2, guids.get(0), guids.get(1)); + } + + @Test + public void traceEnabled2Lambda() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getTraceEnabledLogger(); + logger.trace(logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).trace(logString2, guids.get(0), guids.get(1)); + + logger.trace(marker, logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).trace(marker, logString2, guids.get(0), guids.get(1)); + } + + @Test + public void traceDisabled2Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + + logger.trace(logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.trace(marker, logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void traceEnabled3() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getTraceEnabledLogger(); + logger.trace(logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).trace(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.trace(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).trace(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + } + + @Test + public void traceEnabled3Lambda() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getTraceEnabledLogger(); + + logger.trace(logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).trace(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.trace(marker, logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).trace(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + } + + @Test + public void traceDisabled3Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + + logger.trace(logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.trace(marker, logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + + @Test + public void debugEnabled1() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getDebugEnabledLogger(); + + logger.isDebugEnabled(); + Mockito.verify(logger.getLogger()).isDebugEnabled(); + + logger.isDebugEnabled(marker); + Mockito.verify(logger.getLogger()).isDebugEnabled(marker); + + logger.debug(logString0); + Mockito.verify(logger.getLogger()).debug(logString0); + + logger.debug(logString0,exception); + Mockito.verify(logger.getLogger()).debug(logString0,exception); + + logger.debug(logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).debug(logString1, guids.get(0)); + + logger.debug(marker, logString0); + Mockito.verify(logger.getLogger()).debug(marker, logString0); + + logger.debug(marker, logString0,exception); + Mockito.verify(logger.getLogger()).debug(marker, logString0, exception); + + logger.debug(marker, logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).debug(marker, logString1, guids.get(0)); + } + + @Test + public void debugEnabled1Lambda() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getDebugEnabledLogger(); + logger.debug(logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).debug(logString1, guids.get(0)); + + logger.debug(marker, logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).debug(marker, logString1, guids.get(0)); + } + + @Test + public void debugDisabled1Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.debug(logString1, supplier); + Mockito.verify(supplier, never()).get(); + + logger.debug(marker, logString1, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void debugEnabled2() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getDebugEnabledLogger(); + logger.debug(logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()) + .debug(logString2, guids.get(0), guids.get(1)); + + logger.debug(marker, logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()) + .debug(marker, logString2, guids.get(0), guids.get(1)); + } + + @Test + public void debugEnabled2Lambda() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getDebugEnabledLogger(); + logger.debug(logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).debug(logString2, guids.get(0), guids.get(1)); + + logger.debug(marker, logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).debug(marker, logString2, guids.get(0), guids.get(1)); + } + + @Test + public void debugDisabled2Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + + logger.debug(logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.debug(marker, logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void debugEnabled3() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getDebugEnabledLogger(); + logger.debug(logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).debug(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.debug(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).debug(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + } + + @Test + public void debugEnabled3Lambda() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getDebugEnabledLogger(); + + logger.debug(logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).debug(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.debug(marker, logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).debug(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + } + + @Test + public void debugDisabled3Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + + logger.debug(logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.debug(marker, logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + + @Test + public void infoEnabled1Lambda() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getInfoEnabledLogger(); + + logger.info(logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).info(logString1, guids.get(0)); + + logger.info(marker, logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).info(marker, logString1, guids.get(0)); + } + + @Test + public void infoEnabled1() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getInfoEnabledLogger(); + logger.isInfoEnabled(); + Mockito.verify(logger.getLogger()).isInfoEnabled(); + + logger.isInfoEnabled(marker); + Mockito.verify(logger.getLogger()).isInfoEnabled(marker); + + logger.info(logString0); + Mockito.verify(logger.getLogger()).info(logString0); + + logger.info(logString0, exception); + Mockito.verify(logger.getLogger()).info(logString0, exception); + + logger.info(logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).info(logString1, guids.get(0)); + + logger.info(marker, logString0); + Mockito.verify(logger.getLogger()).info(marker, logString0); + + logger.info(marker, logString0, exception); + Mockito.verify(logger.getLogger()).info(marker, logString0, exception); + + logger.info(marker, logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).info(marker, logString1, guids.get(0)); + } + + @Test + public void infoDisabled1Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.info(logString1, supplier); + Mockito.verify(supplier, never()).get(); + + logger.info(marker, logString1, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void infoEnabled2Lambda() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getInfoEnabledLogger(); + logger.info(logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).info(logString2, guids.get(0), guids.get(1)); + + logger.info(marker, logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).info(marker, logString2, guids.get(0), guids.get(1)); + } + + @Test + public void infoEnabled2() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getInfoEnabledLogger(); + logger.info(logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()).info(logString2, guids.get(0), guids.get(1)); + + logger.info(marker, logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()).info(marker, logString2, guids.get(0), guids.get(1)); + } + + @Test + public void infoDisabled2Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.info(logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.info(marker, logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void infoEnabled3Lambda() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getInfoEnabledLogger(); + logger.info(logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).info(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.info(marker, logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).info(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + + } + + @Test + public void infoEnabled3() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getInfoEnabledLogger(); + logger.info(logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).info(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.info(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).info(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + + } + + @Test + public void infoDisabled3Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.info(logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.info(marker, logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void warnEnabled1Lambda() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getWarnEnabledLogger(); + logger.warn(logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).warn(logString1, guids.get(0)); + + logger.warn(marker, logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).warn(marker, logString1, guids.get(0)); + + } + + @Test + public void warnEnabled1() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getWarnEnabledLogger(); + logger.isWarnEnabled(); + Mockito.verify(logger.getLogger()).isWarnEnabled(); + + logger.isWarnEnabled(marker); + Mockito.verify(logger.getLogger()).isWarnEnabled(marker); + + logger.warn(logString0); + Mockito.verify(logger.getLogger()).warn(logString0); + + logger.warn(logString0,exception); + Mockito.verify(logger.getLogger()).warn(logString0,exception); + + logger.warn(logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).warn(logString1, guids.get(0)); + + logger.warn(marker, logString0); + Mockito.verify(logger.getLogger()).warn(marker, logString0); + + logger.warn(marker, logString0,exception); + Mockito.verify(logger.getLogger()).warn(marker, logString0,exception); + + logger.warn(marker, logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).warn(marker, logString1, guids.get(0)); + } + + @Test + public void warnDisabled1Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.warn(logString1, supplier); + Mockito.verify(supplier, never()).get(); + + logger.warn(marker, logString1, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void warnEnabled2Lambda() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getWarnEnabledLogger(); + logger.warn(logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).warn(logString2, guids.get(0), guids.get(1)); + + logger.warn(marker, logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).warn(marker, logString2, guids.get(0), guids.get(1)); + + } + + @Test + public void warnEnabled2() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getWarnEnabledLogger(); + logger.warn(logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()).warn(logString2, guids.get(0), guids.get(1)); + + logger.warn(marker, logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()).warn(marker, logString2, guids.get(0), guids.get(1)); + } + + + @Test + public void warnDisabled2Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.warn(logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.warn(marker, logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void warnEnabled3Lambda() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getWarnEnabledLogger(); + logger.warn(logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).warn(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.warn(marker, logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).warn(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + } + + @Test + public void warnEnabled3() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getWarnEnabledLogger(); + logger.warn(logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).warn(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.warn(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).warn(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + + } + + @Test + public void warnDisabled3Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.warn(logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.warn(marker, logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void errorEnabled1Lambda() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getErrorEnabledLogger(); + logger.error(logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).error(logString1, guids.get(0)); + + logger.error(marker, logString1, () -> guids.get(0)); + Mockito.verify(logger.getLogger()).error(marker, logString1, guids.get(0)); + } + + @Test + public void errorEnabled1() { + final List<UUID> guids = getGuids(1); + final LazyLogger logger = getErrorEnabledLogger(); + + logger.isErrorEnabled(); + Mockito.verify(logger.getLogger()).isErrorEnabled(); + + logger.isErrorEnabled(marker); + Mockito.verify(logger.getLogger()).isErrorEnabled(marker); + + logger.error(logString0); + Mockito.verify(logger.getLogger()).error(logString0); + + logger.error(logString0,exception); + Mockito.verify(logger.getLogger()).error(logString0,exception); + + logger.error(logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).error(logString1, guids.get(0)); + + logger.error(marker, logString0); + Mockito.verify(logger.getLogger()).error(marker, logString0); + + logger.error(marker, logString0, exception); + Mockito.verify(logger.getLogger()).error(marker, logString0, exception); + + logger.error(marker, logString1, guids.get(0)); + Mockito.verify(logger.getLogger()).error(marker, logString1, guids.get(0)); + + } + + @Test + public void errorDisabled1Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.error(logString1, supplier); + Mockito.verify(supplier, never()).get(); + + logger.error(marker, logString1, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void errorEnabled2Lambda() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getErrorEnabledLogger(); + logger.error(logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).error(logString2, guids.get(0), guids.get(1)); + + logger.error(marker, logString2, () -> guids.get(0), () -> guids.get(1)); + Mockito.verify(logger.getLogger()).error(marker, logString2, guids.get(0), guids.get(1)); + } + + @Test + public void errorEnabled2() { + final List<UUID> guids = getGuids(2); + final LazyLogger logger = getErrorEnabledLogger(); + logger.error(logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()).error(logString2, guids.get(0), guids.get(1)); + + logger.error(marker, logString2, guids.get(0), guids.get(1)); + Mockito.verify(logger.getLogger()).error(marker, logString2, guids.get(0), guids.get(1)); + } + + @Test + public void errorDisabled2Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.error(logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.error(marker, logString2, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } + + @Test + public void errorEnabled3Lambda() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getErrorEnabledLogger(); + logger.error(logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).error(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.error(marker, logString3, () -> guids.get(0), () -> guids.get(1), () -> guids.get(2)); + Mockito.verify(logger.getLogger()).error(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + } + + @Test + public void errorEnabled3() { + final List<UUID> guids = getGuids(3); + final LazyLogger logger = getErrorEnabledLogger(); + logger.error(logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).error(logString3, guids.get(0), guids.get(1), guids.get(2)); + + logger.error(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + Mockito.verify(logger.getLogger()).error(marker, logString3, guids.get(0), guids.get(1), guids.get(2)); + + } + + @Test + public void errorDisabled3Lambda() { + final Supplier<Object> supplier = getMockedSupplier(); + final LazyLogger logger = getDisabledLogger(); + logger.error(logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + + logger.error(marker, logString3, supplier, supplier, supplier); + Mockito.verify(supplier, never()).get(); + } +} \ No newline at end of file diff --git a/metron-platform/metron-common/src/test/java/org/apache/metron/common/utils/LazzyLoggerImplPerfTest.java b/metron-platform/metron-common/src/test/java/org/apache/metron/common/utils/LazzyLoggerImplPerfTest.java new file mode 100644 index 0000000..53c8f99 --- /dev/null +++ b/metron-platform/metron-common/src/test/java/org/apache/metron/common/utils/LazzyLoggerImplPerfTest.java @@ -0,0 +1,118 @@ +package org.apache.metron.common.utils; + +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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. + */ +import java.lang.invoke.MethodHandles; +import java.util.HashMap; +import java.util.Map; +import org.apache.commons.lang3.RandomStringUtils; +import org.apache.commons.math3.stat.descriptive.DescriptiveStatistics; +import org.apache.commons.math3.stat.descriptive.StatisticalSummary; +import org.json.simple.JSONObject; +import org.junit.Ignore; +import org.junit.Test; + +/** + * Performance test for lazy logging. + * By default the test is disabled due to it taking too much time to run during normal unit testing. + * comment out the ignore attribute to allow test to run + */ +public class LazzyLoggerImplPerfTest { + private static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + private static final double NANO_TO_MILLIS = 1e6; + private static final String PATH = "/foo/bar/baz"; + + public interface Operation { + void run(); + } + + @Test + @Ignore + public void calcTimes() { + Map<String, Object> smallMap = new HashMap<>(); + for (int i = 0; i < 10; i++) { + smallMap.put("key" + i, RandomStringUtils.randomAlphabetic(10)); + } + Map<String, Object> largeMap = new HashMap<>(); + for (int i = 0; i < 500; i++) { + largeMap.put("key" + i, RandomStringUtils.randomAlphabetic(1000)); + } + JSONObject largeObject = new JSONObject(largeMap); + JSONObject smallObject = new JSONObject(smallMap); + int reps = 1000; + + StatisticalSummary summary = runTrial(reps, () -> { + LOG.trace("Writing message {} to path: {}", smallObject.toJSONString(), PATH); + }); + printSummary(String.format("Small object %s times", reps), summary); + + summary = runTrial(reps, () -> { + LOG.trace("Writing message {} to path: {}", () -> smallObject.toJSONString(), () -> PATH); + }); + printSummary(String.format("Small object %s times using lazy logging", reps), summary); + + + summary = runTrial(reps, () -> { + LOG.trace("Writing message {} to path: {}", largeObject.toJSONString(), PATH); + }); + printSummary(String.format("Large object %s times", reps), summary); + + summary = runTrial(reps, () -> { + LOG.trace("Writing message {} to path: {}", () -> largeObject.toJSONString(), () -> PATH); + }); + printSummary(String.format("Large object %s times using lazy logging", reps), summary); + + summary = runTrial(reps, () -> { + LOG.trace("Writing message {} to path: {}", "hello", PATH); + }); + printSummary(String.format("Simple string %s times", reps), summary); + + summary = runTrial(reps, () -> { + LOG.trace("Writing message {} to path: {}", () -> "hello", () -> PATH); + }); + printSummary(String.format("Simple string %s times using lazy logging", reps), summary); + } + + + private StatisticalSummary runTrial(int reps, Operation operation) { + DescriptiveStatistics stats = new DescriptiveStatistics(); + long trialTime = timeOperation(() -> { + for (int i = 0; i < reps; i++) { + long time = timeOperation(operation); + stats.addValue(time / NANO_TO_MILLIS); + } + }); + System.out.println("Total trial time (ms): " + (trialTime / NANO_TO_MILLIS)); + return stats; + } + + private long timeOperation(Operation o) { + final long start = System.nanoTime(); + o.run(); + final long finish = System.nanoTime(); + return finish - start; + } + + private void printSummary(String desc, StatisticalSummary summary) { + final String border = "==============================="; + System.out.println(border); + System.out.println(desc); + System.out.println(summary.toString()); + System.out.println(border); + } +} diff --git a/metron-platform/metron-enrichment/metron-enrichment-common/src/main/java/org/apache/metron/enrichment/adapters/simplehbase/SimpleHBaseAdapter.java b/metron-platform/metron-enrichment/metron-enrichment-common/src/main/java/org/apache/metron/enrichment/adapters/simplehbase/SimpleHBaseAdapter.java index c84c494..06f9d21 100644 --- a/metron-platform/metron-enrichment/metron-enrichment-common/src/main/java/org/apache/metron/enrichment/adapters/simplehbase/SimpleHBaseAdapter.java +++ b/metron-platform/metron-enrichment/metron-enrichment-common/src/main/java/org/apache/metron/enrichment/adapters/simplehbase/SimpleHBaseAdapter.java @@ -27,6 +27,8 @@ import java.util.List; import java.util.Map; import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.hbase.HBaseConfiguration; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.enrichment.cache.CacheKey; import org.apache.metron.enrichment.converter.EnrichmentKey; import org.apache.metron.enrichment.converter.EnrichmentValue; @@ -36,11 +38,9 @@ import org.apache.metron.enrichment.lookup.LookupKV; import org.apache.metron.enrichment.lookup.accesstracker.NoopAccessTracker; import org.apache.metron.enrichment.utils.EnrichmentUtils; import org.json.simple.JSONObject; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; public class SimpleHBaseAdapter implements EnrichmentAdapter<CacheKey>,Serializable { - protected static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + protected static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); protected SimpleHBaseConfig config; protected EnrichmentLookup lookup; @@ -89,7 +89,7 @@ public class SimpleHBaseAdapter implements EnrichmentAdapter<CacheKey>,Serializa for (Map.Entry<String, Object> values : kv.getValue().getMetadata().entrySet()) { enriched.put(kv.getKey().type + "." + values.getKey(), values.getValue()); } - LOG.trace("Enriched type {} => {}", kv.getKey().type, enriched); + LOG.trace("Enriched type {} => {}", () -> kv.getKey().type, ()->enriched); } } } diff --git a/metron-platform/metron-enrichment/metron-enrichment-common/src/main/java/org/apache/metron/enrichment/adapters/stellar/StellarAdapter.java b/metron-platform/metron-enrichment/metron-enrichment-common/src/main/java/org/apache/metron/enrichment/adapters/stellar/StellarAdapter.java index 04b759b..c57007e 100644 --- a/metron-platform/metron-enrichment/metron-enrichment-common/src/main/java/org/apache/metron/enrichment/adapters/stellar/StellarAdapter.java +++ b/metron-platform/metron-enrichment/metron-enrichment-common/src/main/java/org/apache/metron/enrichment/adapters/stellar/StellarAdapter.java @@ -124,7 +124,7 @@ public class StellarAdapter implements EnrichmentAdapter<CacheKey>,Serializable if (slowLogThreshold != null && _PERF_LOG.isDebugEnabled()) { long duration = System.currentTimeMillis() - startTime; if (duration > slowLogThreshold) { - _PERF_LOG.debug("SLOW LOG: " + stellarStatement + " took" + duration + "ms"); + _PERF_LOG.debug("SLOW LOG: {} took {} ms",stellarStatement,duration); } } _LOG.debug("{} := {} yields {}", kv.getKey(), stellarStatement , o); diff --git a/metron-platform/metron-parsing/metron-parsers-common/src/main/java/org/apache/metron/parsers/GrokParser.java b/metron-platform/metron-parsing/metron-parsers-common/src/main/java/org/apache/metron/parsers/GrokParser.java index 616639c..12fa8e2 100644 --- a/metron-platform/metron-parsing/metron-parsers-common/src/main/java/org/apache/metron/parsers/GrokParser.java +++ b/metron-platform/metron-parsing/metron-parsers-common/src/main/java/org/apache/metron/parsers/GrokParser.java @@ -44,16 +44,16 @@ import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.fs.FileSystem; import org.apache.hadoop.fs.Path; import org.apache.metron.common.Constants; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.parsers.interfaces.MessageParser; import org.apache.metron.parsers.interfaces.MessageParserResult; import org.json.simple.JSONObject; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; public class GrokParser implements MessageParser<JSONObject>, Serializable { - protected static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + protected static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); protected transient Grok grok; protected String grokPath; @@ -126,7 +126,8 @@ public class GrokParser implements MessageParser<JSONObject>, Serializable { } grok.addPatternFromReader(new InputStreamReader(patterInputStream)); - LOG.info("Grok parser set the following grok expression for '{}': {}", patternLabel, grok.getPatterns().get(patternLabel)); + LOG.info("Grok parser set the following grok expression for '{}': {}", () ->patternLabel, + () -> grok.getPatterns().get(patternLabel)); String grokPattern = "%{" + patternLabel + "}"; @@ -270,7 +271,7 @@ public class GrokParser implements MessageParser<JSONObject>, Serializable { protected long toEpoch(String datetime) throws ParseException { LOG.debug("Grok parser converting timestamp to epoch: {}", datetime); - LOG.debug("Grok parser's DateFormat has TimeZone: {}", dateFormat.getTimeZone()); + LOG.debug("Grok parser's DateFormat has TimeZone: {}", () -> dateFormat.getTimeZone()); Date date = dateFormat.parse(datetime); LOG.debug("Grok parser converted timestamp to epoch: {}", date); diff --git a/metron-platform/metron-parsing/metron-parsers/src/main/java/org/apache/metron/parsers/asa/BasicAsaParser.java b/metron-platform/metron-parsing/metron-parsers/src/main/java/org/apache/metron/parsers/asa/BasicAsaParser.java index 7ac2398..9ae9541 100644 --- a/metron-platform/metron-parsing/metron-parsers/src/main/java/org/apache/metron/parsers/asa/BasicAsaParser.java +++ b/metron-platform/metron-parsing/metron-parsers/src/main/java/org/apache/metron/parsers/asa/BasicAsaParser.java @@ -33,16 +33,16 @@ import oi.thekraken.grok.api.Grok; import oi.thekraken.grok.api.Match; import oi.thekraken.grok.api.exception.GrokException; import org.apache.metron.common.Constants; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.parsers.BasicParser; import org.apache.metron.parsers.ParseException; import org.apache.metron.parsers.utils.SyslogUtils; import org.json.simple.JSONObject; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; public class BasicAsaParser extends BasicParser { - protected static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + protected static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); protected Clock deviceClock; private String syslogPattern = "%{CISCO_TAGGED_SYSLOG}"; @@ -157,7 +157,7 @@ public class BasicAsaParser extends BasicParser { syslogMatch.captures(); if (!syslogMatch.isNull()) { syslogJson = syslogMatch.toMap(); - LOG.trace("[Metron] Grok CISCO ASA syslog matches: {}", syslogMatch.toJson()); + LOG.trace("[Metron] Grok CISCO ASA syslog matches: {}", syslogMatch::toJson); metronJson.put(Constants.Fields.ORIGINAL.getName(), logLine); metronJson.put(Constants.Fields.TIMESTAMP.getName(), @@ -197,7 +197,7 @@ public class BasicAsaParser extends BasicParser { messageMatch.captures(); if (!messageMatch.isNull()) { Map<String, Object> messageJson = messageMatch.toMap(); - LOG.trace("[Metron] Grok CISCO ASA message matches: {}", messageMatch.toJson()); + LOG.trace("[Metron] Grok CISCO ASA message matches: {}", messageMatch::toJson); String src_ip = (String) messageJson.get("src_ip"); if (src_ip != null) @@ -227,7 +227,7 @@ public class BasicAsaParser extends BasicParser { syslogJson.get("CISCOTAG")); } - LOG.debug("[Metron] Final normalized message: {}", metronJson.toString()); + LOG.debug("[Metron] Final normalized message: {}", metronJson::toString); } catch (RuntimeException e) { LOG.error(e.getMessage(), e); diff --git a/metron-platform/metron-parsing/metron-parsers/src/main/java/org/apache/metron/parsers/bro/BasicBroParser.java b/metron-platform/metron-parsing/metron-parsers/src/main/java/org/apache/metron/parsers/bro/BasicBroParser.java index 5264750..9a3e36d 100644 --- a/metron-platform/metron-parsing/metron-parsers/src/main/java/org/apache/metron/parsers/bro/BasicBroParser.java +++ b/metron-platform/metron-parsing/metron-parsers/src/main/java/org/apache/metron/parsers/bro/BasicBroParser.java @@ -25,16 +25,16 @@ import java.util.ArrayList; import java.util.List; import java.util.Map; import org.apache.metron.common.Constants; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.parsers.BasicParser; import org.json.simple.JSONArray; import org.json.simple.JSONObject; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; @SuppressWarnings("serial") public class BasicBroParser extends BasicParser { - protected static final Logger _LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + protected static final LazyLogger _LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); public static final ThreadLocal<NumberFormat> DECIMAL_FORMAT = new ThreadLocal<NumberFormat>() { @Override protected NumberFormat initialValue() { @@ -114,7 +114,7 @@ public class BasicBroParser extends BasicParser { timestamp = convertToMillis(broTimestamp); payload.put(Constants.Fields.TIMESTAMP.getName(), timestamp); payload.put("bro_timestamp", broTimestampFormatted); - _LOG.trace("[Metron] new bro record - timestamp : {}", payload.get(Constants.Fields.TIMESTAMP.getName())); + _LOG.trace("[Metron] new bro record - timestamp : {}", () -> payload.get(Constants.Fields.TIMESTAMP.getName())); } catch (NumberFormatException nfe) { _LOG.error("[Metron] timestamp is invalid: {}", payload.get("timestamp")); payload.put(Constants.Fields.TIMESTAMP.getName(), 0); diff --git a/metron-platform/metron-pcap/src/main/java/org/apache/metron/pcap/mr/PcapJob.java b/metron-platform/metron-pcap/src/main/java/org/apache/metron/pcap/mr/PcapJob.java index 5e82904..9b1c1fc 100644 --- a/metron-platform/metron-pcap/src/main/java/org/apache/metron/pcap/mr/PcapJob.java +++ b/metron-platform/metron-pcap/src/main/java/org/apache/metron/pcap/mr/PcapJob.java @@ -51,6 +51,8 @@ import org.apache.hadoop.mapreduce.Partitioner; import org.apache.hadoop.mapreduce.Reducer; import org.apache.hadoop.mapreduce.lib.input.SequenceFileInputFormat; import org.apache.hadoop.mapreduce.lib.output.SequenceFileOutputFormat; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.common.utils.timestamp.TimestampConverters; import org.apache.metron.job.Finalizer; import org.apache.metron.job.JobException; @@ -67,8 +69,6 @@ import org.apache.metron.pcap.filter.PcapFilter; import org.apache.metron.pcap.filter.PcapFilterConfigurator; import org.apache.metron.pcap.filter.PcapFilters; import org.apache.metron.pcap.utils.FileFilterUtil; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; /** * Encompasses MapReduce job and final writing of Pageable results to specified location. @@ -76,7 +76,7 @@ import org.slf4j.LoggerFactory; */ public class PcapJob<T> implements Statusable<Path> { - private static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + private static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); public static final String START_TS_CONF = "start_ts"; public static final String END_TS_CONF = "end_ts"; public static final String WIDTH_CONF = "width"; @@ -279,7 +279,8 @@ public class PcapJob<T> implements Statusable<Path> { ); String from = format.format(new Date(Long.divideUnsigned(beginNS, 1000000))); String to = format.format(new Date(Long.divideUnsigned(endNS, 1000000))); - LOG.debug("Executing query {} on timerange from {} to {}", filterImpl.queryToString(fields), from, to); + + LOG.debug("Executing query {} on timerange from {} to {}", () -> filterImpl.queryToString(fields), ()-> from, () -> to); } Path interimResultPath = new Path(baseInterimResultPath, outputDirName); PcapOptions.INTERIM_RESULT_PATH.put(configuration, interimResultPath); diff --git a/metron-platform/metron-pcap/src/main/java/org/apache/metron/pcap/utils/FileFilterUtil.java b/metron-platform/metron-pcap/src/main/java/org/apache/metron/pcap/utils/FileFilterUtil.java index 2bfebcc..f48ffb9 100644 --- a/metron-platform/metron-pcap/src/main/java/org/apache/metron/pcap/utils/FileFilterUtil.java +++ b/metron-platform/metron-pcap/src/main/java/org/apache/metron/pcap/utils/FileFilterUtil.java @@ -30,13 +30,13 @@ import java.util.Iterator; import java.util.List; import java.util.Map; import org.apache.hadoop.fs.Path; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.pcap.PcapFilenameHelper; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; public class FileFilterUtil { - private static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + private static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); private FileFilterUtil() { } @@ -49,9 +49,9 @@ public class FileFilterUtil { Iterable<Path> files) { Map<Integer, List<Path>> filesByPartition = getFilesByPartition(files); List<String> filteredFiles = filterByTimestampLT(beginTs, endTs, filesByPartition); - if (LOG.isDebugEnabled()) { - LOG.debug("Including files {}", Joiner.on(",").join(filteredFiles)); - } + + LOG.debug("Including files {}", () -> Joiner.on(",").join(filteredFiles)); + return filteredFiles; } diff --git a/metron-platform/metron-writer/metron-writer-common/src/main/java/org/apache/metron/writer/hbase/SimpleHbaseEnrichmentWriter.java b/metron-platform/metron-writer/metron-writer-common/src/main/java/org/apache/metron/writer/hbase/SimpleHbaseEnrichmentWriter.java index d7b2cb9..dec6926 100644 --- a/metron-platform/metron-writer/metron-writer-common/src/main/java/org/apache/metron/writer/hbase/SimpleHbaseEnrichmentWriter.java +++ b/metron-platform/metron-writer/metron-writer-common/src/main/java/org/apache/metron/writer/hbase/SimpleHbaseEnrichmentWriter.java @@ -18,6 +18,8 @@ package org.apache.metron.writer.hbase; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.common.writer.BulkMessage; import org.apache.metron.common.writer.MessageId; import com.google.common.collect.ImmutableList; @@ -38,8 +40,6 @@ import org.apache.metron.hbase.TableProvider; import org.apache.metron.writer.AbstractWriter; import org.apache.metron.common.writer.BulkWriterResponse; import org.json.simple.JSONObject; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import java.io.IOException; import java.io.Serializable; @@ -51,7 +51,7 @@ import java.util.stream.Collectors; */ public class SimpleHbaseEnrichmentWriter extends AbstractWriter implements BulkMessageWriter<JSONObject>, Serializable { - private static final Logger LOG = LoggerFactory.getLogger(SimpleHbaseEnrichmentWriter.class); + private static final LazyLogger LOG = LazyLoggerFactory.getLogger(SimpleHbaseEnrichmentWriter.class); public enum Configurations { HBASE_TABLE("shew.table") @@ -136,7 +136,7 @@ public class SimpleHbaseEnrichmentWriter extends AbstractWriter implements BulkM if(converter == null) { converter = new EnrichmentConverter(); } - LOG.debug("Sensor: '{}': {Provider: '{}', Converter: '{}'}", sensorName, getClassName(provider), getClassName(converter)); + LOG.debug("Sensor: '{}': {Provider: '{}', Converter: '{}'}", () -> sensorName, () -> getClassName(provider), () -> getClassName(converter)); } @@ -243,7 +243,7 @@ public class SimpleHbaseEnrichmentWriter extends AbstractWriter implements BulkM } keyCols.add(columnName); } - LOG.debug("Key columns: '{}'", String.join(",", keyCols)); + LOG.debug("Key columns: '{}'", () -> String.join(",", keyCols)); return keyCols; } else { @@ -263,10 +263,11 @@ public class SimpleHbaseEnrichmentWriter extends AbstractWriter implements BulkM List<String> keys = getColumns(o, false); Object delimObj = Configurations.KEY_DELIM.get(config); String delim = (delimObj == null || !(delimObj instanceof String))?null:delimObj.toString(); - transformer = new KeyTransformer(keys, delim); - keyTransformer = new AbstractMap.SimpleEntry<>(o, transformer); - LOG.debug("Transformer found for keys '{}' and delimiter '{}': '{}'", String.join(",", keys), delim, transformer); - return transformer; + KeyTransformer newtransformer = new KeyTransformer(keys, delim); + keyTransformer = new AbstractMap.SimpleEntry<>(o, newtransformer); + LOG.debug("Transformer found for keys '{}' and delimiter '{}': '{}'", () -> String.join(",", keys), + () -> delim, () -> newtransformer); + return newtransformer; } } diff --git a/metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/HdfsWriter.java b/metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/HdfsWriter.java index d251602..6ff3d64 100644 --- a/metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/HdfsWriter.java +++ b/metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/HdfsWriter.java @@ -29,6 +29,8 @@ import java.util.stream.Collectors; import org.apache.metron.common.configuration.IndexingConfigurations; import org.apache.metron.common.configuration.writer.WriterConfiguration; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.metron.common.writer.BulkMessageWriter; import org.apache.metron.common.writer.BulkMessage; import org.apache.metron.common.writer.BulkWriterResponse; @@ -46,11 +48,10 @@ import org.apache.storm.hdfs.bolt.sync.SyncPolicy; import org.apache.storm.hdfs.common.rotation.RotationAction; import org.apache.storm.task.TopologyContext; import org.json.simple.JSONObject; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; + public class HdfsWriter implements BulkMessageWriter<JSONObject>, Serializable { - private static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + private static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); List<RotationAction> rotationActions = new ArrayList<>(); FileRotationPolicy rotationPolicy = new NoRotationPolicy(); @@ -93,7 +94,7 @@ public class HdfsWriter implements BulkMessageWriter<JSONObject>, Serializable { this.stellarProcessor = new StellarProcessor(); if(syncPolicy != null) { //if the user has specified the sync policy, we don't want to override their wishes. - LOG.debug("Using user specified sync policy {}", syncPolicy.getClass().getSimpleName()); + LOG.debug("Using user specified sync policy {}", () -> syncPolicy.getClass().getSimpleName()); syncPolicyCreator = new ClonedSyncPolicyCreator(syncPolicy); } else { @@ -124,7 +125,7 @@ public class HdfsWriter implements BulkMessageWriter<JSONObject>, Serializable { ); try { - LOG.trace("Writing message {} to path: {}", message.toJSONString(), path); + LOG.trace("Writing message {} to path: {}", () -> message.toJSONString(), () -> path); SourceHandler handler = getSourceHandler(sensorType, path, configurations); handler.handle(message, sensorType, configurations, syncPolicyCreator); } catch (Exception e) { @@ -169,7 +170,7 @@ public class HdfsWriter implements BulkMessageWriter<JSONObject>, Serializable { @Override public void close() { for(SourceHandler handler : sourceHandlerMap.values()) { - LOG.debug("Closing SourceHandler {}", handler.toString()); + LOG.debug("Closing SourceHandler {}", () -> handler.toString()); handler.close(); } // Everything is closed, so just clear it diff --git a/metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/SourceHandler.java b/metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/SourceHandler.java index d94b7cf..9d4193f 100644 --- a/metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/SourceHandler.java +++ b/metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/SourceHandler.java @@ -32,17 +32,17 @@ import org.apache.hadoop.fs.FileSystem; import org.apache.hadoop.fs.Path; import org.apache.hadoop.hdfs.client.HdfsDataOutputStream; import org.apache.metron.common.configuration.writer.WriterConfiguration; +import org.apache.metron.common.utils.LazyLogger; +import org.apache.metron.common.utils.LazyLoggerFactory; import org.apache.storm.hdfs.bolt.format.FileNameFormat; import org.apache.storm.hdfs.bolt.rotation.FileRotationPolicy; import org.apache.storm.hdfs.bolt.rotation.TimedRotationPolicy; import org.apache.storm.hdfs.bolt.sync.SyncPolicy; import org.apache.storm.hdfs.common.rotation.RotationAction; import org.json.simple.JSONObject; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; public class SourceHandler { - private static final Logger LOG = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + private static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); List<RotationAction> rotationActions = new ArrayList<>(); FileRotationPolicy rotationPolicy; SyncPolicy syncPolicy; @@ -156,7 +156,7 @@ public class SourceHandler { // never be data that would go into a rotation > 0. Instead a new SourceHandler, and by extension file, will // be created. Path path = new Path(this.fileNameFormat.getPath(), this.fileNameFormat.getName(0, System.currentTimeMillis())); - LOG.debug("Creating new output file: {}", path.getName()); + LOG.debug("Creating new output file: {}", () -> path.getName()); if(fs.getScheme().equals("file")) { //in the situation where we're running this in a local filesystem, flushing doesn't work. fs.mkdirs(path.getParent());