create log stream twice #14

Najdzionix · 2017-11-14T12:53:20Z

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 · 2017-11-14T14:31:31Z

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 · 2017-11-14T15:37:48Z

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

pierredavidbelanger · 2017-11-15T15:38:33Z

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 · 2017-11-15T16:26:42Z

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

pierredavidbelanger · 2017-11-22T00:30:19Z

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 · 2017-11-22T00:33:09Z

I guess we now have two options:

we try to find why spring boot is doing this and work around,
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 · 2017-11-27T16:14:03Z

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

malkusch · 2017-12-07T11:29:09Z

@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 · 2017-12-07T11:51:40Z

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

pierredavidbelanger · 2017-12-07T14:45:17Z

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

Najdzionix · 2017-12-07T14:53:40Z

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

remal · 2018-03-03T03:47:06Z

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

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

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

dnovitski · 2023-05-05T14:33:25Z

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 · 2023-05-05T15:40:29Z

See 5a3402f

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

create log stream twice #14

create log stream twice #14

Najdzionix commented Nov 14, 2017 •

edited

Loading

pierredavidbelanger commented Nov 14, 2017

Najdzionix commented Nov 14, 2017

pierredavidbelanger commented Nov 15, 2017

Najdzionix commented Nov 15, 2017

pierredavidbelanger commented Nov 22, 2017

pierredavidbelanger commented Nov 22, 2017

Najdzionix commented Nov 27, 2017

malkusch commented Dec 7, 2017 •

edited

Loading

Najdzionix commented Dec 7, 2017

pierredavidbelanger commented Dec 7, 2017

Najdzionix commented Dec 7, 2017

remal commented Mar 3, 2018

dnovitski commented May 5, 2023

dnovitski commented May 5, 2023

create log stream twice #14

create log stream twice #14

Comments

Najdzionix commented Nov 14, 2017 • edited Loading

pierredavidbelanger commented Nov 14, 2017

Najdzionix commented Nov 14, 2017

pierredavidbelanger commented Nov 15, 2017

Najdzionix commented Nov 15, 2017

pierredavidbelanger commented Nov 22, 2017

pierredavidbelanger commented Nov 22, 2017

Najdzionix commented Nov 27, 2017

malkusch commented Dec 7, 2017 • edited Loading

Najdzionix commented Dec 7, 2017

pierredavidbelanger commented Dec 7, 2017

Najdzionix commented Dec 7, 2017

remal commented Mar 3, 2018

dnovitski commented May 5, 2023

dnovitski commented May 5, 2023

Najdzionix commented Nov 14, 2017 •

edited

Loading

malkusch commented Dec 7, 2017 •

edited

Loading