Spring-boot: /actuator/logfile returns a 404

[bzeemeijer]

I am using spring-boot-starter-actuator to expose my application logging over HTTP, this used to work but starting from Spring Boot 2.1.7.RELEASE a 404 error response is returned when querying the endpoint /actuator/logfile. The actuator endpoint is available:

_links:
  self:
    href: 'http://host:port/application/actuator'
    templated: false
  logfile:
    href: 'http://host:port/application/actuator/logfile'
    templated: false

This issue looks like the one described in issue 17434, but I am not using any generated random values, just a fixed logging file name.

The same issue is present in 2.1.8.RELASE, the problem disappears when downgrading to 2.1.6.RELEASE

[wilkinsona]

Thanks for the report but I cannot reproduce the behaviour that you have described. The endpoint works as expected for me with 2.1.8.RELEASE:

$ curl localhost:8080/actuator/logfile
2019-09-10 09:27:53.224  INFO 19960 --- [main] o.s.boot.SpringApplication               : 
  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.8.RELEASE)


2019-09-10 09:27:53.287  INFO 19960 --- [main] com.example.demo.Gh18191Application      : Starting Gh18191Application on Andys-MacBook-Pro.local with PID 19960 (/Users/awilkinson/dev/workspaces/spring-projects/spring-boot/master/gh-18191/target/classes started by awilkinson in /Users/awilkinson/dev/workspaces/spring-projects/spring-boot/master/gh-18191)
2019-09-10 09:27:53.287  INFO 19960 --- [main] com.example.demo.Gh18191Application      : No active profile set, falling back to default profiles: default
2019-09-10 09:27:54.129  INFO 19960 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2019-09-10 09:27:54.155  INFO 19960 --- [main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2019-09-10 09:27:54.156  INFO 19960 --- [main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.24]
2019-09-10 09:27:54.238  INFO 19960 --- [main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2019-09-10 09:27:54.238  INFO 19960 --- [main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 923 ms
2019-09-10 09:27:54.634  INFO 19960 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2019-09-10 09:27:54.808  INFO 19960 --- [main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 16 endpoint(s) beneath base path '/actuator'
2019-09-10 09:27:54.867  INFO 19960 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2019-09-10 09:27:54.870  INFO 19960 --- [main] com.example.demo.Gh18191Application      : Started Gh18191Application in 1.865 seconds (JVM running for 2.127)
2019-09-10 09:27:57.142  INFO 19960 --- [http-nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-09-10 09:27:57.142  INFO 19960 --- [http-nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-09-10 09:27:57.147  INFO 19960 --- [http-nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 5 ms

The above is produced with the following configuration in application.properties:

logging.file=demo.log
management.endpoints.web.exposure.include=*
spring.main.banner-mode=log

It continues to work if I set the context path to /application:

server.servlet.context-path=/application

$ curl localhost:8080/application/actuator/logfile
2019-09-10 09:30:17.929  INFO 20202 --- [main] o.s.boot.SpringApplication               : 
  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.8.RELEASE)


2019-09-10 09:30:17.988  INFO 20202 --- [main] com.example.demo.Gh18191Application      : Starting Gh18191Application on Andys-MacBook-Pro.local with PID 20202 (/Users/awilkinson/dev/workspaces/spring-projects/spring-boot/master/gh-18191/target/classes started by awilkinson in /Users/awilkinson/dev/workspaces/spring-projects/spring-boot/master/gh-18191)
2019-09-10 09:30:17.989  INFO 20202 --- [main] com.example.demo.Gh18191Application      : No active profile set, falling back to default profiles: default
2019-09-10 09:30:18.872  INFO 20202 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2019-09-10 09:30:18.895  INFO 20202 --- [main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2019-09-10 09:30:18.896  INFO 20202 --- [main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.24]
2019-09-10 09:30:18.969  INFO 20202 --- [main] o.a.c.c.C.[.[localhost].[/application]   : Initializing Spring embedded WebApplicationContext
2019-09-10 09:30:18.970  INFO 20202 --- [main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 952 ms
2019-09-10 09:30:19.358  INFO 20202 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2019-09-10 09:30:19.537  INFO 20202 --- [main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 16 endpoint(s) beneath base path '/actuator'
2019-09-10 09:30:19.595  INFO 20202 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path '/application'
2019-09-10 09:30:19.598  INFO 20202 --- [main] com.example.demo.Gh18191Application      : Started Gh18191Application in 1.893 seconds (JVM running for 2.245)
2019-09-10 09:30:21.249  INFO 20202 --- [http-nio-8080-exec-1] o.a.c.c.C.[.[localhost].[/application]   : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-09-10 09:30:21.249  INFO 20202 --- [http-nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-09-10 09:30:21.254  INFO 20202 --- [http-nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 5 ms

If you would like us to spend some more time investigating, please spend some time providing a minimal example and precise instructions that reproduce the problem, preferably as a zipped project attached to this issue.

[bzeemeijer]

After doing some more tests, the problem seems to be caused by the combination Spring Boot 2.1.7.RELEASE+ and Spring Cloud Config Server. When I retrieve the properties through Spring Cloud Config Server, the 404 error occurs, when I put the same properties in application.yml, everything works fine. I have included a zip file with a demo project which relies on a default Spring Cloud Config Server. The configuration served by this server is located in application.yml. You should be able to reproduce the issue with this project.
configuration.zip
logging-demo.zip

[wilkinsona]

Thank you. I've reproduced the problem. The change in behaviour is due to the fix for https://github.com/spring-projects/spring-boot/issues/17434. When the application's environment prepared event is fired, the properties that come from the config server aren't present. As a result, the logging.file property is absent and, as it's now only read once, that results in the log file being unavailable via the actuator's endpoint.

[bzeemeijer]

Glad you are able to reproduce the issue! Do you expect this bug to be fixed in the near future?

[wilkinsona]

It's too early to say.

My current opinion is that the change made to fix #17434 has revealed a bug in Spring Cloud. It doesn't feel right to me that it is updating the environment after the environment prepared event has been published. This is happening because it uses an ApplicationContextInitializer to load the configuration and update the environment. Ideally, it would be using an EnvironmentPostProcessor instead. /cc @spencergibb

[wilkinsona]

Until we figure out the best way to fix this, you can work around the problem by setting the external-file property on the logfile endpoint:

management:
  endpoint:
    logfile:
      external_file: demo.log

[bzeemeijer]

Thank you for providing the workaround, this is a good temporary solution which works.

[wilkinsona]

Any thoughts on this, @spencergibb?

[spencergibb]

I guess I'm a bit unsure about where "it uses an ApplicationContextInitializer" is.

[wilkinsona]

I think PropertySourceBoostrapConfiguration is the ApplicationContextInitializer that I was referring to.

[spencergibb]

:+1: so that actually gets triggered during the bootstrap phase which is triggered by BootstrapApplicationListener on ApplicationEnvironmentPreparedEvent. We spin up a new SpringApplication, extract it's environment and then create a parent application context for the regular SpringApplication. I've not looked into the ramifications of changing that class to an EnvironmentPostProcessor.

[wilkinsona]

Thanks, @spencergibb. Manipulating the environment in ApplicationEnvironmentPreparedEvent is too late. The work really needs to be done in an EnvironmentPostProcessor. Not only will that fix the issue described here, but it will also address the numerous problems we've had over the years with Cloud reinitialising Boot's logging system. If the changes to the environment were made at the correct point in the lifecycle, I believe that this code would no longer be necessary. This would fix #13077 and make #8235 obsolete. I have opened https://github.com/spring-cloud/spring-cloud-commons/issues/608.

I'm going to close this issue for now. If changes are needed in Boot to get Cloud to where we'd like it to be, we can re-open this issue or open a new issue as appropriate.