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.

Sign up for GitHub

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

Jump to bottom

Spring Boot 2.2.2.RELEASE with logstash-logback-encoder Versions > 5.2 service fails with System.Exit 0 #387

Closed
englishbobster opened this issue Jan 9, 2020 · 12 comments
Closed

Spring Boot 2.2.2.RELEASE with logstash-logback-encoder Versions > 5.2 service fails with System.Exit 0 #387

englishbobster opened this issue Jan 9, 2020 · 12 comments
Milestone
6.4

Comments

@englishbobster
Copy link

Hi,
we have tried to use Spring Boot 2.2.2.RELEASE with logstash-logback-encoder:

<dependency>
            <groupId>net.logstash.logback</groupId>
            <artifactId>logstash-logback-encoder</artifactId>
            <version>6.3</version>
        </dependency>

together with JSON formatted structured logging.

application.properties is working otherwise with non-json logging.

logback-spring.xml looks something like this:

<springProfile name="local">
        <property resource="application.properties" />
        <contextName>${spring.application.name}</contextName>
        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
                <providers>
                    <contextName>
                        <fieldName>appName</fieldName>
                    </contextName>
                    <threadName>
                        <fieldName>appThread</fieldName>
                    </threadName>
                    <timestamp>
                        <fieldName>appTimestamp</fieldName>
                        <timeZone>Europe/Stockholm</timeZone>
                    </timestamp>
                    <loggerName>
                        <fieldName>appLogger</fieldName>
                    </loggerName>
                    <logLevel>
                        <fieldName>appLogLevel</fieldName>
                    </logLevel>
                    <callerData>
                        <classFieldName>callerClass</classFieldName>
                        <methodFieldName>callerMethod</methodFieldName>
                        <fileFieldName>callerFile</fileFieldName>
                        <lineFieldName>callerLine</lineFieldName>
                    </callerData>
                    <mdc/>
                    <arguments>
                        <includeNonStructuredArguments>false</includeNonStructuredArguments>
                    </arguments>
                    <stackTrace>
                        <fieldName>stack</fieldName>
                    </stackTrace>
                    <message>
                        <fieldName>msg</fieldName>
                    </message>
                </providers>
            </encoder>
        </appender>
        <root>
            <appender-ref ref="STDOUT"/>
        </root>
    </springProfile>
</configuration>

In all cases where the logstash-logback-encoder version is greater than 5.2 we see that our Spring Boot services fails to start and exits with status 0.

Anyone else experiencing similar problems?
@philsttr
Copy link
Collaborator

philsttr commented Jan 9, 2020

Can you provide an example application (maybe a small one from from start.spring.io) that reproduces this problem?

What OS?

What Java distribution and version?

@PatrickHuetter
Copy link

I can confirm this problem with the given parameters. Exact the same behaviour. That's why we downgraded to 5.2 again.

@philsttr
Copy link
Collaborator

Hi @PatrickHuetter and @englishbobster

I have not been able to reproduce this problem with this simple project when running on Ubuntu 18.04 with OracleJDK 1.8.0_181 or AdoptOpenJDK 11.0.5. I've tried running the app directly (java --jar target/demo-0.0.1-SNAPSHOT.jar), with the spring-boot-maven-plugin (mvn spring-boot:run), and directly from IntelliJ.

Can one of you provide an example application (maybe a small one from from start.spring.io) that reproduces this problem?

What OS are you using?

What Java distribution and version are you using?

I'm willing to get this fixed, but I need your help to reproduce the problem.

@englishbobster
Copy link
Author

englishbobster commented Jan 24, 2020 via email

@duclm2609
Copy link

duclm2609 commented Jan 31, 2020 •
edited

I faced the same issue, but the problem is a little bit weird. I have 2 projects, both using Spring Boot. In the first project, I have Spring Boot version 2.2.4 with Java version 8, everything's running fine with version 6.3. I then copy the appender configuration to the second project (which is an existing project that using Spring Boot version 2.2.2 and Java version 8) but this time it doesn't work as expected, my project fails to start with exit code 1. Both version 6.3 and 5.3 is not working. Turn on debug, this is what I've got:

20:46:48,811 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [json-logstash]
20:46:48,827 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.LoggingEventJsonProviders] for [providers] property
20:46:48,869 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.LoggingEventFormattedTimestampJsonProvider] for [timestamp] property
20:46:48,870 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.LogLevelJsonProvider] for [logLevel] property
20:46:48,871 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.ThreadNameJsonProvider] for [threadName] property
20:46:48,872 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.LoggerNameJsonProvider] for [loggerName] property
20:46:48,872 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.CallerDataJsonProvider] for [callerData] property
20:46:48,874 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.MdcJsonProvider] for [mdc] property
20:46:48,874 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.MessageJsonProvider] for [message] property
20:46:48,875 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.ArgumentsJsonProvider] for [arguments] property
20:46:48,877 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.StackHashJsonProvider] for [stackHash] property
20:46:48,878 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.StackTraceJsonProvider] for [stackTrace] property
20:46:48,891 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.composite.loggingevent.LoggingEventPatternJsonProvider] for [pattern] property
20:46:48,914 |-WARN in Logger[org.springframework.boot.context.logging.ClasspathLoggingApplicationListener] - No appenders present in context [default] for logger [org.springframework.boot.context.logging.ClasspathLoggingApplicationListener].
Process finished with exit code 1

