Logstash: 8.10.2: Issues with fasterxml: Can not write a field name, expecting a value

[rpasche]

Hello,

setting log.format: "json" throws lot of "com.fasterxml.j ackson.core.JsonGenerationException: Can not write a field name, expecting a value

steps to verify this issue with official docker image (8.10.2)

Create custom logstash.yml file and make sure, the log.format: "json" is set (this triggers the error).

# logstash.yml
log.format: "json"
http.host: "0.0.0.0"
pipeline.ecs_compatibility: "disabled"
#log.level: "debug"

create a custom pipeline configuration

# logstash.conf
input {
  http {
    port => "1080"
  }
}

filter {}

output {
  stdout {
    codec => rubydebug { metadata => true }
  }
}

Run logstash via

docker run --rm -it -v $(pwd)/logstash.yml:/usr/share/logstash/config/logstash.yml -v $(pwd)/logstash.conf:/usr/share/logstash/pipeline/logstash.conf logstash:8.10.2

You will directly see that error

/logstash_test$ docker run --rm -it -v $(pwd)/logstash.yml:/usr/share/logstash/config/logstash.yml -v $(pwd)/logstash_config.conf:/usr/share/logstash/pipeline/logstash.conf logstash:8.10.2
Using bundled JDK: /usr/share/logstash/jdk
Sending Logstash logs to /usr/share/logstash/logs which is now configured via log4j2.properties
{"level":"INFO","loggerName":"logstash.runner","timeMillis":1696853661724,"thread":"main","logEvent":{"message":"Log4j configuration path used is: /usr/share/logstash/config/log4j2.properties"}}
{"level":"INFO","loggerName":"logstash.runner","timeMillis":1696853661745,"thread":"main","logEvent":{"message":"Starting Logstash","logstash.version":"8.10.2","jruby.version":"jruby 9.4.2.0 (3.1.0) 2023-03-08 90d2913fda OpenJDK 64-Bit Server VM 17.0.8+7 on 17.0.8+7 +indy +jit [x86_64-linux]"}}
{"level":"INFO","loggerName":"logstash.runner","timeMillis":1696853661749,"thread":"main","logEvent":{"message":"JVM bootstrap flags: [-Xms1g, -Xmx1g, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djruby.compile.invokedynamic=true, -XX:+HeapDumpOnOutOfMemoryError, -Djava.security.egd=file:/dev/urandom, -Dlog4j2.isThreadContextMapInheritable=true, -Dls.cgroup.cpuacct.path.override=/, -Dls.cgroup.cpu.path.override=/, -Djruby.regexp.interruptible=true, -Djdk.io.File.enableADS=true, --add-exports=jdk.compiler/com.sun.tools.javac.api=ALL-UNNAMED, --add-exports=jdk.compiler/com.sun.tools.javac.file=ALL-UNNAMED, --add-exports=jdk.compiler/com.sun.tools.javac.parser=ALL-UNNAMED, --add-exports=jdk.compiler/com.sun.tools.javac.tree=ALL-UNNAMED, --add-exports=jdk.compiler/com.sun.tools.javac.util=ALL-UNNAMED, --add-opens=java.base/java.security=ALL-UNNAMED, --add-opens=java.base/java.io=ALL-UNNAMED, --add-opens=java.base/java.nio.channels=ALL-UNNAMED, --add-opens=java.base/sun.nio.ch=ALL-UNNAMED, --add-opens=java.management/sun.management=ALL-UNNAMED]"}}
{"level":"INFO","loggerName":"logstash.settings","timeMillis":1696853661760,"thread":"main","logEvent":{"message":"Creating directory","setting":"path.queue","path":"/usr/share/logstash/data/queue"}}
{"level":"INFO","loggerName":"logstash.settings","timeMillis":1696853661762,"thread":"main","logEvent":{"message":"Creating directory","setting":"path.dead_letter_queue","path":"/usr/share/logstash/data/dead_letter_queue"}}
{"level":"INFO","loggerName":"logstash.agent","timeMillis":1696853661991,"thread":"LogStash::Runner","logEvent":{"message":"No persistent UUID file found. Generating new UUID","uuid":"92b8df7d-3942-43df-9ab3-b49cfcd52378","path":"/usr/share/logstash/data/uuid"}}
{"level":"INFO","loggerName":"logstash.agent","timeMillis":1696853662638,"thread":"Api Webserver","logEvent":{"message":"Successfully started Logstash API endpoint","port":9600,"ssl_enabled":false}}
{"level":"INFO","loggerName":"org.reflections.Reflections","timeMillis":1696853662850,"thread":"Converge PipelineAction::Create<main>","logEvent":{"message":"Reflections took 112 ms to scan 1 urls, producing 132 keys and 464 values"}}
{"level":"INFO","loggerName":"logstash.javapipeline","timeMillis":1696853663143,"thread":"Converge PipelineAction::Create<main>","logEvent":{"message":"Pipeline `main` is configured with `pipeline.ecs_compatibility: disabled` setting. All plugins in this pipeline will default to `ecs_compatibility => disabled` unless explicitly configured otherwise."}}
{"level":"INFO","loggerName":"logstash.javapipeline","timeMillis":1696853663179,"thread":"[main]-pipeline-manager","logEvent":{"message":"Starting pipeline","pipeline_id":"main","pipeline.workers":4,"pipeline.batch.size":125,"pipeline.batch.delay":50,"pipeline.max_inflight":500,"pipeline.sources":["/usr/share/logstash/pipeline/logstash.conf"],"thread":"#<Thread:0x164ef52e /usr/share/logstash/logstash-core/lib/logstash/java_pipeline.rb:134 run>"}}
{"level":"INFO","loggerName":"logstash.javapipeline","timeMillis":1696853663742,"thread":"[main]-pipeline-manager","logEvent":{"message":"Pipeline Java execution initialization time","seconds":0.55}}
{"level":"INFO","loggerName":"logstash.javapipeline","timeMillis":1696853663888,"thread":"[main]-pipeline-manager","logEvent":{"message":"Pipeline started","pipeline.id":"main"}}
{"level":"INFO","loggerName":"logstash.inputs.http","timeMillis":1696853663893,"thread":"[main]<http","logEvent":{"message":"Starting http input listener","address":"0.0.0.0:1080","ssl":"false"}}
2023-10-09 12:14:24,100 Agent thread ERROR com.fasterxml.jackson.core.JsonGenerationException: Can not write a field name, expecting a value com.fasterxml.jackson.core.JsonGenerationException: Can not write a field name, expecting a value
    at com.fasterxml.jackson.core.JsonGenerator._reportError(JsonGenerator.java:2849)
    at com.fasterxml.jackson.core.json.WriterBasedJsonGenerator.writeFieldName(WriterBasedJsonGenerator.java:153)
