search

logfellow / logstash-logback-encoder

Logback JSON encoder and appenders
Apache License 2.0
2.43k stars 407 forks source link

Slf4j v2 addKeyValue fluent API silently ignores all logs where Protobuf objects are given #1007

Closed Proximyst closed 1 month ago

Proximyst commented 7 months ago

Describe the bug

If a protobuf object is given to the addKeyValue fluent methods, no log is output, regardless of severity level.

To Reproduce

Here is a minimal reproduction repository: https://github.com/Proximyst/logstash-encoder-addkeyvalue-ignoring-objects-bug

Steps:

  1. Have a Protobuf object
  2. Call LOGGER.atError().withKeyValue("obj", protobufObject).log("test")
  3. See the ERROR severity log be silently swallowed with no output whatsoever

Expected behavior

At the very least output what goes wrong in logging. Preferably, of course, it should just log it properly (be it as a string, as a proper object, or some other way). Even ignoring the specific field would be miles better than how it works today.

Additional context Add any other context about the problem here.

philsttr commented 1 month ago

Hi @Proximyst

Thanks for an excellent bug report. The reproducer is great. I wish every bug report was as good as this one.

Errors that occur within logback during encoding/appending can be seen by enabling a logback status listener. This is a logback feature, and not specific to logstash-logback-encoder.

When doing so in your example project, I see the following error:

2:39:34,929 |-WARN in net.logstash.logback.encoder.LogstashEncoder@4686afc2 - Error encountered while encoding log event. Event: [ERROR] Super mega important log message with large business value com.fasterxml.jackson.databind.exc.InvalidDefinitionException: Direct self-reference leading to cycle (through reference chain: com.spotify.logstashbug.proto.TestMessage["unknownFields"]->com.google.protobuf.UnknownFieldSet["defaultInstanceForType"])
    at com.fasterxml.jackson.databind.exc.InvalidDefinitionException: Direct self-reference leading to cycle (through reference chain: com.spotify.logstashbug.proto.TestMessage["unknownFields"]->com.google.protobuf.UnknownFieldSet["defaultInstanceForType"])
    at  at com.fasterxml.jackson.databind.exc.InvalidDefinitionException.from(InvalidDefinitionException.java:77)
    at  at com.fasterxml.jackson.databind.SerializerProvider.reportBadDefinition(SerializerProvider.java:1330)
    at  at com.fasterxml.jackson.databind.ser.BeanPropertyWriter._handleSelfReference(BeanPropertyWriter.java:948)
    at  at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:726)
    at  at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:770)
    at  at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:183)
    at  at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:732)
    at  at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:770)
    at  at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:183)
    at  at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.java:502)
    at  at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:341)
    at  at com.fasterxml.jackson.databind.ObjectMapper.writeValue(ObjectMapper.java:3362)
    at  at com.fasterxml.jackson.core.base.GeneratorBase.writeObject(GeneratorBase.java:407)
    at  at net.logstash.logback.util.SimpleObjectJsonGeneratorDelegate.writeObject(SimpleObjectJsonGeneratorDelegate.java:186)
    at  at net.logstash.logback.composite.loggingevent.KeyValuePairsJsonProvider.writeTo(KeyValuePairsJsonProvider.java:106)
    at  at net.logstash.logback.composite.loggingevent.KeyValuePairsJsonProvider.writeTo(KeyValuePairsJsonProvider.java:62)
    at  at net.logstash.logback.composite.JsonProviders.writeTo(JsonProviders.java:78)
    at  at net.logstash.logback.composite.AbstractCompositeJsonFormatter.writeEventToGenerator(AbstractCompositeJsonFormatter.java:290)
    at  at net.logstash.logback.composite.AbstractCompositeJsonFormatter$JsonFormatter.writeEvent(AbstractCompositeJsonFormatter.java:190)
    at  at net.logstash.logback.composite.AbstractCompositeJsonFormatter.writeEvent(AbstractCompositeJsonFormatter.java:156)
    at  at net.logstash.logback.encoder.CompositeJsonEncoder.encode(CompositeJsonEncoder.java:106)
    at  at net.logstash.logback.encoder.CompositeJsonEncoder.encode(CompositeJsonEncoder.java:92)
    at  at net.logstash.logback.encoder.CompositeJsonEncoder.encode(CompositeJsonEncoder.java:36)
    at  at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:192)
    at  at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:237)
    at  at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
    at  at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
    at  at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
    at  at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
    at  at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
    at  at ch.qos.logback.classic.Logger.log(Logger.java:817)
    at  at org.slf4j.spi.DefaultLoggingEventBuilder.log(DefaultLoggingEventBuilder.java:147)
    at  at org.slf4j.spi.DefaultLoggingEventBuilder.log(DefaultLoggingEventBuilder.java:109)
    at  at com.spotify.logstashbug.Main.main(Main.java:16)

The error indicates that jackson is not able to serialize the value.

When using logstash-logback-encoder, it's up to the user to ensure that values passed to withKeyValue are serializable by jackson.

Doing some googling, I found https://github.com/HubSpot/jackson-datatype-protobuf, which seems to enable Jackson to serialize protobuf objects as json. I've never used it, but you could give it a shot. See instructions for customizing jackson in the readme.

You could also pass other representations of the object to withKeyValue. For example pass the .toString() representation of the object.