search

logzio / logzio-logback-appender

Logback Appender that ships logs using HTTPs bulk
Apache License 2.0
25 stars 19 forks source link

spring boot application fails to start with appender version 1.0.9 #20

Closed RafaelTreml closed 7 years ago

RafaelTreml commented 7 years ago

Hello logz.io team, i am trying to add the logz.io appender version 1.0.9 to a spring boot application. Here are the versions i am using:

1.4.1.RELEASE Camden.SR1 1.3.5 When i add the appender to the pom io.logz.logback logzio-logback-appender 1.0.9 i am getting the following error messages: `14:50:16,511 |-WARN in io.logz.logback.LogzioLogbackAppender[LOGZIO] - Already found appender configured for type java, re-using the same one. 14:50:16,512 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@26:16 - RuntimeException in Action for tag [appender] java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@590c73d3 rejected from java.util.concurrent.ScheduledThreadPoolExecutor@6b9ce1bf[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2]` and `14:50:16,536 |-WARN in io.logz.logback.LogzioLogbackAppender[LOGZIO] - Attempted to append to non started appender [LOGZIO]. 14:50:16 ERROR org.springframework.boot.SpringApplication - Application startup failed java.lang.IllegalStateException: Logback configuration error detected: ERROR in ch.qos.logback.core.joran.spi.Interpreter@26:16 - RuntimeException in Action for tag [appender] java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@590c73d3 rejected from java.util.concurrent.ScheduledThreadPoolExecutor@6b9ce1bf[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2]                 at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:161)                 at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:72) ` After that the application is shut down. I think the problem is that in spring boot applications the logback configuration is scanned more than one time, at least twice. At the second try the first error messages occures when an appender of the same type is configured and the second error message when this appender is started. If i am using version 1.0.6 of the appender everything is ok. Do you think you can improve the behaviour of v 1.0.9?
roiravhon commented 7 years ago

Well, the whole point of version 1.0.9 was to fix exactly that :-D We had a similar issue using the play framework, and it was fixed there. Obviously this doesn't work with spring.

I'll investigate that and will update here. In the meantime, do you think you can set up a minimal project that reproduces the issue? So we can debug it right away.

Thanks, Roi

roiravhon commented 7 years ago

Also, can you please attach your logback configuration?

RafaelTreml commented 7 years ago

demo.zip

I attached a minimum demo project (created via https://start.spring.io/). It also contains a logback.xml.

Please note that the last working version (for me) was 1.0.6.

roiravhon commented 7 years ago

Hey @RafaelTreml, I think that I found the issue you are having. We are thinking of a good way to solve that now.. I'll update on progress.

roiravhon commented 7 years ago

Hey @RafaelTreml, I have merged the fix, and tested it locally under your demo app - looks working. Pushed to maven central, should take 1-2 hours to propagate.

Can you please test the fix on your end so we can close this issue?

Thanks, Roi.

RafaelTreml commented 7 years ago

That's great news. I'll test the fix when it's available.

RafaelTreml commented 7 years ago

Test successful; as for me this issue can be closed. Thanks for the quick response.

roiravhon commented 7 years ago

Thanks! Good luck :)

altre commented 6 years ago

I get a very similar error in a spring boot project. Unfortunately it does not happen most of the time, but only occurs rarely.