...

See also official Elastic case: 01495152

Kind regards
Robert

[jsvd]

The issue comes from the jackson upgrade from 2.14.1 in LS 8.9.3 to jrjackson 2.15.2 in LS 8.10.0.
Even the simplest setup triggers the issue as long as log.format=json is enabled:

bin/logstash --log.format=json -e ""

[jsvd]

There are a few known issues of breaking changes in 2.15.0:

• 2.15.0 breaking behaviour change for records and Getter Visibility FasterXML/jackson-databind#3895
• Regression: 2.15.0 breaks deserialization for records when mapper.setVisibility(PropertyAccessor.ALL, Visibility.NONE); FasterXML/jackson-databind#3906
• 2.15.0 breaks deserialization when POJO/Record only has a single field and is marked Access.WRITE_ONLY FasterXML/jackson-databind#3897

But all of these have been fixed, while this particular issue still happens with 2.15.3

[jsvd]

Here is a test that shows the failure:

diff --git a/logstash-core/src/test/java/org/logstash/log/CustomLogEventTests.java b/logstash-core/src/test/java/org/logstash/log/CustomLogEventTests.java
index a2af82ea4..4fbd828ff 100644
--- a/logstash-core/src/test/java/org/logstash/log/CustomLogEventTests.java
+++ b/logstash-core/src/test/java/org/logstash/log/CustomLogEventTests.java
@@ -47,6 +47,8 @@ import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
 import org.apache.logging.log4j.junit.LoggerContextRule;
 import org.apache.logging.log4j.test.appender.ListAppender;
+import org.jruby.Ruby;
+import org.jruby.RubySymbol;
 import org.junit.ClassRule;
 import org.junit.Test;
 import org.logstash.ObjectMappers;
@@ -90,6 +92,10 @@ public class CustomLogEventTests {
         logger.error("here is a map: {}", Collections.singletonMap(2, 5));
         logger.warn("ignored params {}", 4, 6, 8);
 
+        Ruby runtime = Ruby.newInstance();
+        RubySymbol mainSymbol = RubySymbol.newSymbol(runtime, "main");
+        logger.warn("test", Collections.singletonMap("foo", mainSymbol));
+
         List<String> messages = appender.getMessages();
 
         Map<String, Object> firstMessage =
@@ -132,5 +138,9 @@ public class CustomLogEventTests {
         assertEquals(5, fifthMessage.size());
         logEvent = Collections.singletonMap("message", "ignored params 4");
         assertEquals(logEvent, fifthMessage.get("logEvent"));
+
+        Map<String, Object> sixthMessage =
+                ObjectMappers.JSON_MAPPER.readValue(messages.get(5), Map.class);
+        assertEquals(4, sixthMessage.size());
     }
 }

