search

logfellow / logstash-logback-encoder

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

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

Closed englishbobster closed 4 years ago

englishbobster commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

philsttr commented 4 years ago

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 commented 4 years ago

Hi, sorry I have been neglecting this. Of course, found this behavior at work and have not had time to get back. Hope to add more over the weekend.

/Stu

On Fri, Jan 24, 2020 at 5:05 AM Phil Clay notifications@github.com wrote:

Hi @PatrickHuetter https://github.com/PatrickHuetter and @englishbobster https://github.com/englishbobster

I have not been able to reproduce this problem with this simple project https://github.com/logstash/logstash-logback-encoder/files/4106758/demo.zip 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.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/logstash/logstash-logback-encoder/issues/387?email_source=notifications&email_token=ABCUH3QI3QZCZ42R4IRPTXLQ7JSINA5CNFSM4KEYQ452YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJZVDBQ#issuecomment-577982854, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABCUH3RVIGXKJDJKC2OWPBTQ7JSINANCNFSM4KEYQ45Q .

duclm2609 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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.

duclm2609 commented 4 years ago

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

englishbobster commented 4 years ago

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 commented 4 years ago

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

fdesu commented 4 years ago

@philsttr thanks for the analysis and an explanation