The complete log: SLF4J: Class path contains multiple SLF4J bindings. SLF4J: Found binding in [jar:file:/opt/mercateo/releases/pentaho.dataimport/2018-01-12-C/pentaho.dataimport.spring.boot.jar!/BOOT-INF/lib/logback-classic-1.1.8.jar!/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: Found binding in [jar:file:/opt/mercateo/releases/pentaho.dataimport/2018-01-12-C/pentaho.dataimport.spring.boot.jar!/BOOT-INF/lib/log4j-slf4j-impl-2.2.jar!/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation. SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder] SLF4J: The following set of substitute loggers may have been accessed SLF4J: during the initialization phase. Logging calls during this SLF4J: phase were not honored. However, subsequent logging calls to these SLF4J: loggers will work as normally expected. SLF4J: See also http://www.slf4j.org/codes.html#substituteLogger SLF4J: io.logz.com.bluejeans.common.bigqueue.MappedPageFactory SLF4J: io.logz.com.bluejeans.common.bigqueue.MappedPage SLF4J: io.logz.com.bluejeans.common.bigqueue.LRUCache 01-15T12:00:55.774+0100 [pentaho.dataimport@dwh] [main] INFO org.springframework.context.annotation.AnnotationConfigApplicationContext:582: Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@198e2867: startup date [Mon Jan 15 12:00:55 CET 2018]; root of context hierarchy 01-15T12:00:57.421+0100 [pentaho.dataimport@dwh] [main] INFO org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor:155: JSR-330 'javax.inject.Inject' annotation found and supported for autowiring 01-15T12:00:57.676+0100 [pentaho.dataimport@dwh] [main] INFO org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:325: Bean 'configurationPropertiesRebinderAutoConfiguration' of type [class org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$c5d9d4e4] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying) 01-15T12:01:00.116+0100 [pentaho.dataimport@dwh] [main] WARN org.springframework.boot.SpringApplication:91: Error handling failed (no error message) 01-15T12:01:00.126+0100 [pentaho.dataimport@dwh] [main] ERROR org.springframework.boot.SpringApplication:839: Application startup failed java.lang.IllegalStateException: Logback configuration error detected: ERROR in ch.qos.logback.core.joran.spi.Interpreter@20:13 - RuntimeException in Action for tag [appender] java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@1593948d rejected from java.util.concurrent.ScheduledThreadPoolExecutor@1b604f19[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 2] at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:161) at org.springframework.boot.logging.logback.LogbackLoggingSystem.reinitialize(LogbackLoggingSystem.java:205) at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:65) at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:50) at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:114) at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:299) at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:272) at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:235) at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:208) at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:166) at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:138) at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:121) at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:68) at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54) at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:337) at org.springframework.boot.SpringApplication.run(SpringApplication.java:308) at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:134) at com.mercateo.pentaho.dataimport.spring.EtlJobRunner.main(EtlJobRunner.java:41) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48) at org.springframework.boot.loader.Launcher.launch(Launcher.java:87) at org.springframework.boot.loader.Launcher.launch(Launcher.java:50) at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:51)

roiravhon commented 6 years ago

Hey @altre! from your logs, looks like the application is failing to start: ERROR org.springframework.boot.SpringApplication:839: Application startup failed Which closes the executer and preventing us from drain logs.

Sure this is something related to the appender?

baptiste-mnh commented 5 years ago

Hi, I have a similar issue which happend now every time : 

Exception in thread "main" java.lang.IllegalStateException: Logback configuration error detected: 
ERROR in ch.qos.logback.core.joran.spi.Interpreter@24:16 - RuntimeException in Action for tag [appender] java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@40f70521[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@5b1f29fa[Wrapped task = io.logz.sender.LogzioSender$$Lambda$113/0x00000008001e6c40@aeab9a1]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@774698ab[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 2]
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:169)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.reinitialize(LogbackLoggingSystem.java:224)
    at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:75)
    at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:117)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:292)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:265)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:228)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:201)
    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:75)
    at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
    at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:347)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:306)
    at com.globalpricing.cli.CliApplication.main(CliApplication.java:86)
idohalevi commented 5 years ago

@baptiste-mnh What version are you using?

baptiste-mnh commented 5 years ago

@idohalevi I'm using v1.0.22 .

idohalevi commented 5 years ago

@baptiste-mnh What is your set up?

baptiste-mnh commented 5 years ago

@idohalevi

So it's :

        <dependency>
            <groupId>io.logz.logback</groupId>
            <artifactId>logzio-logback-appender</artifactId>
            <version>1.0.22</version>
        </dependency>

With logback v1.2.3, Spring v5.1.8, Spring-Boot v2.1.5 with java 11 on MacOS.

Tanks for your help!

rambobbala commented 4 years ago

I see the same issue in one of my application With logback v1.2.3, Spring v5.2.3, java 13

Any fix for this ?