Can not start an object, expecting field name (context: Object)

robatipoor commented 3 weeks ago

I tried using this example example in my Spring Boot project, but I encountered the following error:

ERROR An exception occurred processing Appender ElasticsearchAppender java.lang.IllegalArgumentException: com.fasterxml.jackson.core.JsonGenerationException: Can not start an object, expecting field name (context: Object)
        at org.appenders.log4j2.elasticsearch.PooledItemSourceFactory.create(PooledItemSourceFactory.java:118)
        at org.appenders.log4j2.elasticsearch.GenericItemSourceLayout.serialize(GenericItemSourceLayout.java:43)
        at org.appenders.log4j2.elasticsearch.ItemSourceAppender.append(ItemSourceAppender.java:52)
        at org.appenders.log4j2.elasticsearch.ItemSourceAppender.append(ItemSourceAppender.java:32)
        at org.appenders.log4j2.elasticsearch.ElasticsearchAppender.append(ElasticsearchAppender.java:79)
        at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
        at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:705)
        at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:663)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:639)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:575)
        at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
        at org.apache.logging.log4j.core.Logger.log(Logger.java:169)
        at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2906)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2859)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2841)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2586)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2341)
        at org.apache.commons.logging.LogAdapter$Log4jLog.log(LogAdapter.java:264)
        at org.apache.commons.logging.LogAdapter$Log4jLog.info(LogAdapter.java:224)
        at org.springframework.boot.StartupInfoLogger.logStarting(StartupInfoLogger.java:50)
        at org.springframework.boot.SpringApplication.logStartupInfo(SpringApplication.java:638)
        at org.springframework.boot.SpringApplication.prepareContext(SpringApplication.java:405)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:334)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1363)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1352)
        at com.zarinpal.onyx.OnyxApplicationKt.main(OnyxApplication.kt:15)
Caused by: com.fasterxml.jackson.core.JsonGenerationException: Can not start an object, expecting field name (context: Object)
        at com.fasterxml.jackson.core.JsonGenerator._constructWriteException(JsonGenerator.java:2884)
        at com.fasterxml.jackson.core.JsonGenerator._reportError(JsonGenerator.java:2868)
        at com.fasterxml.jackson.core.json.JsonGeneratorImpl._reportCantWriteValueExpectName(JsonGeneratorImpl.java:275)
        at com.fasterxml.jackson.core.json.JsonGeneratorImpl._verifyPrettyValueWrite(JsonGeneratorImpl.java:265)
        at com.fasterxml.jackson.core.json.UTF8JsonGenerator._verifyValueWrite(UTF8JsonGenerator.java:1163)
        at com.fasterxml.jackson.core.json.UTF8JsonGenerator.writeStartObject(UTF8JsonGenerator.java:396)
        at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:179)
        at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.java:502)
        at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:341)
        at com.fasterxml.jackson.databind.ObjectWriter$Prefetch.serialize(ObjectWriter.java:1574)
        at com.fasterxml.jackson.databind.ObjectWriter._writeValueAndClose(ObjectWriter.java:1275)
        at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:1098)
        at org.appenders.log4j2.elasticsearch.JacksonSerializer.write(JacksonSerializer.java:55)
        at org.appenders.log4j2.elasticsearch.PooledItemSourceFactory.create(PooledItemSourceFactory.java:114)
        ... 28 more

pom.xml:

<?xml version="1.0" encoding="UTF-8"?>
<project 
    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>3.3.1</version>
        <relativePath/>
    </parent>

    <dependencies>
        <dependency>
            <groupId>org.springframework.retry</groupId>
            <artifactId>spring-retry</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-aspects</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
            <exclusions>
                <exclusion>
                    <groupId>org.springframework.boot</groupId>
                    <artifactId>spring-boot-starter-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web-services</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-validation</artifactId>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.module</groupId>
            <artifactId>jackson-module-kotlin</artifactId>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.datatype</groupId>
            <artifactId>jackson-datatype-jsr310</artifactId>
        </dependency>
        <dependency>
            <groupId>org.jetbrains.kotlin</groupId>
            <artifactId>kotlin-reflect</artifactId>
        </dependency>
        <dependency>
            <groupId>org.jetbrains.kotlin</groupId>
            <artifactId>kotlin-stdlib</artifactId>
        </dependency>
        <dependency>
            <groupId>org.apache.httpcomponents.client5</groupId>
            <artifactId>httpclient5</artifactId>
            <version>5.3.1</version>
        </dependency>
        <dependency>
            <groupId>com.ibm.icu</groupId>
            <artifactId>icu4j</artifactId>
            <version>73.1</version>
        </dependency>
        <dependency>
            <groupId>com.squareup.retrofit2</groupId>
            <artifactId>retrofit</artifactId>
            <version>${retrofit.version}</version>
        </dependency>
        <dependency>
            <groupId>com.squareup.retrofit2</groupId>
            <artifactId>converter-jackson</artifactId>
            <version>${retrofit.version}</version>
        </dependency>
        <dependency>
            <groupId>com.github.mifmif</groupId>
            <artifactId>generex</artifactId>
            <version>1.0.2</version>
        </dependency>
        <dependency>
            <groupId>org.apache.axis</groupId>
            <artifactId>axis</artifactId>
            <version>1.4</version>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
            <exclusions>
                <exclusion>
                    <groupId>org.mockito</groupId>
                    <artifactId>mockito-core</artifactId>
                </exclusion>
                <exclusion>
                    <groupId>org.mockito</groupId>
                    <artifactId>mockito-junit-jupiter</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.appenders.log4j</groupId>
            <artifactId>log4j2-elasticsearch-jest</artifactId>
            <version>1.6.1</version>
        </dependency>
        <dependency>
            <groupId>org.appenders.st</groupId>
            <artifactId>appenders-jackson-st</artifactId>
            <version>1.0.1</version>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.dataformat</groupId>
            <artifactId>jackson-dataformat-yaml</artifactId>
            <version>${jackson.version}</version>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.module</groupId>
            <artifactId>jackson-module-afterburner</artifactId>
            <version>${jackson.version}</version>
        </dependency>
        <dependency>
            <groupId>net.openhft</groupId>
            <artifactId>chronicle-map</artifactId>
            <version>3.19.40</version>
        </dependency>
        <dependency>
            <groupId>com.lmax</groupId>
            <artifactId>disruptor</artifactId>
            <version>3.4.4</version>
        </dependency>
    </dependencies>
    <build>
        <sourceDirectory>${project.basedir}/src/main/kotlin</sourceDirectory>
        <testSourceDirectory>${project.basedir}/src/test/kotlin</testSourceDirectory>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
            <plugin>
                <groupId>org.jetbrains.kotlin</groupId>
                <artifactId>kotlin-maven-plugin</artifactId>
                <configuration>
                    <args>
                        <arg>-Xjsr305=strict</arg>
                    </args>
                    <compilerPlugins>
                        <plugin>spring</plugin>
                        <plugin>all-open</plugin>
                    </compilerPlugins>
                    <jvmTarget>21</jvmTarget>
                </configuration>
                <dependencies>
                    <dependency>
                        <groupId>org.jetbrains.kotlin</groupId>
                        <artifactId>kotlin-maven-allopen</artifactId>
                        <version>${kotlin.version}</version>
                    </dependency>
                </dependencies>
            </plugin>
        </plugins>
    </build>
</project>

log4j2.xml:

<Configuration name="ConfigTest" status="ERROR" monitorInterval="5">
    <Appenders>
        <Console name="Console">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n"/>
        </Console>
        <RollingFile name="FileAppender" filePattern="/var/log/spring/app-%d{yyyy-MM-dd}.log">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy/>
            </Policies>
        </RollingFile>
        <Elasticsearch name="ElasticsearchAppender">
            <RollingIndexName indexName="test-app" pattern="yyyy-MM" timeZone="Europe/Warsaw"/>
            <ThresholdFilter level="INFO" onMatch="ACCEPT"/>
            <JacksonJsonLayout singleThread="true" afterburner="true">
                <ByteBufItemSourceFactory itemSizeInBytes="1024" maxItemSizeInBytes="16384" initialPoolSize="20000"/>
                <VirtualProperty name="hostname" value="$${env:hostname:-undefined}"/>
                <PooledItemSourceFactory poolName="itemPool" itemSizeInBytes="1024" initialPoolSize="6000"
                                         monitored="true" monitorTaskInterval="10000" resizeTimeout="500">
                    <UnlimitedResizePolicy resizeFactor="0.6"/>
                </PooledItemSourceFactory>
            </JacksonJsonLayout>
            <AsyncBatchDelivery batchSize="2000" deliveryInterval="5000">
                <IndexTemplate name="test-app" path="classpath:indexTemplate.json" apiVersion="8"/>
                <JestBufferedHttp serverUris="http://localhost:9200"
                                  connTimeout="500"
                                  readTimeout="30000"
                                  maxTotalConnection="8"
                                  defaultMaxTotalConnectionPerRoute="8">
                    <PooledItemSourceFactory poolName="batchPool" itemSizeInBytes="2048000" initialPoolSize="3"
                                             monitored="true" monitorTaskInterval="10000" resizeTimeout="500">
                        <UnlimitedResizePolicy resizeFactor="0.70"/>
                    </PooledItemSourceFactory>
                    <BatchLimitBackoffPolicy maxBatchesInFlight="4"/>
                </JestBufferedHttp>
            </AsyncBatchDelivery>
        </Elasticsearch>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="FileAppender"/>
            <AppenderRef ref="ElasticsearchAppender"/>
        </Root>
    </Loggers>
</Configuration>

Thank you for your consideration.

rfoltyns commented 3 weeks ago

I can see that you tweaked the example a bit. That's great, but some tweaks need to be applied in very specific context.

I noticed that you'd like to use JacksonJsonLayout singleThread="true". This will not work with Logger (as stated in the documentation: Use ONLY with AsyncLogger)

singleThread=true enables SingleThreadJsonFactory. Usage of this factory is strictly limited - in Log4j2 library context - to AsyncLogger(s). singleThread means "it can only be used by one thread at a time". This condition (unless running a single-thread app) will never be satisfied when using Logger - logger (and appender) can be accessed concurrently by more than 1 thread, mangling the underlying, shared JsonWriteContext that SingleThreadJsonFactory provides.

In contrast, AsyncLogger consumes LogEvent(s) from a RingBuffer in a separate (single) thread, ensuring that re-used data structures are ready (and safe) to serialize next log event.

Given the above, I suggest either:

Removing the singleThread=true - depending on the amount of logs you'd like to produce, while it reduces the memory allocation during serialisation to JSON, it's not really noticeable in low-traffic applications
Or switching to AsyncLogger - if you can continue if log was not written (that depends on how reliable your application logging must be), ensuring only-one-thread-at-a-time access to SingleThreadJsonFactory is critical for this factory to work properly.

rfoltyns commented 3 weeks ago

Also, this doesn't seem to be correct. See Object Pooling docs

<ByteBufItemSourceFactory itemSizeInBytes="1024" maxItemSizeInBytes="16384" initialPoolSize="20000"/>
<PooledItemSourceFactory poolName="itemPool" itemSizeInBytes="1024" initialPoolSize="6000"
                                         monitored="true" monitorTaskInterval="10000" resizeTimeout="500">...

robatipoor commented 2 weeks ago

Thank you for your response. it seems my problem is solved.

rfoltyns commented 2 days ago

Happy to help :+1:

rfoltyns / log4j2-elasticsearch

Can not start an object, expecting field name (context: Object) #97