[edmocosta]

I'm going to try to summarize the root cause of this issue here.

Logstash has a custom Jackson serializer for logs events - CustomLogEventSerializer, which is responsible for serializing the logs messages produced by the LogstashMessageFactory.

If the log message has a Map parameter, the LogstashMessageFactory produces a StructuredMessage adding the raw logged parameters into the params field.

logger.debug("Executing action", :action => action, :fail => false)

When this message is delegated to CustomLogEventSerializer, it does write all string fields, and then tries to serialize the message parameters L48.

We have no control on those parameters types, it might be anything, JRuby objects, maps, lists, etc.
That way, when Jackson tries to serialize it, it might ends up using the BeanSerializer, which goes through the whole object hierarchically.

This process is likely to fail due to infinite recursion for all RubyBasicObject subclasses (which in essence are all Ruby/JRuby objects). When Jackson detects the recursive loop, it raises an exception, which is catch by the Logstash CustomLogEventSerializer L53 and retried to write using the value.toString().

It's from where the Can not write a field name, expecting a value error is coming, depending on the param's object type, the stage Jackson detected the loop, and the current value of the generator, it might or not work. For example: The writeObjectField is not atomic, it can work to write the field name, but them fail to write the value. If it tries to invoke the same method again, it will fail, as the filed name was already written by the previous call.

But why it used to work, and now it's failing?

In reality, it probably never worked pretty well. What brought this issue up was a small change in Jackson, which affected the serialization order of transient fields (FasterXML/jackson-databind#3682).

The following object:

   public static class Example {
        protected int first = 1;
        protected transient int second = 2;
        protected int third = 3;

        public int getFirst() {
            return first;
        }

        public int getSecond() {
            return second;
        }

        public int getThird() {
            return third;
        }
    }

In Jackson 2.14.1, serializes as:

{"first":1,"second":2,"third":3}

and in Jackson 2.15.3

{"first":1,"third":3,"second":2}

Before that change, the transient int second field was being added to the "property list to serialize" during the field scan phase, and removed (or not) later. Now it's being skipped on the filed scan phase (https://github.com/FasterXML/jackson-databind/blob/2.15/src/main/java/com/fasterxml/jackson/databind/introspect/POJOPropertiesCollector.java#L615), and added on the getters scan phase, which may impact the serialization order if there's more field after the transient one.

For Logstash, it means that a few transient RubyBasicObject properties, which also have public gets, are being serialized first, causing an infinite loop early and failing the retry mechanism implemented on the CustomLogEventSerializer.

I can think of a few possible solutions for this issue, one could be just improving the retry mechanism to make it work, which is not optimal as recursive loops are happening there. And a more complex one that could customize the serialization, ignoring non-needed fields and using the ruby's inspect or to_s methods as fallback when no specific Jackson serializer is registered for the object.

Logstash does have a few serializers implement already for JRuby objects, but they're not being used, as Log4j has its own Log4jJsonObjectMapper.

I'll keep this issue updated regarding the solution.

[denisgils]

The customer noticed that the logstash_internal user password is exposed in the log in 8.10.1 with log.format: json set. Can you please confirm if is this related to this issue?

Oct 23 12:40:59 tip-logstash-eude-0 logstash /usr/share/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-elasticsearch-11.16.0-java/lib/logstash/outputs/elasticsearch/http_client/pool.rb:376: warning: singleton on non-persistent Java type Java::JavaNet::URI (https://github.com/jruby/jruby/wiki/Persistence)
Oct 23 12:40:59 tip-logstash-eude-0 logstash INFO {"level":"INFO","loggerName":"logstash.licensechecker.licensereader","timeMillis":1698079258736,"thread":"LogStash::Runner","logEvent":{"message":"Elasticsearch pool URLs updated","changes":{"added":[{"var0":{"object":"http://logstash_internal/:<###THE ACTUAL PASSWORD###>@tip-elasticsearch-elasticsearch-client.tip.svc.cluster.local:9200/","singletonClass":{"id":7376,"idTest":{"varargsCollector":false},"generation":103008,"generationObject":103008,"changes":"{:removed=>[], :added=>[http://logstash_internal:xxxxxx@tip-elasticsearch-elasticsearch-client.tip.svc.cluster.local:9200/]}"}}}]}}}

[edmocosta]

Hey @denisgils! I'd say it's a different bug. Although both issues are related, printing the password indicates that Logstash does not register any Jackson serializer for password type configurations. I've opened a new issue #15530 for fixing this problem. Thank you!