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

Use of logback.groovy results in double output. #1091

Closed
PeterNSteinmetz opened this issue Jun 12, 2014 · 12 comments
Closed

Use of logback.groovy results in double output. #1091

PeterNSteinmetz opened this issue Jun 12, 2014 · 12 comments
Labels
type: bug A general bug
Milestone
1.2.0.RC1

Comments

@PeterNSteinmetz
Copy link

If one replaces logback.xml with a logback.groovy file and eliminates the logback.xml file, the program produces two copies of each log item.

It is as though there are two appenders created. Seems likely spring-boot is not checking for logback.groovy to suppress its own logging configuration, as it does with logback.xml.

This is with 1.1.1-RELEASE.
@dsyer
Copy link
Member

dsyer commented Jun 13, 2014

Works for me. How about a little sample project?

@dsyer
Copy link
Member

dsyer commented Jun 26, 2014

No response?

@dsyer dsyer closed this as completed Jun 26, 2014
@faroe228
Copy link

faroe228 commented Sep 1, 2014

I had a similar issue today with Spring Boot (v1.1.5.RELEASE) causing double log output. It turns out logback.groovy was getting executed twice (logback.xml works fine).

My workaround was to rename logback.groovy to logbackx.groovy and update the application.properties file with:

logging.config=classpath:logbackx.groovy

@dsyer dsyer reopened this Sep 1, 2014
@dsyer
Copy link
Member

dsyer commented Sep 1, 2014

A pull request at https://github.com/spring-projects/spring-boot-issues with a sample project would still be very helpful.

@faroe228
Copy link

faroe228 commented Sep 7, 2014

I created a test example project at:

https://github.com/faroe228/spring-boot-issues/tree/master/gh-1091-groovy-logback

@philwebb philwebb added this to the 1.1.7 milestone Sep 7, 2014
@philwebb philwebb added the type: bug A general bug label Sep 7, 2014
@faroe228
Copy link

faroe228 commented Sep 7, 2014

Another observation: renaming logback.groovy to logback-test.groovy also works properly for Spring Boot (v1.1.5.RELEASE) and there is no need to update the application.properties file.

@philwebb
Copy link
Member

The logback.groovy file is being invoked more than once, but I'm not sure if there is much that we can do about that or if it is an issue.

The first invocation comes from logback itself:

Thread [main] (Suspended (breakpoint at line 786 in System))    
    System.setProperty(String, String) line: 786    
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]  
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62  
    DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43  
    Method.invoke(Object, Object...) line: 483  
    CachedMethod.invoke(Object, Object[]) line: 90  
    CachedMethod(MetaMethod).doMethodInvoke(Object, Object[]) line: 324 
    StaticMetaMethodSite$StaticMetaMethodSiteNoUnwrap.invoke(Object, Object[]) line: 130    
    StaticMetaMethodSite$StaticMetaMethodSiteNoUnwrap(StaticMetaMethodSite).call(Object, Object[]) line: 88 
    CallSiteArray.defaultCall(CallSite, Object, Object[]) line: 45  
    AbstractCallSite.call(Object, Object[]) line: 108   
    AbstractCallSite.call(Object, Object, Object) line: 120 
    Script1.run() line: 96  
    Script1$run.call(Object, Object[]) line: not available  
    CallSiteArray.defaultCall(CallSite, Object, Object[]) line: 45  
    AbstractCallSite.call(Object, Object[]) line: 108   
    AbstractCallSite.call(Object) line: 112 
    GafferConfigurator.run(String) line: 77 
    GafferConfigurator$run.callCurrent(GroovyObject, Object[]) line: not available  
    CallSiteArray.defaultCallCurrent(CallSite, GroovyObject, Object[]) line: 49 
    AbstractCallSite.callCurrent(GroovyObject, Object[]) line: 133  
    AbstractCallSite.callCurrent(GroovyObject, Object) line: 141    
    GafferConfigurator.run(URL) line: 44    
    GafferUtil.runGafferConfiguratorOn(LoggerContext, Object, URL) line: 43 
    ContextInitializer.configureByResource(URL) line: 66    
    ContextInitializer.autoConfig() line: 150   
    StaticLoggerBinder.init() line: 85  
    StaticLoggerBinder.<clinit>() line: 55  
    LoggerFactory.bind() line: 129  
    LoggerFactory.performInitialization() line: 108 
    LoggerFactory.getILoggerFactory() line: 302 
    LoggerFactory.getLogger(String) line: 276   
    SLF4JLogFactory.getInstance(String) line: 156   
    SLF4JLogFactory.getInstance(Class) line: 132    
    LogFactory.getLog(Class) line: 274  
    SpringApplication.<init>(Object...) line: 160   
    SpringApplication.run(Object[], String[]) line: 952 
    SpringApplication.run(Object, String...) line: 941  
    Application.main(String[]) line: 17 
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]  
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62  
    DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43  
    Method.invoke(Object, Object...) line: 483  
    MainMethodRunner.run() line: 53 
    Thread.run() line: 745

The second is from our custom log initialization:

Thread [main] (Suspended (breakpoint at line 786 in System))    
    System.setProperty(String, String) line: 786    
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]  
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62  
    DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43  
    Method.invoke(Object, Object...) line: 483  
    CachedMethod.invoke(Object, Object[]) line: 90  
    CachedMethod(MetaMethod).doMethodInvoke(Object, Object[]) line: 324 
    StaticMetaMethodSite$StaticMetaMethodSiteNoUnwrap.invoke(Object, Object[]) line: 130    
    StaticMetaMethodSite$StaticMetaMethodSiteNoUnwrap(StaticMetaMethodSite).call(Object, Object[]) line: 88 
    CallSiteArray.defaultCall(CallSite, Object, Object[]) line: 45  
    AbstractCallSite.call(Object, Object[]) line: 108   
    AbstractCallSite.call(Object, Object, Object) line: 120 
    Script1.run() line: 96  
    Script1$run.call(Object, Object[]) line: not available  
    CallSiteArray.defaultCall(CallSite, Object, Object[]) line: 45  
    Script1$run.call(Object) line: not available    
    GafferConfigurator.run(String) line: 77 
    GafferConfigurator$run.callCurrent(GroovyObject, Object) line: not available    
    GafferConfigurator.run(URL) line: 44    
    GafferUtil.runGafferConfiguratorOn(LoggerContext, Object, URL) line: 43 
    ContextInitializer.configureByResource(URL) line: 66    
    LogbackLoggingSystem.initialize(String) line: 101   
    LogbackLoggingSystem(AbstractLoggingSystem).initialize() line: 53   
    LoggingApplicationListener.initializeSystem(ConfigurableEnvironment, LoggingSystem) line: 209   
    LoggingApplicationListener.initialize(ConfigurableEnvironment, ClassLoader) line: 152   
    LoggingApplicationListener.onApplicationEvent(ApplicationEvent) line: 126   
    SimpleApplicationEventMulticaster.multicastEvent(ApplicationEvent) line: 98 
    EventPublishingRunListener.publishEvent(SpringApplicationEvent) line: 100   
    EventPublishingRunListener.environmentPrepared(ConfigurableEnvironment) line: 59    
    SpringApplication.run(String...) line: 284  
    SpringApplication.run(Object[], String[]) line: 952 
    SpringApplication.run(Object, String...) line: 941  
    Application.main(String[]) line: 17 
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]  
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62  
    DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43  
    Method.invoke(Object, Object...) line: 483  
    MainMethodRunner.run() line: 53 
    Thread.run() line: 745

I don't see duplicate log entries in the output but one thing that we could try is calling reset() on the LoggerContext before the second initialization. I'll commit a fix for that and lets see where that takes us.

@philwebb
Copy link
Member

Could you try the latest snapshots to see if you can reproduce the double output error. I've also merge gh-1091 into the issues repository. If you manage to make that sample fail with double logging please send an updated PR.

Cheers.

@faroe228
Copy link

Phil,

I was unable to recreate the double logging output issue (reported by PeterNSteinmetz) with either of these versions: 1.1.5.RELEASE or 1.2.0.BUILD-SNAPSHOT) using the spring-boot gradle plugin - however double file appenders are still being created because of the double execution of logback.groovy.

In the test example I submitted ( https://github.com/faroe228/spring-boot-issues/tree/master/gh-1091-groovy-logback ) one can see that two log files are created (in the log folder - one for each appender). It appears the first log file is never actually appended too (size remains zero). I also experimented with having the two different file appender instances (created by double execution of logback.groovy) to write to the same log file and there was no double output (even with the prudent property of the file appender set to true or false).

I'm guessing the double execution of logback.groovy for most situations does little harm. For the hopefully rare cases when double execution of logback.groovy would create an issue there is at least a workaround by not using the default name of logback.groovy for the logback configuration file.

Laurence Toenjes

@philwebb philwebb reopened this Sep 23, 2014
@philwebb
Copy link
Member

I've reopened this to take another look, but I think it's too risky to change the logging infrastructure at this stage in the 1.1.x line. I'll target this for 1.2 and we will have to leave it as a known issue in 1.1.x.

@philwebb philwebb modified the milestones: 1.2.0.M2, 1.1.7 Sep 25, 2014
@philwebb philwebb modified the milestones: 1.2.0.RC1, 1.2.0.M2 Oct 10, 2014
@davetownsend
Copy link

Was dealing with this issue today and seemed to be more of a logback appender additivity issue. Once I set the additivity flag to false the double logging stopped. And all was well. My ConsoleAppender and FileAppender working as expected.

@philwebb
Copy link
Member

@davetownsend Thanks for the info!

@dsyer dsyer closed this as completed Oct 27, 2014
@philwebb philwebb reopened this Oct 27, 2014
@snicoll snicoll mentioned this issue Dec 11, 2014
Closed
philwebb added a commit that referenced this issue Dec 17, 2014
@philwebb
Always reinitialize logging system
6391973 
Update LoggingSystems so that they can reinitialize themselves
before logging begins. This allows reset of the root logger (which
may have been set to OFF in beforeInitialize) and also re-evaluation
of systems properties such as PID which may not have been set when
logging configuration was first loaded.

This commit may possibly reintroduce gh-1091, but it seems like
reloading is our only option.

Fixes gh-2125
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
type: bug A general bug
Projects
None yet
Milestone
1.2.0.RC1
Development

No branches or pull requests
5 participants
@davetownsend @dsyer @philwebb @PeterNSteinmetz @faroe228