diff --git a/src/main/java/io/avaje/logback/encoder/Eval.java b/src/main/java/io/avaje/logback/encoder/Eval.java new file mode 100644 index 0000000..248769c --- /dev/null +++ b/src/main/java/io/avaje/logback/encoder/Eval.java @@ -0,0 +1,78 @@ +package io.avaje.logback.encoder; + +/** + * Helper to evaluate expressions like {@code "${my.property}"}, {@code "${MY_PROPERTY:someDefaultValue}"} etc. + */ +final class Eval { + + /** + * Return the default component value using environment variables. + *

+ * For K8s this derives the component name from the HOSTNAME. + */ + static String defaultComponent() { + String component = System.getenv("COMPONENT"); + if (component != null) { + return component; + } + if (System.getenv("KUBERNETES_PORT") != null) { + // in k8s we can default off the hostname + return k8sComponent(System.getenv("HOSTNAME")); + } + return null; + } + + static String k8sComponent(String hostname) { + if (hostname == null) { + return null; + } + int p0 = hostname.lastIndexOf('-'); + if (p0 > 1) { + int p1 = hostname.lastIndexOf('-', p0 - 1); + if (p1 > 0) { + return hostname.substring(0, p1); + } + } + return null; + } + + /** + * Evaluate the expression and otherwise return the original value. + *

+ * Expressions are in the form {@code ${key:defaultValue}} + *

+ * Examples: + *

{@code
+   *
+   *  ${APP_ENV:localDev}
+   *  ${system.name:unknown}
+   *  ${MY_COMPONENT:myDefaultValue}
+   *
+   * }
+ */ + static String eval(String value) { + if (value == null || !value.startsWith("${") || !value.endsWith("}")) { + return value; + } + String raw = value.substring(2, value.length() - 1); + String[] split = raw.split(":", 2); + String key = split[0]; + String val = System.getProperty(key); + if (val != null) { + return val; + } + val = System.getenv(key); + if (val != null) { + return val; + } + val = System.getProperty(toSystemPropertyKey(key)); + if (val != null) { + return val; + } + return split.length == 2 ? split[1] : value; + } + + static String toSystemPropertyKey(String key) { + return key.replace('_', '.').toLowerCase(); + } +} diff --git a/src/main/java/io/avaje/logback/encoder/FilterBuilder.java b/src/main/java/io/avaje/logback/encoder/FilterBuilder.java new file mode 100644 index 0000000..ef41a99 --- /dev/null +++ b/src/main/java/io/avaje/logback/encoder/FilterBuilder.java @@ -0,0 +1,167 @@ +package io.avaje.logback.encoder; + +import java.util.ArrayList; +import java.util.List; +import java.util.regex.Pattern; + +final class FilterBuilder implements StackElementFilter.Builder { + + private final List filters = new ArrayList<>(); + + @Override + public StackElementFilter.Builder generated() { + filters.add(new Generated()); + return this; + } + + @Override + public StackElementFilter.Builder reflectiveInvocation() { + filters.add(new ReflectiveInvocation()); + return this; + } + + @Override + public StackElementFilter.Builder jdkInternals() { + filters.add(new JDKInternals()); + return this; + } + + @Override + public StackElementFilter.Builder spring() { + filters.add(new SpringFilter()); + return this; + } + + @Override + public StackElementFilter.Builder byPattern(List excludes) { + if (excludes != null && !excludes.isEmpty()) { + filters.add(new PatternFilter(excludes)); + } + return this; + } + + @Override + public StackElementFilter.Builder allFilters() { + generated(); + reflectiveInvocation(); + jdkInternals(); + spring(); + return this; + } + + @Override + public StackElementFilter build() { + if (filters.isEmpty()) { + return StackElementFilter.any(); + } + return new Group(filters.toArray(new StackElementFilter[0])); + } + + private static final class Generated implements StackElementFilter { + + @Override + public boolean accept(StackTraceElement element) { + String className = element.getClassName(); + return !className.contains("$$FastClassByCGLIB$$") + && !className.contains("$$EnhancerBySpringCGLIB$$"); + } + } + + private static final class ReflectiveInvocation implements StackElementFilter { + + @Override + public boolean accept(StackTraceElement element) { + String methodName = element.getMethodName(); + if (methodName.equals("invoke")) { + String className = element.getClassName(); + return !className.startsWith("sun.reflect.") + && !className.startsWith("java.lang.reflect.") + && !className.startsWith("net.sf.cglib.proxy.MethodProxy"); + } + return true; + } + } + + private static final class JDKInternals implements StackElementFilter { + + @Override + public boolean accept(StackTraceElement element) { + String className = element.getClassName(); + return !className.startsWith("com.sun.") + && !className.startsWith("sun.net."); + } + } + + private static final class SpringFilter implements StackElementFilter { + + private static final String[] MATCHES = { + "org.springframework.cglib.", + "org.springframework.transaction.", + "org.springframework.validation.", + "org.springframework.app.", + "org.springframework.aop.", + "org.springframework.ws.", + "org.springframework.web.", + "org.springframework.transaction" + }; + + @Override + public boolean accept(StackTraceElement element) { + String className = element.getClassName(); + if (className.startsWith("org.springframework")) { + for (String match : MATCHES) { + if (className.startsWith(match)) { + return false; + } + } + return true; + } + if (className.startsWith("org.apache")) { + return !className.startsWith("org.apache.tomcat.") + && !className.startsWith("org.apache.catalina.") + && !className.startsWith("org.apache.coyote."); + } + return true; + } + } + + private static final class PatternFilter implements StackElementFilter { + + private final Pattern[] excludes; + + PatternFilter(final List excludes) { + this.excludes = excludes.toArray(new Pattern[0]); + } + + @Override + public boolean accept(StackTraceElement element) { + final String classNameAndMethod = element.getClassName() + "." + element.getMethodName(); + for (final Pattern exclusionPattern : excludes) { + if (exclusionPattern.matcher(classNameAndMethod).find()) { + return false; + } + } + return true; + } + } + + private static final class Group implements StackElementFilter { + + private final StackElementFilter[] filters; + + public Group(StackElementFilter[] filters) { + this.filters = filters; + } + + @Override + public boolean accept(StackTraceElement element) { + for (StackElementFilter filter : filters) { + if (!filter.accept(element)) { + return false; + } + } + return true; + } + } + +} diff --git a/src/main/java/io/avaje/logback/encoder/JsonEncoder.java b/src/main/java/io/avaje/logback/encoder/JsonEncoder.java index b5bda17..344069a 100644 --- a/src/main/java/io/avaje/logback/encoder/JsonEncoder.java +++ b/src/main/java/io/avaje/logback/encoder/JsonEncoder.java @@ -9,6 +9,8 @@ import ch.qos.logback.classic.pattern.ThrowableHandlingConverter; import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.classic.spi.IThrowableProxy; +import ch.qos.logback.classic.spi.ThrowableProxy; import ch.qos.logback.core.encoder.EncoderBase; import io.avaje.json.PropertyNames; import io.avaje.json.simple.SimpleMapper; @@ -20,6 +22,7 @@ public final class JsonEncoder extends EncoderBase { private final JsonStream json; private final Map customFieldsMap = new HashMap<>(); private final PropertyNames properties; + private final StackHasher stackHasher; private ThrowableHandlingConverter throwableConverter = new ShortenedThrowableConverter(); private DateTimeFormatter formatter; @@ -29,12 +32,14 @@ public final class JsonEncoder extends EncoderBase { private int fieldExtra; private String component; private String environment; + private boolean includeStackHash = true; public JsonEncoder() { this.json = JsonStream.builder().build(); - this.properties = json.properties("component", "env", "timestamp", "level", "logger", "message", "thread", "stacktrace"); - this.component = System.getenv("COMPONENT"); + this.properties = json.properties("component", "env", "timestamp", "level", "logger", "message", "thread", "stackhash", "stacktrace"); + this.component = Eval.defaultComponent(); this.environment = System.getenv("ENVIRONMENT"); + this.stackHasher = new StackHasher(StackElementFilter.builder().allFilters().build()); } @Override @@ -96,7 +101,15 @@ public byte[] encode(ILoggingEvent event) { writer.name(6); writer.value(threadName); if (!stackTraceBody.isEmpty()) { - writer.name(7); + if (includeStackHash) { + IThrowableProxy throwableProxy = event.getThrowableProxy(); + if (throwableProxy instanceof ThrowableProxy) { + String hash = stackHasher.hexHash(((ThrowableProxy) throwableProxy).getThrowable()); + writer.name(7); + writer.value(hash); + } + } + writer.name(8); writer.value(stackTraceBody); } customFieldsMap.forEach((k, v) -> { @@ -113,12 +126,16 @@ public byte[] encode(ILoggingEvent event) { return outputStream.toByteArray(); } + public void setIncludeStackHash(boolean includeStackHash) { + this.includeStackHash = includeStackHash; + } + public void setComponent(String component) { - this.component = component; + this.component = Eval.eval(component); } public void setEnvironment(String environment) { - this.environment = environment; + this.environment = Eval.eval(environment); } public void setThrowableConverter(ThrowableHandlingConverter throwableConverter) { @@ -130,7 +147,12 @@ public void setCustomFields(String customFields) { return; } var mapper = SimpleMapper.builder().jsonStream(json).build(); - mapper.map().fromJson(customFields).forEach((k, v) -> customFieldsMap.put(k, mapper.toJson(v))); + mapper.map().fromJson(customFields).forEach((key, value) -> { + if (value instanceof String) { + value = Eval.eval((String) value); + } + customFieldsMap.put(key, mapper.toJson(value)); + }); } public void setTimestampPattern(String pattern) { diff --git a/src/main/java/io/avaje/logback/encoder/StackElementFilter.java b/src/main/java/io/avaje/logback/encoder/StackElementFilter.java index cd0583f..267caf4 100644 --- a/src/main/java/io/avaje/logback/encoder/StackElementFilter.java +++ b/src/main/java/io/avaje/logback/encoder/StackElementFilter.java @@ -22,28 +22,31 @@ * Component in charge of accepting or rejecting {@link StackTraceElement elements} when computing a * stack trace hash */ -public abstract class StackElementFilter { +public interface StackElementFilter { + + /** + * Return a Builder for common stack element filters. + */ + static Builder builder() { + return new FilterBuilder(); + } + /** - * Tests whether or not the specified {@link StackTraceElement} should be accepted when computing + * Tests whether the specified {@link StackTraceElement} should be accepted when computing * a stack hash. * * @param element The {@link StackTraceElement} to be tested * @return {@code true} if and only if {@code element} should be accepted */ - public abstract boolean accept(StackTraceElement element); + boolean accept(StackTraceElement element); /** * Creates a {@link StackElementFilter} that accepts any stack trace elements * * @return the filter */ - public static StackElementFilter any() { - return new StackElementFilter() { - @Override - public boolean accept(StackTraceElement element) { - return true; - } - }; + static StackElementFilter any() { + return element -> true; } /** @@ -53,13 +56,8 @@ public boolean accept(StackTraceElement element) { * * @return the filter */ - public static StackElementFilter withSourceInfo() { - return new StackElementFilter() { - @Override - public boolean accept(StackTraceElement element) { - return element.getFileName() != null && element.getLineNumber() >= 0; - } - }; + static StackElementFilter withSourceInfo() { + return element -> element.getFileName() != null && element.getLineNumber() >= 0; } /** @@ -68,20 +66,50 @@ public boolean accept(StackTraceElement element) { * @param excludes regular expressions matching {@link StackTraceElement} to filter out * @return the filter */ - public static StackElementFilter byPattern(final List excludes) { - return new StackElementFilter() { - @Override - public boolean accept(StackTraceElement element) { - if (!excludes.isEmpty()) { - final String classNameAndMethod = element.getClassName() + "." + element.getMethodName(); - for (final Pattern exclusionPattern : excludes) { - if (exclusionPattern.matcher(classNameAndMethod).find()) { - return false; - } - } - } - return true; - } - }; + static StackElementFilter byPattern(final List excludes) { + return builder().byPattern(excludes).build(); + } + + /** + * Builder for common StackElementFilters. + */ + interface Builder { + + /** + * Include generated classes in the filter containing + * {@code $$FastClassByCGLIB$$} and {@code $$EnhancerBySpringCGLIB$$} + */ + Builder generated(); + + /** + * Include reflective invocation in the filter. + */ + Builder reflectiveInvocation(); + + /** + * Include jdk internal classes in the filter. + */ + Builder jdkInternals(); + + /** + * Include Spring Framework dynamic invocation and plumbing in the filter. + */ + Builder spring(); + + /** + * Include the regex patterns in the filter. + */ + Builder byPattern(List excludes); + + /** + * Include all the standard filters generated, reflective invocation, jdk internals and spring. + */ + Builder allFilters(); + + /** + * Build and return the StackElementFilter with the given options. + */ + StackElementFilter build(); + } } diff --git a/src/main/java/io/avaje/logback/encoder/StackHasher.java b/src/main/java/io/avaje/logback/encoder/StackHasher.java new file mode 100644 index 0000000..2ebe380 --- /dev/null +++ b/src/main/java/io/avaje/logback/encoder/StackHasher.java @@ -0,0 +1,121 @@ +/* + * Copyright 2013-2023 the original author or authors. + * + * Licensed 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 io.avaje.logback.encoder; + +import java.util.ArrayDeque; +import java.util.Deque; + +/** + * Utility class that generates a hash from any Java {@link Throwable error} + * + * @author Pierre Smeyers + */ +public final class StackHasher { + + private final StackElementFilter filter; + + /** + * Constructs a {@link StackHasher} with the given filter. + * + * @param filter filter + */ + public StackHasher(StackElementFilter filter) { + this.filter = filter; + } + + /** + * Constructs a {@link StackHasher} using {@link StackElementFilter#withSourceInfo()} filter + */ + public StackHasher() { + this(StackElementFilter.withSourceInfo()); + } + + /** + * Generates a Hexadecimal hash for the given error stack. + *

+ * Two errors with the same stack hash are most probably same errors. + * + * @param error the error to generate a hash from + * @return the generated hexadecimal hash + */ + public String hexHash(Throwable error) { + // compute topmost error hash, but don't queue the complete hashes chain + return toHex(hash(error, null)); + } + + /** + * Generates and returns Hexadecimal hashes for the error stack and each ancestor {@link Throwable#getCause() cause}. + *

+ * The first queue element is the stack hash for the topmost error, the next one (if any) is it's direct + * {@link Throwable#getCause() cause} hash, and so on... + * + * @param error the error to generate a hash from + * @return a Dequeue with hashes + */ + public Deque hexHashes(Throwable error) { + Deque hexHashes = new ArrayDeque(); + hash(error, hexHashes); + return hexHashes; + } + + /** + * Generates a hash (int) of the given error stack. + *

+ * Two errors with the same stack hash are most probably same errors. + * + * @param error the error to generate a hash from + * @param hexHashes + * @return the generated hexadecimal hash + */ + int hash(Throwable error, Deque hexHashes) { + int hash = 0; + + // compute parent error hash + if (error.getCause() != null && error.getCause() != error) { + // has parent error + hash = hash(error.getCause(), hexHashes); + } + + // then this error hash + // hash error classname + hash = 31 * hash + error.getClass().getName().hashCode(); + // hash stacktrace + for (StackTraceElement element : error.getStackTrace()) { + if (filter.accept(element)) { + hash = 31 * hash + hash(element); + } + } + + // push hexadecimal representation of hash + if (hexHashes != null) { + hexHashes.push(toHex(hash)); + } + + return hash; + } + + String toHex(int hash) { + return String.format("%08x", hash); + } + + int hash(StackTraceElement element) { + int result = element.getClassName().hashCode(); + result = 31 * result + element.getMethodName().hashCode(); + // let's assume filename is not necessary + result = 31 * result + element.getLineNumber(); + return result; + } +} diff --git a/src/test/java/io/avaje/logback/encoder/EvalTest.java b/src/test/java/io/avaje/logback/encoder/EvalTest.java new file mode 100644 index 0000000..ab02aad --- /dev/null +++ b/src/test/java/io/avaje/logback/encoder/EvalTest.java @@ -0,0 +1,56 @@ +package io.avaje.logback.encoder; + +import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +class EvalTest { + + @BeforeAll + static void beforeAll() { + System.setProperty("my.property", "x42"); + } + + @Test + void eval_basic() { + assertThat(Eval.eval("${my.property}")).isEqualTo("x42"); + } + + @Test + void eval_defaultValue() { + assertThat(Eval.eval("${my.property:someDefaultValue}")).isEqualTo("x42"); + assertThat(Eval.eval("${my.other:someDefaultValue}")).isEqualTo("someDefaultValue"); + assertThat(Eval.eval("${my.other}")).isEqualTo("${my.other}"); + } + + @Test + void eval_nonMatchingEnds() { + assertThat(Eval.eval("my.property")).isEqualTo("my.property"); + assertThat(Eval.eval("${my.property")).isEqualTo("${my.property"); + assertThat(Eval.eval("my.property}")).isEqualTo("my.property}"); + } + + @Test + void toSystemPropertyKey() { + assertThat(Eval.toSystemPropertyKey("FOO")).isEqualTo("foo"); + assertThat(Eval.toSystemPropertyKey("MY_FOO")).isEqualTo("my.foo"); + assertThat(Eval.toSystemPropertyKey("A_MY_FOO")).isEqualTo("a.my.foo"); + assertThat(Eval.toSystemPropertyKey("my.foo")).isEqualTo("my.foo"); + } + + @Test + void k8sComponent_expected() { + assertThat(Eval.k8sComponent("some-x-y")).isEqualTo("some"); + assertThat(Eval.k8sComponent("my-some-x-y")).isEqualTo("my-some"); + assertThat(Eval.k8sComponent("foo-bar-some-x-y")).isEqualTo("foo-bar-some"); + } + + @Test + void k8sComponent_unexpected() { + assertThat(Eval.k8sComponent(null)).isNull(); + assertThat(Eval.k8sComponent("")).isNull(); + assertThat(Eval.k8sComponent("some")).isNull(); + assertThat(Eval.k8sComponent("some-x")).isNull(); + } +} diff --git a/src/test/java/io/avaje/logback/encoder/JsonEncoderTest.java b/src/test/java/io/avaje/logback/encoder/JsonEncoderTest.java index a5bcbf8..78c7b3e 100644 --- a/src/test/java/io/avaje/logback/encoder/JsonEncoderTest.java +++ b/src/test/java/io/avaje/logback/encoder/JsonEncoderTest.java @@ -68,17 +68,33 @@ void encode_component() { } @Test - void throwable_usingDefault() { + void customFieldsEval() { + System.setProperty("some.custom.property", "Hi!"); JsonEncoder encoder = new JsonEncoder(); + encoder.setCustomFields("{\"my-custom\":\"${some.custom.property}\", \"other\": \"myLiteral\", \"more\": 12}"); encoder.start(); byte[] bytes = encoder.encode(createLogEvent(createThrowable())); SimpleMapper simpleMapper = SimpleMapper.builder().build(); Map asMap = simpleMapper.map().fromJson(bytes); - assertThat((String)asMap.get("stacktrace")).startsWith("java.lang.NullPointerException: "); + assertThat((String)asMap.get("my-custom")).isEqualTo("Hi!"); + assertThat((String)asMap.get("other")).isEqualTo("myLiteral"); + assertThat((Long)asMap.get("more")).isEqualTo(12L); } + @Test + void throwable_usingDefault() { + JsonEncoder encoder = new JsonEncoder(); + encoder.start(); + + byte[] bytes = encoder.encode(createLogEvent(createThrowable())); + SimpleMapper simpleMapper = SimpleMapper.builder().build(); + Map asMap = simpleMapper.map().fromJson(bytes); + + assertThat((String)asMap.get("stacktrace")).startsWith("java.lang.NullPointerException: "); + } + @Test void throwable_usingConverter() { final TrimPackageAbbreviator trimPackages = new TrimPackageAbbreviator(); @@ -90,6 +106,29 @@ void throwable_usingConverter() { JsonEncoder encoder = new JsonEncoder(); encoder.setThrowableConverter(converter); + encoder.setIncludeStackHash(false); + encoder.start(); + + byte[] bytes = encoder.encode(createLogEvent(createThrowable())); + SimpleMapper simpleMapper = SimpleMapper.builder().build(); + Map asMap = simpleMapper.map().fromJson(bytes); + + assertThat((String)asMap.get("stacktrace")).startsWith("j.l.NullPointerException: "); + assertThat(asMap).doesNotContainKey("stackhash"); + } + + @Test + void throwable_usingConverter_includeStackHash() { + final TrimPackageAbbreviator trimPackages = new TrimPackageAbbreviator(); + trimPackages.setTargetLength(10); + + final ShortenedThrowableConverter converter = new ShortenedThrowableConverter(); + converter.setMaxDepthPerThrowable(3); + converter.setClassNameAbbreviator(trimPackages); + + JsonEncoder encoder = new JsonEncoder(); + encoder.setThrowableConverter(converter); + encoder.setIncludeStackHash(true); encoder.start(); byte[] bytes = encoder.encode(createLogEvent(createThrowable())); @@ -97,6 +136,7 @@ void throwable_usingConverter() { Map asMap = simpleMapper.map().fromJson(bytes); assertThat((String)asMap.get("stacktrace")).startsWith("j.l.NullPointerException: "); + assertThat(asMap.get("stackhash")).isNotNull(); } @Test diff --git a/src/test/java/io/avaje/logback/encoder/StackElementFilterTest.java b/src/test/java/io/avaje/logback/encoder/StackElementFilterTest.java new file mode 100644 index 0000000..bf7fa68 --- /dev/null +++ b/src/test/java/io/avaje/logback/encoder/StackElementFilterTest.java @@ -0,0 +1,102 @@ +package io.avaje.logback.encoder; + +import org.junit.jupiter.api.Test; + +import java.util.ArrayList; +import java.util.List; +import java.util.regex.Pattern; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.*; + +class StackElementFilterTest { + + @Test + void generated() { + StackElementFilter filter = StackElementFilter.builder().generated().build(); + + assertTrue(filter.accept(new StackTraceElement("a.b.C", "foo", null, 0))); + + assertFalse(filter.accept(new StackTraceElement("a.b.C$$FastClassByCGLIB$$", "foo", null, 0))); + assertFalse(filter.accept(new StackTraceElement("a.b.C$$FastClassByCGLIB$$D", "foo", null, 0))); + assertFalse(filter.accept(new StackTraceElement("a.b.$$EnhancerBySpringCGLIB$$", "foo", null, 0))); + assertFalse(filter.accept(new StackTraceElement("a.b.$$EnhancerBySpringCGLIB$$D", "foo", null, 0))); + } + + @Test + void reflectiveInvoke() { + StackElementFilter filter = StackElementFilter.builder().reflectiveInvocation().build(); + + assertTrue(filter.accept(new StackTraceElement("a.b.C", "invoke", null, 0))); + + assertTrue(filter.accept(new StackTraceElement("java.lang.reflect.A", "notInvoke", null, 0))); + assertTrue(filter.accept(new StackTraceElement("sun.reflect.A", "notInvoke", null, 0))); + assertTrue(filter.accept(new StackTraceElement("net.sf.cglib.proxy.MethodProxy", "notInvoke", null, 0))); + + assertFalse(filter.accept(new StackTraceElement("java.lang.reflect.A", "invoke", null, 0))); + assertFalse(filter.accept(new StackTraceElement("sun.reflect.A", "invoke", null, 0))); + assertFalse(filter.accept(new StackTraceElement("net.sf.cglib.proxy.MethodProxy", "invoke", null, 0))); + } + + @Test + void jdkInternals() { + StackElementFilter filter = StackElementFilter.builder().jdkInternals().build(); + + assertTrue(filter.accept(new StackTraceElement("a.b.C", "invoke", null, 0))); + assertTrue(filter.accept(new StackTraceElement("java.lang.C", "invoke", null, 0))); + + assertFalse(filter.accept(new StackTraceElement("com.sun.A", "any", null, 0))); + assertFalse(filter.accept(new StackTraceElement("sun.net.A", "any", null, 0))); + } + + @Test + void spring() { + StackElementFilter filter = StackElementFilter.builder().spring().build(); + + // accepted + assertTrue(filter.accept(new StackTraceElement("a.b.C", "any", null, 0))); + assertTrue(filter.accept(new StackTraceElement("org.springframework.cglibX", "any", null, 0))); + assertTrue(filter.accept(new StackTraceElement("org.springframework.foo", "any", null, 0))); + assertTrue(filter.accept(new StackTraceElement("org.springframework.Foo", "any", null, 0))); + + // filtered out + final String[] prefixes = new String[]{ + "org.springframework.cglib.", + "org.springframework.transaction.", + "org.springframework.validation.", + "org.springframework.app.", + "org.springframework.aop.", + "org.springframework.ws.", + "org.springframework.web.", + "org.springframework.transaction" + }; + + for (String prefix : prefixes) { + assertThat(filter.accept(new StackTraceElement(prefix, "any", null, 0))) + .describedAs("prefix of "+prefix) + .isFalse(); + } + } + + @Test + void patterns() { + List patterns = new ArrayList<>(); + patterns.add(Pattern.compile("^java\\.util\\.concurrent\\.ThreadPoolExecutor\\.runWorker")); + patterns.add(Pattern.compile("^java\\.lang\\.Thread\\.run$")); + patterns.add(Pattern.compile("My\\$Foo")); + + StackElementFilter filter = StackElementFilter.builder().byPattern(patterns).build(); + + assertFalse(filter.accept(new StackTraceElement("java.util.concurrent.ThreadPoolExecutor", "runWorker", null, 0))); + assertFalse(filter.accept(new StackTraceElement("java.util.concurrent.ThreadPoolExecutor", "runWorkerA", null, 0))); + + assertFalse(filter.accept(new StackTraceElement("java.lang.Thread", "run", null, 0))); + assertTrue(filter.accept(new StackTraceElement("java.lang.Thread", "runX", null, 0))); + assertTrue(filter.accept(new StackTraceElement("java.lang.Thread", "xrun", null, 0))); + + assertFalse(filter.accept(new StackTraceElement("org.My$Foo", "any", null, 0))); + assertFalse(filter.accept(new StackTraceElement("org.BeforeMy$Foo", "any", null, 0))); + assertFalse(filter.accept(new StackTraceElement("org.BeforeMy$FooAfter", "any", null, 0))); + } + +} diff --git a/src/test/java/io/avaje/logback/encoder/StackHasherTest.java b/src/test/java/io/avaje/logback/encoder/StackHasherTest.java new file mode 100644 index 0000000..9976571 --- /dev/null +++ b/src/test/java/io/avaje/logback/encoder/StackHasherTest.java @@ -0,0 +1,147 @@ +/* + * Copyright 2013-2023 the original author or authors. + * + * Licensed 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 io.avaje.logback.encoder; + +import org.junit.jupiter.api.Test; + +import java.util.Deque; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.fail; + +public class StackHasherTest { + + private static class StackTraceElementGenerator { + public static void generateSingle() { + oneSingle(); + } + + public static void oneSingle() { + twoSingle(); + } + + private static void twoSingle() { + threeSingle(); + } + + private static void threeSingle() { + four(); + } + + private static void four() { + five(); + } + + private static void five() { + six(); + } + + private static void six() { + seven(); + } + + private static void seven() { + eight(); + } + + private static void eight() { + throw new RuntimeException("message"); + } + + public static void generateCausedBy() { + oneCausedBy(); + } + + private static void oneCausedBy() { + twoCausedBy(); + } + + private static void twoCausedBy() { + try { + threeSingle(); + } catch (RuntimeException e) { + throw new RuntimeException("wrapper", e); + } + } + } + + @Test + public void one_hash_should_be_generated() { + try { + StackTraceElementGenerator.generateSingle(); + fail("Exception must have been thrown"); + } catch (RuntimeException e) { + // GIVEN + StackHasher hasher = new StackHasher(); + + // WHEN + Deque hashes = hasher.hexHashes(e); + + // THEN + assertThat(hashes).hasSize(1); + } + } + + @Test + public void two_hashes_should_be_generated() { + try { + StackTraceElementGenerator.generateCausedBy(); + fail("Exception must have been thrown"); + } catch (RuntimeException e) { + // GIVEN + StackHasher hasher = new StackHasher(); + + // WHEN + Deque hashes = hasher.hexHashes(e); + + // THEN + assertThat(hashes).hasSize(2); + } + } + private static class OnlyFromStackTraceElementGeneratorFilter implements StackElementFilter { + @Override + public boolean accept(StackTraceElement element) { + return element.getClassName().equals(StackTraceElementGenerator.class.getName()); + } + } + + /** + * Warning: computes expected hash based on StackTraceElementGenerator elements + * + * do not change methods name, line or it will break the test + */ + @Test + public void expected_hash_should_be_generated() { + try { + StackTraceElementGenerator.generateSingle(); + fail("Exception must have been thrown"); + } catch (RuntimeException e) { + // GIVEN + StackHasher hasher = new StackHasher(new OnlyFromStackTraceElementGeneratorFilter()); + + // WHEN + Deque hashes = hasher.hexHashes(e); + + // THEN + assertThat(hashes) + .hasSize(1) + .first().isEqualTo("86983bb4"); + + String hash = hasher.hexHash(e); + assertThat(hash).isEqualTo("86983bb4"); + } + } +} diff --git a/stack-hash.md b/stack-hash.md new file mode 100644 index 0000000..d4e8dfd --- /dev/null +++ b/stack-hash.md @@ -0,0 +1,310 @@ +# Details about stack hash + +This page gives details about the **stack hash** feature (goal and implementation). + + +## Why generating stack hashes? + +Actually the `stack_hash` is meant to identify an error (throwable) with a **short** and **stable** signature, that +will help matching several distinct occurrences of the same type of error: + +* **short** for easing elasticsearch indexing, and take advantage of it (that's why we use a hex encoded hash), +* **stable** is the tricky part, as the same type of error occurring twice may not generate exactly the same stack trace (see below). + +This done, it becomes easy with elasticsearch or any other logs centralization and indexation system to: + +* **count** distinct type of errors that occur in your code over time, +* **count** occurrences and frequency of a given type of error, +* **detect** when a (new) type of error occurred for the first time (maybe linking this to a new version being deployed?). + +The stack hash may also become a simple error id that you can link your bug tracker with... + + +## Stack hash stability challenge by examples + +### Let's consider error stack 1 + +*(the stack trace presented here has been cut by half from useless lines)* + +

+com.xyz.MyApp$MyClient$MyClientException: An error occurred while getting Alice's things(msg)
+  at com.xyz.MyApp$MyClient.getTheThings(MyApp.java:26)
+  at com.xyz.MyApp$MyService.displayThings(MyApp.java:16)
+  at com.xyz.MyApp$MyService$$FastClassByCGLIB$$e7645040.invoke()(aop)
+  at net.sf.cglib.proxy.MethodProxy.invoke()(aop)
+  at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed()(fwk)
+  at sun.reflect.NativeMethodAccessorImpl.invoke0()(aop)
+  at sun.reflect.NativeMethodAccessorImpl.invoke()(aop)
+  at sun.reflect.DelegatingMethodAccessorImpl.invoke()(aop)
+  at java.lang.reflect.Method.invoke()(aop)
+  at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs()(fwk)
+  at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod()(fwk)
+  at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.interceptor.AbstractTraceInterceptor.invoke()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.transaction.interceptor.TransactionInterceptor.invoke()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept()(fwk)
+  at com.xyz.MyApp$MyService$$EnhancerBySpringCGLIB$$c673c675.displayThings(<generated>)(aop)
+  at sun.reflect.GeneratedMethodAccessor647.invoke(Unknown Source)(aop)
+  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)(aop)
+  at java.lang.reflect.Method.invoke(Method.java:498)(aop)
+  at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)(fwk)
+  at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)(fwk)
+  at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116)(fwk)
+  at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)(fwk)
+  at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)(fwk)
+  at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)(fwk)
+  at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963)(fwk)
+  at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)(fwk)
+  at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)(fwk)
+  at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)(fwk)
+  at javax.servlet.http.HttpServlet.service(HttpServlet.java:624)(jee)
+  at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)(fwk)
+  at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)(jee)
+  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)(jee)
+  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)(jee)
+  at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)(jee)
+  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)(jee)
+  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)(jee)
+  ...
+  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)(fwk)
+  at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)(fwk)
+  at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)(fwk)
+  at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)(fwk)
+  at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262)(fwk)
+  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)(jee)
+  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)(jee)
+  ...
+  at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)(jee)
+  at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)(jee)
+  at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1078)(jee)
+  at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)(jee)
+  at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)(jee)
+  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)(jee)
+  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)(jee)
+  at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)(jee)
+  at java.lang.Thread.run(Thread.java:748)(jee)
+  ...
+Caused by: com.xyz.MyApp$HttpStack$HttpError: I/O error on GET http://dummy/user/alice/things(msg)
+  at com.xyz.MyApp$HttpStack.get(MyApp.java:40)
+  at com.xyz.MyApp$MyClient.getTheThings(MyApp.java:24)
+  ... 23 common frames omitted
+Caused by: java.net.SocketTimeoutException: Read timed out(msg)
+  at com.xyz.MyApp$HttpStack.get(MyApp.java:38)
+  ... 24 common frames omitted
+
+ +--- + +Strike out elements may vary from one occurrence to the other: + +* error messages(msg) often contain stuff related to the very error occurrence context, +* AOP generated classes(aop) may vary from one execution to another. + +*Italic* elements are somewhat not stable, or at least useless (purely technical). Ex: + +* JEE container stuff(jee): may change when you upgrade your JEE container version or add/remove/reorganize your servlet filters chain for instance, +* Spring Framework(fwk) underlying stacks (MVC, security) for pretty much the same reason, +* AOP and dynamic invocation(aop): purely technical, and quite implementation-dependent. + +Only **bolded elements** are supposed to be stable. + + +### Now let's consider error stack 2 + +*(shortened)* + +
+com.xyz.MyApp$MyClient$MyClientException: An error occurred while getting Bob's things(msg)
+  at com.xyz.MyApp$MyClient.getTheThings(MyApp.java:26)
+  at com.xyz.MyApp$MyService.displayThings(MyApp.java:16)
+  at com.xyz.MyApp$MyService$$FastClassByCGLIB$$07e70d1e.invoke()(aop)
+  at net.sf.cglib.proxy.MethodProxy.invoke()(aop)
+  at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed()(fwk)
+  at sun.reflect.NativeMethodAccessorImpl.invoke0()(aop)
+  at sun.reflect.NativeMethodAccessorImpl.invoke()(aop)
+  at sun.reflect.DelegatingMethodAccessorImpl.invoke()(aop)
+  at java.lang.reflect.Method.invoke()(aop)
+  at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs()(fwk)
+  at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod()(fwk)
+  at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.interceptor.AbstractTraceInterceptor.invoke()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.transaction.interceptor.TransactionInterceptor.invoke()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept()(fwk)
+  at com.xyz.MyApp$MyService$$EnhancerBySpringCGLIB$$e3f570b1.displayThings(<generated>)(aop)
+  at sun.reflect.GeneratedMethodAccessor737.invoke(Unknown Source)(aop)
+  ...
+Caused by: com.xyz.MyApp$HttpStack$HttpError: I/O error on GET http://dummy/user/bob/things(msg)
+  at com.xyz.MyApp$HttpStack.get(MyApp.java:40)
+  at com.xyz.MyApp$MyClient.getTheThings(MyApp.java:24)
+  ... 23 common frames omitted
+Caused by: java.net.SocketTimeoutException: Read timed out(msg)
+  at com.xyz.MyApp$HttpStack.get(MyApp.java:38)
+  ... 24 common frames omitted
+
+ +--- + +You may see in this example that most of the strike elements have slight differences from error stack +1 (messages and generated classes names). + +Nevertheless it is the same exact error (despite the context is different as it applies to another user), and the goal +here is to be able to count them as *two occurrences of the same error*. + +### Now let's consider error stack 3 + +*(shortened)* + +
+com.xyz.MyApp$MyClient$MyClientException: An error occurred while getting Alice's things(msg)
+  at com.xyz.MyApp$MyClient.getTheThings(MyApp.java:26)
+  at com.xyz.MyApp$MyService.displayThings(MyApp.java:16)
+  at com.xyz.MyApp$MyService$$FastClassByCGLIB$$e7645040.invoke()(aop)
+  at net.sf.cglib.proxy.MethodProxy.invoke()(aop)
+  at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint()(fwk)
+  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()(fwk)
+  at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed()(fwk)
+  at sun.reflect.NativeMethodAccessorImpl.invoke0()(aop)
+  at sun.reflect.NativeMethodAccessorImpl.invoke()(aop)
+  at sun.reflect.DelegatingMethodAccessorImpl.invoke()(aop)
+  at java.lang.reflect.Method.invoke()(aop)
+  ...
+Caused by: com.xyz.MyApp$HttpStack$HttpError: I/O error on GET http://dummy/user/alice/things(msg)
+  at com.xyz.MyApp$HttpStack.get(MyApp.java:40)
+  at com.xyz.MyApp$MyClient.getTheThings(MyApp.java:24)
+  ... 23 common frames omitted
+Caused by: javax.net.ssl.SSLException: Connection has been shutdown: javax.net.ssl.SSLHandshakeException: Received fatal alert: certificate_unknown(msg)
+  at com.sun.net.ssl.internal.ssl.SSLSocketImpl.checkEOF(SSLSocketImpl.java:1172)
+  ... 24 common frames omitted
+
+ +--- + +Here, you can see that the first and second errors are the same as in error stack 1, but the root cause is different (`SSLException` instead of `SocketTimeoutException`). + +So in that case we don't want the top error hash computed for error stack 3 to be the same as for error stack 1. + +## Stack hash computation rules + +As a conclusion, stack hash computation applies the following rules: + +1. a stack hash shall **not compute with the error message** +2. a stack hash shall **compute with it's parent cause** (recurses) +3. in order to stabilize the stack hash (over time and space), it's recommended to **exclude non-stable elements** + + +## Using stack hash in `logstash-logback-encoder` components + +### `StackHashJsonProvider` + +This provider computes the stack hash for any log event with a throwable, and adds it as a single JSON attribute (`stack_hash` by default). + +It also supports defining a list of exclusion patterns. + +### `ShortenedThrowableConverter` + +Setting the `inlineHash` property to `true` in the `net.logstash.logback.stacktrace.ShortenedThrowableConverter` component +computes and inlines stack hashes into the stack trace. + +The exclusion patterns to shorten the stack trace are used to compute the stack hashes too. + +Note: if no exclusion pattern is specified and the `inlineHash` property is active, a minimal filter is used to filter out +elements with no source info (null filename or linenumber < 0) to ignore generated classnames. The drawback is that it +will also exclude classes not compiled in debug mode (do not contain source info). + +## Recommended exclusion patterns + +In a spring framework context, the following exclusion patterns produce pretty stable hashes: + +```xml + + + \$\$FastClassByCGLIB\$\$ + \$\$EnhancerBySpringCGLIB\$\$ + ^sun\.reflect\..*\.invoke + + ^com\.sun\. + ^sun\.net\. + + ^net\.sf\.cglib\.proxy\.MethodProxy\.invoke + ^org\.springframework\.cglib\. + ^org\.springframework\.transaction\. + ^org\.springframework\.validation\. + ^org\.springframework\.app\. + ^org\.springframework\.aop\. + ^java\.lang\.reflect\.Method\.invoke + + ^org\.springframework\.ws\..*\.invoke + ^org\.springframework\.ws\.transport\. + ^org\.springframework\.ws\.soap\.saaj\.SaajSoapMessage\. + ^org\.springframework\.ws\.client\.core\.WebServiceTemplate\. + ^org\.springframework\.web\.filter\. + + ^org\.apache\.tomcat\. + ^org\.apache\.catalina\. + ^org\.apache\.coyote\. + ^java\.util\.concurrent\.ThreadPoolExecutor\.runWorker + ^java\.lang\.Thread\.run$ + +``` + +Also notice that both `StackHashJsonProvider` and `ShortenedThrowableConverter` components support a single `` +element to set all exclusion patterns at once (as a coma separated list): + +```xml + + + \$\$FastClassByCGLIB\$\$,\$\$EnhancerBySpringCGLIB\$\$,^sun\.reflect\..*\.invoke,^com\.sun\.,^sun\.net\.,^net\.sf\.cglib\.proxy\.MethodProxy\.invoke,^org\.springframework\.cglib\.,^org\.springframework\.transaction\.,^org\.springframework\.validation\.,^org\.springframework\.app\.,^org\.springframework\.aop\.,^java\.lang\.reflect\.Method\.invoke,^org\.springframework\.ws\..*\.invoke,^org\.springframework\.ws\.transport\.,^org\.springframework\.ws\.soap\.saaj\.SaajSoapMessage\.,^org\.springframework\.ws\.client\.core\.WebServiceTemplate\.,^org\.springframework\.web\.filter\.,^org\.apache\.tomcat\.,^org\.apache\.catalina\.,^org\.apache\.coyote\.,^java\.util\.concurrent\.ThreadPoolExecutor\.runWorker,^java\.lang\.Thread\.run$ + +``` + +Obviously it is recommended to use either multiple `` elements or one single ``. + +## Tip: variabilize your exclusion patterns! + +If you compute stack hashes with both `StackHashJsonProvider` and `ShortenedThrowableConverter` components, +it is highly recommended to use **the same exclusion patterns** for both or - in some cases - you will not get same hashes. + +In such a case, or even if you just want to make the exclusion patterns configurable, you shall use the `` +field (see above) in conjunction with a Logback variable. + +Here is an example: + +```xml + + + + + + + ... + + + true + + ${STE_EXCLUSIONS} + + + ... + + + ${STE_EXCLUSIONS} + + ... + + + +```