Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix issue with Jackson 2.15: Can not write a field name, expecting a value #15564

Merged
merged 4 commits into from
Nov 21, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
18 changes: 15 additions & 3 deletions logstash-core/src/main/java/org/logstash/ObjectMappers.java
Original file line number Diff line number Diff line change
Expand Up @@ -37,11 +37,12 @@
import com.fasterxml.jackson.databind.ser.std.StdSerializer;
import com.fasterxml.jackson.dataformat.cbor.CBORFactory;
import com.fasterxml.jackson.dataformat.cbor.CBORGenerator;
import com.fasterxml.jackson.databind.jsontype.BasicPolymorphicTypeValidator;

import java.io.IOException;
import java.math.BigDecimal;
import java.math.BigInteger;
import java.util.HashMap;
import org.apache.logging.log4j.core.jackson.Log4jJsonObjectMapper;
import org.jruby.RubyBignum;
import org.jruby.RubyBoolean;
import org.jruby.RubyFixnum;
Expand All @@ -51,11 +52,14 @@
import org.jruby.RubySymbol;
import org.jruby.ext.bigdecimal.RubyBigDecimal;
import org.logstash.ext.JrubyTimestampExtLibrary;
import org.logstash.log.RubyBasicObjectSerializer;

public final class ObjectMappers {

static final String RUBY_SERIALIZERS_MODULE_ID = "RubySerializers";

private static final SimpleModule RUBY_SERIALIZERS =
new SimpleModule("RubySerializers")
new SimpleModule(RUBY_SERIALIZERS_MODULE_ID)
.addSerializer(RubyString.class, new RubyStringSerializer())
.addSerializer(RubySymbol.class, new RubySymbolSerializer())
.addSerializer(RubyFloat.class, new RubyFloatSerializer())
Expand All @@ -71,7 +75,15 @@ public final class ObjectMappers {
.addDeserializer(RubyNil.class, new RubyNilDeserializer());

public static final ObjectMapper JSON_MAPPER =
new ObjectMapper().registerModule(RUBY_SERIALIZERS);
new ObjectMapper().registerModule(RUBY_SERIALIZERS);

static String RUBY_BASIC_OBJECT_SERIALIZERS_MODULE_ID = "RubyBasicObjectSerializers";

// The RubyBasicObjectSerializer must be registered first, so it has a lower priority
// over other more specific serializers.
public static final ObjectMapper LOG4J_JSON_MAPPER = new Log4jJsonObjectMapper()
.registerModule(new SimpleModule(RUBY_BASIC_OBJECT_SERIALIZERS_MODULE_ID).addSerializer(new RubyBasicObjectSerializer()))
.registerModule(RUBY_SERIALIZERS);

/* TODO use this validator instead of LaissezFaireSubTypeValidator
public static final PolymorphicTypeValidator TYPE_VALIDATOR = BasicPolymorphicTypeValidator.builder()
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -21,17 +21,26 @@
package org.logstash.log;

import com.fasterxml.jackson.core.JsonGenerator;
import com.fasterxml.jackson.core.io.SegmentedStringWriter;
import com.fasterxml.jackson.core.util.BufferRecycler;
import com.fasterxml.jackson.databind.JsonMappingException;
import com.fasterxml.jackson.databind.JsonSerializer;
import com.fasterxml.jackson.databind.SerializerProvider;

import com.google.common.primitives.Primitives;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import java.io.IOException;
import java.util.Map;

import static org.logstash.ObjectMappers.LOG4J_JSON_MAPPER;

/**
* Json serializer for logging messages, use in json appender.
* */
*/
public class CustomLogEventSerializer extends JsonSerializer<CustomLogEvent> {

private static final Logger LOGGER = LogManager.getLogger(CustomLogEventSerializer.class);

@Override
public void serialize(CustomLogEvent event, JsonGenerator generator, SerializerProvider provider) throws IOException {
generator.writeStartObject();
Expand All @@ -41,20 +50,9 @@ public void serialize(CustomLogEvent event, JsonGenerator generator, SerializerP
generator.writeObjectField("thread", event.getThreadName());
generator.writeFieldName("logEvent");
generator.writeStartObject();
if (event.getMessage() instanceof StructuredMessage) {
StructuredMessage message = (StructuredMessage) event.getMessage();
generator.writeStringField("message", message.getMessage());
if (message.getParams() != null) {
for (Map.Entry<Object, Object> entry : message.getParams().entrySet()) {
Object value = entry.getValue();
try {
generator.writeObjectField(entry.getKey().toString(), value);
} catch (JsonMappingException e) {
generator.writeObjectField(entry.getKey().toString(), value.toString());
}
}
}

if (event.getMessage() instanceof StructuredMessage) {
writeStructuredMessage((StructuredMessage) event.getMessage(), generator);
} else {
generator.writeStringField("message", event.getMessage().getFormattedMessage());
}
Expand All @@ -63,9 +61,48 @@ public void serialize(CustomLogEvent event, JsonGenerator generator, SerializerP
generator.writeEndObject();
}

private void writeStructuredMessage(StructuredMessage message, JsonGenerator generator) throws IOException {
generator.writeStringField("message", message.getMessage());

if (message.getParams() == null || message.getParams().isEmpty()) {
return;
}

for (final Map.Entry<Object, Object> entry : message.getParams().entrySet()) {
final String paramName = entry.getKey().toString();
final Object paramValue = entry.getValue();

try {
if (isValueSafeToWrite(paramValue)) {
generator.writeObjectField(paramName, paramValue);
continue;
}

// Create a new Jackson's generator for each entry, that way, the main generator is not compromised/invalidated
// in case any key/value fails to write. It also uses the JSON_LOGGER_MAPPER instead of the default Log4's one,
// leveraging all necessary custom Ruby serializers.
try (final SegmentedStringWriter entryJsonWriter = new SegmentedStringWriter(new BufferRecycler());
final JsonGenerator entryGenerator = LOG4J_JSON_MAPPER.getFactory().createGenerator(entryJsonWriter)) {
entryGenerator.writeObject(paramValue);
generator.writeFieldName(paramName);
generator.writeRawValue(entryJsonWriter.getAndClear());
}
Comment on lines +84 to +89
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

any thoughts on the performance impact of this change? if isValueSafeToWrite is false frequently then creating a new generator, writer and buffer recycler could get expensive.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On my local tests (1k fields), It had a minor/same performance impact compared to using only the main generator. I've also tried to reuse the BufferRecycler, but it didn't save many cycles as it needs to invoke the getAndClear() method in every iteration. The SegmentedStringWriter also had similar results to a JDK StringWriter.

} catch (JsonMappingException e) {
LOGGER.debug("Failed to serialize message param type {}", paramValue.getClass(), e);
generator.writeObjectField(paramName, paramValue.toString());
}
}
}

private boolean isValueSafeToWrite(Object value) {
return value == null ||
value instanceof String ||
value.getClass().isPrimitive() ||
Primitives.isWrapperType(value.getClass());
}

@Override
public Class<CustomLogEvent> handledType() {

return CustomLogEvent.class;
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,116 @@
/*
* Licensed to Elasticsearch B.V. under one or more contributor
* license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright
* ownership. Elasticsearch B.V. 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.
*/

package org.logstash.log;

import com.fasterxml.jackson.core.JsonGenerator;
import com.fasterxml.jackson.databind.JsonMappingException;
import com.fasterxml.jackson.databind.JsonSerializer;
import com.fasterxml.jackson.databind.SerializerProvider;
import com.fasterxml.jackson.databind.ser.std.StdSerializer;
import com.fasterxml.jackson.databind.util.ClassUtil;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.jruby.RubyBasicObject;
import org.jruby.RubyMethod;
import org.jruby.RubyString;
import org.jruby.exceptions.NameError;
import org.logstash.RubyUtil;

import java.io.IOException;
import java.util.Optional;

/**
* Default serializer for {@link org.jruby.RubyBasicObject} since Jackson can't handle that type natively.
* Arrays, Collections and Maps are delegated to the default Jackson's serializer - which might end-up invoking this
* serializer for its elements.
* Values which inspect method is implemented and owned by the LogStash module will be serialized using this method return.
* If none of the above conditions match, it gets the serialized value by invoking the Ruby's {@code to_s} method, falling back
* to {@link RubyBasicObject#to_s()} and {@link RubyBasicObject#anyToString()} in case of errors.
*/
public final class RubyBasicObjectSerializer extends StdSerializer<RubyBasicObject> {

private static final long serialVersionUID = -5557562960691452054L;
private static final Logger LOGGER = LogManager.getLogger(RubyBasicObjectSerializer.class);
private static final String METHOD_INSPECT = "inspect";
private static final String METHOD_TO_STRING = "to_s";

public RubyBasicObjectSerializer() {
super(RubyBasicObject.class);
}

@Override
public void serialize(final RubyBasicObject value, final JsonGenerator gen, final SerializerProvider provider) throws IOException {
final Optional<JsonSerializer<Object>> serializer = findTypeSerializer(value, provider);
if (serializer.isPresent()) {
try {
serializer.get().serialize(value, gen, provider);
return;
} catch (IOException e) {
LOGGER.debug("Failed to serialize value type {} using default serializer {}", value.getClass(), serializer.get().getClass(), e);
}
}

if (isCustomInspectMethodDefined(value)) {
try {
gen.writeString(value.callMethod(METHOD_INSPECT).asJavaString());
return;
} catch (Exception e) {
LOGGER.debug("Failed to serialize value type {} using the custom `inspect` method", value.getMetaClass(), e);
}
}

try {
gen.writeString(value.callMethod(METHOD_TO_STRING).asJavaString());
return;
} catch (Exception e) {
LOGGER.debug("Failed to serialize value type {} using `to_s` method", value.getMetaClass(), e);
}

try {
gen.writeString(value.to_s().asJavaString());
} catch (Exception e) {
LOGGER.debug("Failed to serialize value type {} using `RubyBasicObject#to_s()` method", value.getMetaClass(), e);
gen.writeString(value.anyToString().asJavaString());
}
}

private Optional<JsonSerializer<Object>> findTypeSerializer(final RubyBasicObject value, final SerializerProvider provider) {
if (ClassUtil.isCollectionMapOrArray(value.getClass())) {
try {
// Delegates the serialization to the Jackson's default serializers, which might
// end up using this serializer for its elements.
return Optional.ofNullable(provider.findTypedValueSerializer(value.getJavaClass(), false, null));
} catch (JsonMappingException e) {
// Ignored
}
}

return Optional.empty();
}

private boolean isCustomInspectMethodDefined(final RubyBasicObject value) {
try {
final Object candidate = value.method(RubyString.newString(RubyUtil.RUBY, METHOD_INSPECT));
return candidate instanceof RubyMethod && ((RubyMethod) candidate).owner(RubyUtil.RUBY.getCurrentContext()).toString().toLowerCase().startsWith("logstash");
Comment on lines +110 to +111
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same as above, do we know if this is costly performance wise when there's a lot of log entries? If necessary we could consider some memoization/caching strategy.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, invoking JRuby's method demonstrated to be an expensive operation. Unfortunately, I couldn't find any better option here - with the same result - as those objects passed to the logger are dynamically generated/parsed. Memoazing/caching them would also be complex and prone to errors, IMO, as their values are actually coming from methods invocations, which might return different values even if the type is the same, for example.

In terms of overall performance, the CustomLogEventSerializer now uses the LOG4J_JSON_MAPPER to serialize the message parameters. That mapper registers a few JRuby's serializes with a higher priority than this generic one. It should speed up the process by avoiding this generic serializer to be used.

Considering the RubyBasicObjectSerializer is a kind of fallback, and that the current behavior (without this serializer) is going through the whole object hierarchic serializing all fields until it fails. I believe the cost of invoking those methods is considerably smaller.

WDYT? Any suggestions?

} catch (NameError e) {
return false;
}
}
}
52 changes: 52 additions & 0 deletions logstash-core/src/test/java/org/logstash/ObjectMappersTest.java
Original file line number Diff line number Diff line change
@@ -0,0 +1,52 @@
package org.logstash;

import com.fasterxml.jackson.databind.JavaType;
import com.fasterxml.jackson.databind.JsonSerializer;
import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.ser.BeanSerializerFactory;
import com.fasterxml.jackson.databind.ser.Serializers;
import com.fasterxml.jackson.databind.type.TypeFactory;
import org.jruby.RubyBasicObject;
import org.junit.Test;
import org.logstash.log.RubyBasicObjectSerializer;

import java.util.LinkedList;

import static org.junit.Assert.assertNotNull;
import static org.junit.Assert.assertTrue;
import static org.logstash.ObjectMappers.RUBY_BASIC_OBJECT_SERIALIZERS_MODULE_ID;
import static org.logstash.ObjectMappers.RUBY_SERIALIZERS_MODULE_ID;

public class ObjectMappersTest {

@Test
public void testLog4jOMRegisterRubySerializersModule() {
assertTrue(ObjectMappers.LOG4J_JSON_MAPPER.getRegisteredModuleIds().contains(RUBY_SERIALIZERS_MODULE_ID));
}

@Test
public void testLog4jOMRegisterRubyBasicObjectSerializersModule() {
assertTrue(ObjectMappers.LOG4J_JSON_MAPPER.getRegisteredModuleIds().contains(RUBY_BASIC_OBJECT_SERIALIZERS_MODULE_ID));
}

@Test
public void testLog4jOMRegisterRubyBasicObjectSerializersFirst() {
final ObjectMapper mapper = ObjectMappers.LOG4J_JSON_MAPPER;
final BeanSerializerFactory factory = (BeanSerializerFactory) mapper.getSerializerFactory();

final LinkedList<Serializers> list = new LinkedList<>();
for (Serializers serializer : factory.getFactoryConfig().serializers()) {
list.add(serializer);
}

// RubyBasicObjectSerializer + Log4jJsonModule
assertTrue(list.size() > 1);

final Serializers rubyBasicObjectSerializer = list.get(list.size() - 2);
final JavaType valueType = TypeFactory.defaultInstance().constructType(RubyBasicObject.class);
final JsonSerializer<?> found = rubyBasicObjectSerializer.findSerializer(mapper.getSerializationConfig(), valueType, null);

assertNotNull(found);
assertTrue("RubyBasicObjectSerializer must be registered before others non-default serializers", found instanceof RubyBasicObjectSerializer);
}
}