Below is my logback configuration:

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>
    <appender name="json-logstash" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- deny all events with a level below INFO, that is TRACE and DEBUG -->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
            <providers>
                <timestamp>
                    <fieldName>timestamp</fieldName>
                </timestamp>
                <logLevel/>
                <threadName/>
                <loggerName/>
                <callerData>
                    <classFieldName>log_source_class</classFieldName>
                    <methodFieldName>log_source_method</methodFieldName>
                    <lineFieldName>log_source_line</lineFieldName>
                    <fileFieldName>[ignore]</fileFieldName>
                </callerData>
                <mdc/>
                <message/>
                <arguments/>
                <stackHash/>
                <stackTrace>
                    <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
                        <maxDepthPerThrowable>30</maxDepthPerThrowable>
                        <maxLength>2048</maxLength>
                        <shortenedClassNameLength>20</shortenedClassNameLength>
                        <rootCauseFirst>true</rootCauseFirst>
                        <inlineHash>false</inlineHash>
                        <!-- generated class names -->
                        <exclude>\$\$FastClassByCGLIB\$\$</exclude>
                        <exclude>\$\$EnhancerBySpringCGLIB\$\$</exclude>
                        <exclude>^sun\.reflect\..*\.invoke</exclude>
                        <!-- JDK internals -->
                        <exclude>^com\.sun\.</exclude>
                        <exclude>^sun\.net\.</exclude>
                        <!-- dynamic invocation -->
                        <exclude>^net\.sf\.cglib\.proxy\.MethodProxy\.invoke</exclude>
                        <exclude>^org\.springframework\.cglib\.</exclude>
                        <exclude>^org\.springframework\.transaction\.</exclude>
                        <exclude>^org\.springframework\.validation\.</exclude>
                        <exclude>^org\.springframework\.app\.</exclude>
                        <exclude>^org\.springframework\.aop\.</exclude>
                        <exclude>^java\.lang\.reflect\.Method\.invoke</exclude>
                        <!-- Spring plumbing -->
                        <exclude>^org\.springframework\.ws\..*\.invoke</exclude>
                        <exclude>^org\.springframework\.ws\.transport\.</exclude>
                        <exclude>^org\.springframework\.ws\.soap\.saaj\.SaajSoapMessage\.</exclude>
                        <exclude>^org\.springframework\.ws\.client\.core\.WebServiceTemplate\.</exclude>
                        <exclude>^org\.springframework\.web\.filter\.</exclude>
                        <!-- Tomcat internals -->
                        <exclude>^org\.apache\.tomcat\.</exclude>
                        <exclude>^org\.apache\.catalina\.</exclude>
                        <exclude>^org\.apache\.coyote\.</exclude>
                        <exclude>^java\.util\.concurrent\.ThreadPoolExecutor\.runWorker</exclude>
                        <exclude>^java\.lang\.Thread\.run$</exclude>
                    </throwableConverter>
                </stackTrace>
                <!-- provides the fields in the configured pattern -->
                <pattern>
                    <omitEmptyFields>true</omitEmptyFields>
                    <!-- the pattern that defines what to include -->
                    <pattern>
                        {
                        "timestamp": "%date{ISO8601}"
                        }
                    </pattern>
                </pattern>
            </providers>
        </encoder>
        <file>logs/app-json-logstash.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>logs/archived/app-json-logstash-%d{yyyy-MM-dd}.%i.zip</fileNamePattern>
            <!-- each file should be at most 1GB, keep 30 days worth of history, but at most 20GB -->
            <maxFileSize>1024MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
    </appender>
    <root level="DEBUG">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="json-logstash"/>
    </root>
</configuration>

I've tried to increase the Spring Boot version to 2.2.4 on the second project but no luck. If i downgrade the version of library to 5.2, it works normally.

@philsttr
Copy link
Collaborator

Since this is such a strange issue, I'm not going to be able to debug/fix/test this unless someone can provide a complete project (uploaded as a zip) that can reproduce this issue. I have not been able to reproduce it with the provided logback configuration files and spring boot versions.

Since the same logback configuration files are working in some projects, and not others, I don't believe this is limited to just a problem between logstash-logback-encoder and spring-boot. I think something else is at play as well. And without a project that can reproduce this problem, I cannot determine what that something else is.

@duclm2609
Copy link

duclm2609 commented Feb 1, 2020 •
edited

I've created a repository for the failed project. It contains no logic source code, but I try to keep the pom.xml file nearly the same as my aforementioned failed project. This project crashed when using version 6.3. If downgrade to 5.2 version, it's working fine.
Here is the link to the project:

https://github.com/duclm2609/debug-logstash-logback-springboot

My laptop is running MacOS Catalina 10.15.2. Hope this will help.

