Document logger environment variable restrictions

[vpavic]

I'm trying to configure log level for a concrete logger using environment variable, but am unable to do so since binding doesn't appear to work correctly in this case.

This can be easily reproduce using a simple Spring Boot application consisting of only spring-boot-starter-web. For example, setting log level for org.springframework.web.context using LOGGING_LEVEL_ORG_SPRINGFRAMEWORK_WEB_CONTEXT works:

$ env LOGGING_LEVEL_ORG_SPRINGFRAMEWORK_WEB_CONTEXT=DEBUG java -jar build/libs/spring-boot-sample.jar 

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.7.RELEASE)

2019-08-25 21:32:35.719  INFO 429 --- [           main] sample.SampleApplication                 : Starting SampleApplication on thinkpad with PID 429 (/home/vpavic/dev/projects/misc/spring-boot-sample/build/libs/spring-boot-sample.jar started by vpavic in /home/vpavic/dev/projects/misc/spring-boot-sample)
2019-08-25 21:32:35.723  INFO 429 --- [           main] sample.SampleApplication                 : No active profile set, falling back to default profiles: default
2019-08-25 21:32:36.706  INFO 429 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2019-08-25 21:32:36.750  INFO 429 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2019-08-25 21:32:36.750  INFO 429 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.22]
2019-08-25 21:32:36.849  INFO 429 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2019-08-25 21:32:36.849 DEBUG 429 --- [           main] o.s.web.context.ContextLoader            : Published root WebApplicationContext as ServletContext attribute with name [org.springframework.web.context.WebApplicationContext.ROOT]
2019-08-25 21:32:36.849  INFO 429 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1076 ms
2019-08-25 21:32:37.050  INFO 429 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2019-08-25 21:32:37.228  INFO 429 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2019-08-25 21:32:37.232  INFO 429 --- [           main] sample.SampleApplication                 : Started SampleApplication in 1.96 seconds (JVM running for 2.289)

(notice the DEBUG log message)

However trying to set log level for org.springframework.web.context.ContextLoader doesn't work:

$ env LOGGING_LEVEL_ORG_SPRINGFRAMEWORK_WEB_CONTEXT_CONTEXTLOADER=DEBUG java -jar build/libs/spring-boot-sample.jar 

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.7.RELEASE)

2019-08-25 21:32:47.995  INFO 515 --- [           main] sample.SampleApplication                 : Starting SampleApplication on thinkpad with PID 515 (/home/vpavic/dev/projects/misc/spring-boot-sample/build/libs/spring-boot-sample.jar started by vpavic in /home/vpavic/dev/projects/misc/spring-boot-sample)
2019-08-25 21:32:47.999  INFO 515 --- [           main] sample.SampleApplication                 : No active profile set, falling back to default profiles: default
2019-08-25 21:32:48.921  INFO 515 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2019-08-25 21:32:48.994  INFO 515 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2019-08-25 21:32:48.995  INFO 515 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.22]
2019-08-25 21:32:49.108  INFO 515 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2019-08-25 21:32:49.108  INFO 515 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1030 ms
2019-08-25 21:32:49.327  INFO 515 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2019-08-25 21:32:49.519  INFO 515 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2019-08-25 21:32:49.523  INFO 515 --- [           main] sample.SampleApplication                 : Started SampleApplication in 1.97 seconds (JVM running for 2.353)

I've also tried with:

$ env LOGGING_LEVEL_ORG_SPRINGFRAMEWORK_WEB_CONTEXT_CONTEXT_LOADER=DEBUG java -jar build/libs/spring-boot-sample.jar 

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.7.RELEASE)

2019-08-25 21:32:56.356  INFO 596 --- [           main] sample.SampleApplication                 : Starting SampleApplication on thinkpad with PID 596 (/home/vpavic/dev/projects/misc/spring-boot-sample/build/libs/spring-boot-sample.jar started by vpavic in /home/vpavic/dev/projects/misc/spring-boot-sample)
2019-08-25 21:32:56.362  INFO 596 --- [           main] sample.SampleApplication                 : No active profile set, falling back to default profiles: default
2019-08-25 21:32:57.308  INFO 596 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2019-08-25 21:32:57.361  INFO 596 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2019-08-25 21:32:57.362  INFO 596 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.22]
2019-08-25 21:32:57.445  INFO 596 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2019-08-25 21:32:57.446  INFO 596 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1035 ms
2019-08-25 21:32:57.664  INFO 596 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2019-08-25 21:32:57.827  INFO 596 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2019-08-25 21:32:57.831  INFO 596 --- [           main] sample.SampleApplication                 : Started SampleApplication in 1.888 seconds (JVM running for 2.279)

The issue is that LOGGING_LEVEL_ORG_SPRINGFRAMEWORK_WEB_CONTEXT_CONTEXTLOADER gets resolved to org.springframework.web.context.contextloader in LoggingApplicationListener#setLogLevels which obviously won't configure the desired logger. I would assume there should be some special handling for setting concrete loggers. I didn't find anything in reference documentation about this limitation.

[Sauhardstark]

@vpavic
Hi, you can make it work by setting it as
logging.level.org.springframework.web.context.ContextLoader = DEBUG

So if you run the command
env logging.level.org.springframework.web.context.ContextLoader = DEBUG java -jar build/libs/spring-boot-sample.jar

it will work exactly as expected. One other way I found would require the Logger class in ch.qos.logback.classic to to add an else after the if statement

            if (childName.equals(childName_i)) {
                return childLogger_i;
            }

If you add an else if statement checking again but this time with equalsIgnoreCase()

           else if (childName.equalsIgnoreCase(childName_i)) {
                return childLogger_i;
            }

Since we can't do that here, my suggestion would be to go with the first approach

[vpavic]

The dot is not a valid character in a shell identifier - while it works using env (which is used here only for demonstration purposes) you'll not be able to export such a variable.

[philwebb]

I'm trying to think how we can fix this. One option would be to try and make all logger lookups case-insensitive, but I'm really not sure how we can do that. Another might be try and find a class name that matches the logger name (using some case-insensitive search) then use the found class name to get the correct case back.

I'll flag this one for team attention to see if anyone else has some bright ideas.

[wilkinsona]

With both Logback (a list of loggers) and Log4j2 (a map of name -> logger config) it is possible to perform a case insensitive match for existing loggers when setting a log level. However, that would not help when the level is being set before the logger has been created. Setting the level would then create the logger with a name that does not match the one used in application code. We could further refine this by trying to find a class name that is a case-insensitive match for the logger name as @philwebb suggests above.

Other than using SPRING_APPLICATION_JSON I don't have any other ideas here at the moment, let alone bright ones.

[philwebb]

See also #17975 for another issue that would be impossible to set in environment variables.

[philwebb]

We'll make this one a documentation issue since there's no easy fix. I've opened #18003 to see if we can't come up with a better long term solution.