create log stream twice

[Najdzionix]

Hello, I configurate yours appender on my aplication ( I am using spring boot). But I have small issue, when app is starting create log stream twice (check attached screenshot) and one of always is empty It is my logback configration:

logback.txt

[pierredavidbelanger]

I am really not sure why.

First thought is where this is running ? Are you running locally, just after some unit or integration tests ? Do you use the same logback config file for your tests ?

Other things to have a look:

Are you able to put a @PostConstruct somewhere in your @SpringBootApplication, with a System.out.println("PostConstruct") in it, to see why you app could be booted twice ?

Are you able to reproduce this in a fresh small empty spring boot app ? If yes, please share it with me.

Are you able to reproduce with the debugger attached ? If yes, please put a break point into the (IntelliJ decompiled) class ca.pjer.logback.AWSLogsStub in the method start() where the awsLogs.createLogStream() is called. Execute and not both stack traces.

[Najdzionix]

Hi, I create simple spring project to reproduce issue: https://github.com/Najdzionix/spring-test-app Added PostConstruct and app boot once

[pierredavidbelanger]

Thank you for this test app, I can reproduce the behaviour you are seeing.

I am still not sure why though.

It may be related to the strange spring boot single jar class loading system.

One thing I can see, is that your test app logs everything twice:

...
2017-11-15 10:30:50.013  INFO 31014 --- [           main] c.najdzionix.test.springboot.LogTester   : Test logger
2017-11-15 10:30:50.013  INFO 31014 --- [main] c.najdzionix.test.springboot.LogTester   : Test logger
...

Anyways, I will have a look at this soon.

[Najdzionix]

I eliminated duplicate logs in my test app, but still create stream log twice

[pierredavidbelanger]

I am sorry I did not reply sooner. This one is really a puzzle :)

I manage to get the two stack trace that leads to AwsLogsAppender.start:

	at com.najdzionix.test.springboot.AwsLogsAppender.start(AwsLogsAppender.java:8)
	at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:90)
	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:173)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:145)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.reinitialize(LogbackLoggingSystem.java:208)
	at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:74)
	at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:59)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:115)
	at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:303)
	at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:276)
	at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:239)
	at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:212)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:167)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:122)
	at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:74)
	at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
	at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:325)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:296)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1118)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1107)
	at com.najdzionix.test.springboot.Application.main(Application.java:16)
	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:498)
	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)

	at com.najdzionix.test.springboot.AwsLogsAppender.start(AwsLogsAppender.java:8)
	at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:90)
	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 ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
	at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:150)
	at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
	at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.getLoggerContext(LogbackLoggingSystem.java:273)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.beforeInitialize(LogbackLoggingSystem.java:98)
	at org.springframework.boot.logging.LoggingApplicationListener.onApplicationStartingEvent(LoggingApplicationListener.java:230)
	at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:209)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:167)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:122)
	at org.springframework.boot.context.event.EventPublishingRunListener.starting(EventPublishingRunListener.java:69)
	at org.springframework.boot.SpringApplicationRunListeners.starting(SpringApplicationRunListeners.java:48)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:292)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1118)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1107)
	at com.najdzionix.test.springboot.Application.main(Application.java:16)
	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:498)
	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)

[pierredavidbelanger]

I guess we now have two options:

1. we try to find why spring boot is doing this and work around,

2. or we could just lazy create the group/stream when the first batch is sent

I prefer the 2nd option, it makes sense anyways, not only in the context of this bug

[Najdzionix]

Hi, I am sorry to delayed response. Yes, second option it is seem to good

[malkusch]

@Najdzionix as a Spring user myself, I never experienced such a behaviour. May I see your spring-test-app also? It's no more available.

Going by the code of this appender, it looks more like there are two appenders started and the issue is actually withing the application.

[Najdzionix]

Hi @malkusch I do not delete app, you should be access it. https://github.com/Najdzionix/spring-test-app

[pierredavidbelanger]

@malkusch The links @Najdzionix provided did not work for me either, but this one does

[Najdzionix]

I am sorry, I made mistake on create url, yes this is correct url (past & copy issue ...)

[remal]

As I remember, Spring Boot configures logging libraries programmatically. There is a chance, that logback is configured twice in example project:

1. Logback itself reads logback.xml file
2. Spring Boot configures logback using logback.xml file

I can't check this assumption right now, but hope it will help..

[dnovitski]

Spring boot configures the logging system twice. Once in a bootstrap Spring context configuration, and once for the 'final' application context.

Actually, it's even allowed to configure it as many times as it wants, for example with hot reloading of logging properties.

So Logback appenders that get created and destroyed dynamically is something that should be supported. I'll put something together in my PR that should fix this

[dnovitski]

See https://github.com/pierredavidbelanger/logback-awslogs-appender/pull/38/commits/5a3402f369c27240dc5ba9c662ebf36133a7034d