@philsttr
Copy link
Collaborator

philsttr commented Feb 3, 2020 •
edited

Thanks @duclm2609 !

While debugging your example application with logstash-logback-encoder >= v5.3, I found the following exception occurring during startup:

java.util.ServiceConfigurationError: com.fasterxml.jackson.databind.Module: Provider com.fasterxml.jackson.module.jaxb.JaxbAnnotationModule not found
	at java.base/java.util.ServiceLoader.fail(ServiceLoader.java:588)
	at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.nextProviderClass(ServiceLoader.java:1211)
	at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNextService(ServiceLoader.java:1220)
	at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNext(ServiceLoader.java:1264)
	at java.base/java.util.ServiceLoader$2.hasNext(ServiceLoader.java:1299)
	at java.base/java.util.ServiceLoader$3.hasNext(ServiceLoader.java:1384)
	at com.fasterxml.jackson.databind.ObjectMapper.findModules(ObjectMapper.java:1054)
	at com.fasterxml.jackson.databind.ObjectMapper.findModules(ObjectMapper.java:1038)
	at com.fasterxml.jackson.databind.ObjectMapper.findAndRegisterModules(ObjectMapper.java:1088)
	at net.logstash.logback.composite.CompositeJsonFormatter.createJsonFactory(CompositeJsonFormatter.java:129)
	at net.logstash.logback.composite.CompositeJsonFormatter.start(CompositeJsonFormatter.java:103)
	at net.logstash.logback.encoder.CompositeJsonEncoder.start(CompositeJsonEncoder.java:211)
	at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.end(NestedComplexPropertyIA.java:161)
	at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:309)
	at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:193)
	at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:179)
	at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:165)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:152)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:110)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.configureByResourceUrl(LogbackLoggingSystem.java:178)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:155)
	at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:80)
	at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:118)
	at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:313)
	at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:288)
	at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:246)
	at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
	at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:76)
	at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:53)
	at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:345)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:308)
	at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:140)
	at org.springframework.cloud.bootstrap.BootstrapApplicationListener.bootstrapServiceContext(BootstrapApplicationListener.java:203)
	at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:114)
	at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:71)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
	at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:76)
	at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:53)
	at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:345)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:308)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1226)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1215)
	at com.example.debuglogbacklogstash.DebugLogbackLogstashApplication.main(DebugLogbackLogstashApplication.java:11)

Starting with logstash-logback-encoder v5.3, automatic discovery of jackson modules was enabled by default. With logstash-logback-encoder <= 5.2, the problem does not occur because automatic discovery of jackson modules does not occur by default.

The root cause is a bug in liquibase reported as CORE-3542. Basically the liquibase-core jar contains a service definition file (META-INF/services/com.fasterxml.jackson.databind.Module) that points to the com.fasterxml.jackson.module.jaxb.JaxbAnnotationModule class, which is not on the classpath. When jackson tries to load all modules via java's ServiceLoader, a ClassNotFoundException occurs, which is then translated into the ServiceConfigurationError mentioned above.

There are three possible solutions to get this to work with the latest logstash-logback-encoder:

A) Don't use org.liquibase:liquibase-core until CORE-3542 is fixed, since that jar has an incorrect service loader configuration file.

OR

B) Disable automatic jackson module discovery (as mentioned here) for the encoder/layout.

For example:

        <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
            <findAndRegisterJacksonModules>false</findAndRegisterJacksonModules>
            ...

OR

C) Add the dependency that contains the com.fasterxml.jackson.module.jaxb.JaxbAnnotationModule class (which allows the automatic discovery to work properly):

        <dependency>
            <groupId>com.fasterxml.jackson.module</groupId>
            <artifactId>jackson-module-jaxb-annotations</artifactId>
        </dependency>

@duclm2609, Any one of these solutions will allow your example project to work with the latest logstash-logback-encoder.

@englishbobster and @PatrickHuetter , can you see if these solutions address your problems as well? I'm going to assume that it is the same problem. I'll close this issue if I don't hear back after a while.

philsttr added a commit that referenced this issue Feb 3, 2020
@philsttr
For #387, provide error message when dynamically loading jackson modu…
2e98d6c 
…les from the classpath fails
@duclm2609
Copy link

Thanks @philsttr . I've applied solution B and it worked.

@englishbobster
Copy link
Author

Bit late to the party....but solution B worked fine. Thanks for the help and sorry didn't have time to expand/help out on the issue.

@jabouchleih
Copy link

jabouchleih commented Feb 17, 2020 •
edited

Solution C worked with Spring Boot 2.1.7.RELEASE, Logstash 6.3 and a personalized net.logstash.logback.encoder.LogstashEncoder

@fdesu
Copy link

fdesu commented Feb 27, 2020 •
edited

@philsttr thanks for the analysis and an explanation

@philsttr philsttr added this to the 6.4 milestone May 30, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
6.4
Development

No branches or pull requests
6 participants
@PatrickHuetter @duclm2609 @jabouchleih @englishbobster @fdesu @philsttr