Generator-jhipster: Logstash appender stops working after logback-spring.xml change

[gmarziou]

Overview of the issue

Opening this issue to follow up on discussion started on jhipster/jhipster-console#41

Logstash appender is configured programmatically because of custom fields using dynamic properties, other part of logback configuration is done in logback-spring.xml file. When the app is running, if you make changes to logback-spring.xml file and scan attribute is true, the logback context is reset and the programmatic part of the configuration is lost, resulting in log events no longer forwarded to Logstash.

Motivation for or Use Case

A fairly common use case is changing the log level on some logger while the app is running, this breaks our ELK monitoring and requires an application restart to fix it.

Reproduce the error

• devtools are not used to be sure that modifying src/main/resources/logback-spring.xml will not reload the app context
• configure logstash appender
• run the app with mvn spring-boot:run
• while running, change logger level in src/main/resources/config/logback-spring.xml

=> No more logs in Kibana from this app

Suggest a Fix

I added a LoggerContextListener that adds logstash appender on reset event as shown in the log below:

Log after changing log level in logback-spring.xml

18:57:04,904 |-INFO in ReconfigureOnChangeTask(born:1471969999958) - Detected change in configuration files.
18:57:04,904 |-INFO in ReconfigureOnChangeTask(born:1471969999958) - Will reset and reconfigure context named [default]
18:57:04,904 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_LOGSTASH] - Worker thread will flush remaining events before exiting. 
18:57:04,909 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_LOGSTASH] - Queue flush finished successfully within timeout.
18:57:04,911 |-INFO in net.logstash.logback.appender.LogstashSocketAppender[LOGSTASH] - Defaulting maxMessageSize to [8192]
18:57:04,911 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_LOGSTASH] - Attaching appender named [LOGSTASH] to AsyncAppender.
18:57:04,911 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_LOGSTASH] - Setting discardingThreshold to 102
18:57:04,911 |-INFO in com.example.LogbackLoggerContextListener@1eed657 - Added Logstash Appender
18:57:04,904 |-INFO in ReconfigureOnChangeTask(born:1471969999958) - Detected change in configuration files.
18:57:04,904 |-INFO in ReconfigureOnChangeTask(born:1471969999958) - Will reset and reconfigure context named [default]
18:57:04,904 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_LOGSTASH] - Worker thread will flush remaining events before exiting. 
18:57:04,909 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_LOGSTASH] - Queue flush finished successfully within timeout.
18:57:04,911 |-INFO in net.logstash.logback.appender.LogstashSocketAppender[LOGSTASH] - Defaulting maxMessageSize to [8192]
18:57:04,911 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_LOGSTASH] - Attaching appender named [LOGSTASH] to AsyncAppender.
18:57:04,911 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_LOGSTASH] - Setting discardingThreshold to 102
18:57:04,911 |-INFO in com.example.LogbackLoggerContextListener@1eed657 - Added Logstash Appender
18:57:04,913 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/C:/projets/gh-issues/test-logback-reload/target/classes/logback-spring.xml] 
18:57:04,913 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 5 seconds
18:57:04,914 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
18:57:04,914 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
18:57:04,914 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
18:57:04,915 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.example] to INFO
18:57:04,915 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
18:57:04,915 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
18:57:04,915 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
18:57:04,915 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@144d9e1 - Registering current configuration as safe fallback point

You can see it in my minimal project, I need to cleanup code a little and I will submit a PR.

JHipster Version(s)

3.6.1

[jdubois]

I didn't think of this!! You are perfectly right @gmarziou and this is quite important.

Do you have the time to do the PR? As this has been opened for more than one month, do you need help?

[gmarziou]

I don't need help, I'll work on it this by end of week.