diff --git a/examples/gradle/build.gradle b/examples/gradle/build.gradle index 3713f92..f7266af 100644 --- a/examples/gradle/build.gradle +++ b/examples/gradle/build.gradle @@ -7,7 +7,7 @@ repositories { } dependencies { - implementation 'com.logtail:logback-logtail:0.3.5' + implementation 'com.logtail:logback-logtail:0.3.6' implementation 'ch.qos.logback:logback-classic:1.2.11' implementation 'ch.qos.logback:logback-core:1.2.11' implementation 'com.fasterxml.jackson.core:jackson-databind:2.13.5' diff --git a/examples/maven/pom.xml b/examples/maven/pom.xml index 0a8ee59..48bfaef 100644 --- a/examples/maven/pom.xml +++ b/examples/maven/pom.xml @@ -26,7 +26,7 @@ com.logtail logback-logtail - 0.3.5 + 0.3.6 ch.qos.logback diff --git a/pom.xml b/pom.xml index dffb4e1..e1bda28 100644 --- a/pom.xml +++ b/pom.xml @@ -11,7 +11,7 @@ com.logtail logback-logtail jar - 0.3.5 + 0.3.6 ${project.groupId}:${project.artifactId} Logback Java appender for sending logs to BetterStack.com diff --git a/src/main/java/com/logtail/logback/BestEffortSerialization.java b/src/main/java/com/logtail/logback/BestEffortSerialization.java new file mode 100644 index 0000000..820ed9c --- /dev/null +++ b/src/main/java/com/logtail/logback/BestEffortSerialization.java @@ -0,0 +1,204 @@ +package com.logtail.logback; + +import com.fasterxml.jackson.core.JsonGenerator; +import com.fasterxml.jackson.databind.BeanDescription; +import com.fasterxml.jackson.databind.BeanProperty; +import com.fasterxml.jackson.databind.JsonMappingException; +import com.fasterxml.jackson.databind.JsonSerializer; +import com.fasterxml.jackson.databind.SerializationConfig; +import com.fasterxml.jackson.databind.SerializerProvider; +import com.fasterxml.jackson.databind.jsontype.TypeSerializer; +import com.fasterxml.jackson.databind.module.SimpleModule; +import com.fasterxml.jackson.databind.ser.BeanSerializerModifier; +import com.fasterxml.jackson.databind.ser.ContextualSerializer; +import com.fasterxml.jackson.databind.ser.ResolvableSerializer; +import com.fasterxml.jackson.databind.type.ArrayType; +import com.fasterxml.jackson.databind.type.CollectionType; +import com.fasterxml.jackson.databind.type.MapType; +import com.fasterxml.jackson.databind.util.NameTransformer; +import com.fasterxml.jackson.databind.util.TokenBuffer; + +import java.io.IOException; +import java.util.Collections; +import java.util.IdentityHashMap; +import java.util.Set; + +/** + * Jackson module making serialization of arbitrary logged values best-effort instead of all-or-nothing, + * in a single serialization pass. Values serialize into the same JSON as without this module, except that + * data Jackson cannot handle is omitted and replaced with a marker string: + * + */ +public class BestEffortSerialization extends SimpleModule { + + static final String CIRCULAR_REFERENCE_MARKER = ""; + + private static final Object ANCESTORS = new Object(); + + public BestEffortSerialization() { + addSerializer(Guarded.class, new GuardedSerializer()); + setSerializerModifier(new BeanSerializerModifier() { + @Override + public JsonSerializer modifySerializer(SerializationConfig config, BeanDescription beanDesc, JsonSerializer serializer) { + return new CycleGuard(serializer); + } + + @Override + public JsonSerializer modifyArraySerializer(SerializationConfig config, ArrayType valueType, BeanDescription beanDesc, JsonSerializer serializer) { + return new CycleGuard(serializer); + } + + @Override + public JsonSerializer modifyCollectionSerializer(SerializationConfig config, CollectionType valueType, BeanDescription beanDesc, JsonSerializer serializer) { + return new CycleGuard(serializer); + } + + @Override + public JsonSerializer modifyMapSerializer(SerializationConfig config, MapType valueType, BeanDescription beanDesc, JsonSerializer serializer) { + return new CycleGuard(serializer); + } + }); + } + + /** + * Wraps a value of an unknown type so that when its serialization fails, it is replaced with a marker + * string instead of failing the serialization of everything around it. + */ + public static Object guard(Object value) { + if (value == null || isSafeScalar(value)) { + return value; + } + return new Guarded(value); + } + + // Only exact final JDK types whose serializers cannot fail may skip the guard - an instanceof check + // is not enough, e.g. a Number subclass can still throw from the toString Jackson serializes it with + private static boolean isSafeScalar(Object value) { + Class type = value.getClass(); + return type == String.class || type == Boolean.class || type == Character.class + || type == Integer.class || type == Long.class || type == Double.class + || type == Float.class || type == Short.class || type == Byte.class; + } + + static final class Guarded { + final Object value; + + Guarded(Object value) { + this.value = value; + } + } + + static final class GuardedSerializer extends JsonSerializer { + @Override + public void serialize(Guarded guarded, JsonGenerator gen, SerializerProvider provider) throws IOException { + // Serialized into a buffer first, so a failure halfway through leaves no partial output behind + TokenBuffer buffer = new TokenBuffer(gen.getCodec(), false); + try { + provider.defaultSerializeValue(guarded.value, buffer); + } catch (Exception | StackOverflowError e) { + gen.writeString(""); + return; + } + buffer.serialize(gen); + } + + @Override + public void serializeWithType(Guarded guarded, JsonGenerator gen, SerializerProvider provider, TypeSerializer typeSer) throws IOException { + // The wrapper is invisible in the output, so there is no type id to write for it - the + // wrapped value's own serializer emits its type info inside the buffer + serialize(guarded, gen, provider); + } + } + + static final class CycleGuard extends JsonSerializer implements ContextualSerializer, ResolvableSerializer { + private final JsonSerializer delegate; + + @SuppressWarnings("unchecked") + CycleGuard(JsonSerializer delegate) { + this.delegate = (JsonSerializer) delegate; + } + + @Override + public void serialize(Object value, JsonGenerator gen, SerializerProvider provider) throws IOException { + if (!enter(provider, value)) { + gen.writeString(CIRCULAR_REFERENCE_MARKER); + return; + } + try { + delegate.serialize(value, gen, provider); + } finally { + leave(provider, value); + } + } + + @Override + public void serializeWithType(Object value, JsonGenerator gen, SerializerProvider provider, TypeSerializer typeSer) throws IOException { + if (!enter(provider, value)) { + gen.writeString(CIRCULAR_REFERENCE_MARKER); + return; + } + try { + delegate.serializeWithType(value, gen, provider, typeSer); + } finally { + leave(provider, value); + } + } + + @Override + public boolean isEmpty(SerializerProvider provider, Object value) { + return delegate.isEmpty(provider, value); + } + + @Override + public JsonSerializer unwrappingSerializer(NameTransformer transformer) { + return new CycleGuard(delegate.unwrappingSerializer(transformer)); + } + + @Override + public boolean isUnwrappingSerializer() { + return delegate.isUnwrappingSerializer(); + } + + @Override + public void resolve(SerializerProvider provider) throws JsonMappingException { + if (delegate instanceof ResolvableSerializer) { + ((ResolvableSerializer) delegate).resolve(provider); + } + } + + @Override + public JsonSerializer createContextual(SerializerProvider provider, BeanProperty property) throws JsonMappingException { + if (delegate instanceof ContextualSerializer) { + JsonSerializer contextual = ((ContextualSerializer) delegate).createContextual(provider, property); + if (contextual != delegate) { + return new CycleGuard(contextual); + } + } + return this; + } + } + + private static boolean enter(SerializerProvider provider, Object value) { + Set ancestors = ancestors(provider); + if (ancestors == null) { + ancestors = Collections.newSetFromMap(new IdentityHashMap()); + provider.setAttribute(ANCESTORS, ancestors); + } + return ancestors.add(value); + } + + private static void leave(SerializerProvider provider, Object value) { + ancestors(provider).remove(value); + } + + @SuppressWarnings("unchecked") + private static Set ancestors(SerializerProvider provider) { + return (Set) provider.getAttribute(ANCESTORS); + } +} diff --git a/src/main/java/com/logtail/logback/LogtailAppender.java b/src/main/java/com/logtail/logback/LogtailAppender.java index 029c4d9..d857e83 100644 --- a/src/main/java/com/logtail/logback/LogtailAppender.java +++ b/src/main/java/com/logtail/logback/LogtailAppender.java @@ -77,7 +77,8 @@ public LogtailAppender() { dataMapper = new ObjectMapper() .setSerializationInclusion(JsonInclude.Include.NON_NULL) .setPropertyNamingStrategy(PropertyNamingStrategies.UPPER_CAMEL_CASE) - .disable(SerializationFeature.FAIL_ON_EMPTY_BEANS); + .disable(SerializationFeature.FAIL_ON_EMPTY_BEANS) + .registerModule(new BestEffortSerialization()); scheduledExecutorService = Executors.newSingleThreadScheduledExecutor(threadFactory); scheduledFuture = scheduledExecutorService.scheduleWithFixedDelay(new LogtailSender(), batchInterval, batchInterval, TimeUnit.MILLISECONDS); @@ -269,7 +270,7 @@ protected Map buildPostData(ILoggingEvent event) { logLine.put("message", generateLogMessage(event)); logLine.put("meta", generateLogMeta(event)); logLine.put("runtime", generateLogRuntime(event)); - logLine.put("args", event.getArgumentArray()); + logLine.put("args", guardArguments(event.getArgumentArray())); if (event.getThrowableProxy() != null) { logLine.put("throwable", generateLogThrowable(event.getThrowableProxy())); } @@ -277,6 +278,13 @@ protected Map buildPostData(ILoggingEvent event) { return logLine; } + protected Object[] guardArguments(Object[] arguments) { + if (arguments == null) { + return null; + } + return Arrays.stream(arguments).map(BestEffortSerialization::guard).toArray(); + } + protected String generateLogMessage(ILoggingEvent event) { return this.encoder != null ? new String(this.encoder.encode(event)) : event.getFormattedMessage(); } diff --git a/src/test/java/com/logtail/logback/BestEffortSerializationTest.java b/src/test/java/com/logtail/logback/BestEffortSerializationTest.java new file mode 100644 index 0000000..d838e7c --- /dev/null +++ b/src/test/java/com/logtail/logback/BestEffortSerializationTest.java @@ -0,0 +1,77 @@ +package com.logtail.logback; + +import com.fasterxml.jackson.annotation.JsonInclude; +import com.fasterxml.jackson.annotation.JsonUnwrapped; +import com.fasterxml.jackson.databind.ObjectMapper; +import com.fasterxml.jackson.databind.jsontype.impl.LaissezFaireSubTypeValidator; +import org.junit.Test; + +import java.util.ArrayList; +import java.util.HashMap; +import java.util.List; +import java.util.Map; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertTrue; + +/** + * For anything that serializes fine, the module must be invisible: its output has to be + * byte-identical to a plain ObjectMapper, including for Jackson annotations that change + * how a serializer is used ({@code @JsonUnwrapped}) or when a value is included + * ({@code @JsonInclude(NON_EMPTY)}). + */ +public class BestEffortSerializationTest { + + private final ObjectMapper plain = new ObjectMapper(); + private final ObjectMapper bestEffort = new ObjectMapper().registerModule(new BestEffortSerialization()); + + public static class Name { + public String getFirst() { + return "Ada"; + } + + public String getLast() { + return "Lovelace"; + } + } + + public static class UnwrappedName { + @JsonUnwrapped + public Name getName() { + return new Name(); + } + } + + public static class NonEmptyItems { + @JsonInclude(JsonInclude.Include.NON_EMPTY) + public List getItems() { + return new ArrayList<>(); + } + } + + @Test + public void testUnwrappedPropertiesStayFlattened() throws Exception { + assertEquals(plain.writeValueAsString(new UnwrappedName()), + bestEffort.writeValueAsString(new UnwrappedName())); + } + + @Test + public void testEmptyValueInclusionIsRespected() throws Exception { + assertEquals(plain.writeValueAsString(new NonEmptyItems()), + bestEffort.writeValueAsString(new NonEmptyItems())); + } + + @Test + public void testGuardedValuesSurvivePolymorphicTyping() throws Exception { + ObjectMapper typed = new ObjectMapper() + .registerModule(new BestEffortSerialization()) + .activateDefaultTyping(LaissezFaireSubTypeValidator.instance, ObjectMapper.DefaultTyping.OBJECT_AND_NON_CONCRETE); + + Map value = new HashMap<>(); + value.put("key", "value"); + + String json = typed.writeValueAsString(new Object[]{BestEffortSerialization.guard(value)}); + + assertTrue("Guarded values must serialize under polymorphic typing", json.contains("\"key\":\"value\"")); + } +} diff --git a/src/test/java/com/logtail/logback/LogtailAppenderSerializationTest.java b/src/test/java/com/logtail/logback/LogtailAppenderSerializationTest.java new file mode 100644 index 0000000..ce9fa34 --- /dev/null +++ b/src/test/java/com/logtail/logback/LogtailAppenderSerializationTest.java @@ -0,0 +1,207 @@ +package com.logtail.logback; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.LoggingEvent; +import com.fasterxml.jackson.databind.node.JsonNodeFactory; +import com.fasterxml.jackson.databind.node.ObjectNode; +import org.junit.Before; +import org.junit.Test; + +import java.util.ArrayList; +import java.util.Collections; +import java.util.HashMap; +import java.util.List; +import java.util.Map; + +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertTrue; + +/** + * A log argument that Jackson cannot serialize - a cyclic object graph (e.g. a JDBC Connection, which + * HikariCP logs on every pooled connection creation), or a value whose getter throws - must never + * prevent the batch from being sent. The unserializable data itself is omitted and replaced with a + * marker string; everything around it stays structured JSON. + */ +public class LogtailAppenderSerializationTest { + + // Stand-in for any cyclic object graph a dependency might log, e.g. PgConnection <-> PgDatabaseMetaData + static class Parent { + Child child; + + public Child getChild() { + return child; + } + } + + static class Child { + Parent parent; + + public Parent getParent() { + return parent; + } + } + + // Stand-in for any argument Jackson chokes on for a reason other than a cycle + static class Unserializable { + public String getValue() { + throw new UnsupportedOperationException("not available"); + } + } + + // Number is not final: a subclass can fail during serialization (Jackson stringifies unknown + // Number types via toString), and scalar-looking arguments must not get a free pass because of it + static class BrokenNumber extends Number { + @Override + public int intValue() { + throw new UnsupportedOperationException("not available"); + } + + @Override + public long longValue() { + throw new UnsupportedOperationException("not available"); + } + + @Override + public float floatValue() { + throw new UnsupportedOperationException("not available"); + } + + @Override + public double doubleValue() { + throw new UnsupportedOperationException("not available"); + } + + @Override + public String toString() { + throw new UnsupportedOperationException("not available"); + } + } + + private LogtailAppender appender; + private Logger logger; + + @Before + public void setUp() { + logger = new LoggerContext().getLogger(Logger.ROOT_LOGGER_NAME); + + appender = new LogtailAppender(); + appender.setAppName("BetterStackTest"); + appender.setSourceToken("dummy-token"); // any non-empty value; no request is made by these tests + } + + @Test + public void testCyclicArgumentIsOmittedAtTheCycleOnly() throws Exception { + Parent parent = new Parent(); + Child child = new Child(); + parent.child = child; + child.parent = parent; // the cycle + + log("Log line before the cyclic one"); + // Equivalent to HikariPool's: LOGGER.debug("{} - Added connection {}", poolName, poolEntry.connection); + log("Some object graph: {} and a sibling argument: {}", parent, Collections.singletonMap("sibling", true)); + log("Log line after the cyclic one: {}", Collections.singletonMap("orderId", 42)); + + String json = appender.batchToJson(3); + + assertTrue("Log line before the cyclic one must be sent", json.contains("Log line before the cyclic one")); + assertTrue("The cyclic log line itself must be sent", json.contains("Some object graph:")); + assertTrue("Log line after the cyclic one must be sent", json.contains("Log line after the cyclic one:")); + + assertTrue("The cyclic argument must stay structured up to the point where it loops back", + json.contains("{\"Child\":{\"Parent\":\"\"}}")); + assertTrue("Sibling arguments of the cyclic one must stay structured", + json.contains("{\"sibling\":true}")); + assertTrue("Arguments of other log lines must stay structured", + json.contains("{\"orderId\":42}")); + } + + @Test + public void testCyclicContainerArgumentsAreOmittedAtTheCycleOnly() throws Exception { + Map map = new HashMap<>(); + map.put("self", map); + List list = new ArrayList<>(); + list.add(list); + Object[] array = new Object[1]; + array[0] = array; + + log("A cyclic map: {}", map); + log("A cyclic list: {}", list); + log("A cyclic array: {}", new Object[]{array}); + + String json = appender.batchToJson(3); + + assertTrue("The cyclic map must be sent with its cycle omitted", + json.contains("{\"self\":\"\"}")); + assertTrue("The cyclic list and array must be sent with their cycles omitted", + json.contains("[\"\"]")); + assertTrue(json.contains("A cyclic map:")); + assertTrue(json.contains("A cyclic list:")); + assertTrue(json.contains("A cyclic array:")); + } + + @Test + public void testUnserializableArgumentIsOmittedWithAMarker() throws Exception { + log("Log line with a broken argument: {}", new Unserializable()); + log("Log line after the broken one"); + + String json = appender.batchToJson(2); + + assertTrue("The broken log line itself must be sent", json.contains("Log line with a broken argument:")); + assertTrue("Log line after the broken one must be sent", json.contains("Log line after the broken one")); + assertTrue("The broken argument must be replaced with a marker naming its class", + json.contains("\"\"")); + } + + @Test + public void testCyclicArgumentOutsideGuardedTypesDoesNotDropTheBatch() throws Exception { + // JsonNode serializes through its own JsonSerializable path, which no serializer-modifier hook + // wraps - the cycle guard cannot see this cycle, so it must fall back to whole-argument omission + ObjectNode node = JsonNodeFactory.instance.objectNode(); + node.put("key", "value"); + node.set("self", node); + + log("A cyclic JsonNode: {}", node); + log("Log line after the cyclic node"); + + String json = appender.batchToJson(2); + + assertTrue("Log line after the cyclic node must be sent", json.contains("Log line after the cyclic node")); + assertTrue("A cycle the cycle guard cannot see must still be omitted as a whole argument", + json.contains("\"\"")); + } + + @Test + public void testBrokenScalarLikeArgumentDoesNotDropTheBatch() throws Exception { + log("Log line with a broken number: {}", new BrokenNumber()); + log("Log line after the broken number"); + + String json = appender.batchToJson(2); + + assertTrue("The broken log line itself must be sent", json.contains("Log line with a broken number:")); + assertTrue("Log line after the broken number must be sent", json.contains("Log line after the broken number")); + assertTrue("The broken argument must be replaced with a marker naming its class", + json.contains("\"\"")); + } + + @Test + public void testRepeatedReferencesAreNotMistakenForCycles() throws Exception { + Map shared = Collections.singletonMap("value", 42); + Map argument = new HashMap<>(); + argument.put("first", shared); + argument.put("second", shared); + + log("Same object referenced twice: {}", argument); + + String json = appender.batchToJson(1); + + assertFalse("A repeated reference is not a cycle and must not be omitted", json.contains("omitted")); + assertTrue(json.contains("\"first\":{\"value\":42}")); + assertTrue(json.contains("\"second\":{\"value\":42}")); + } + + private void log(String message, Object... args) { + appender.append(new LoggingEvent(Logger.FQCN, logger, Level.INFO, message, null, args)); + } +}