The change to filter non-existing locations, related to #27538, caused those messages to appear automatically in scenarios where there are no static resource locations. The warning messages should be updated to take into account that static resource locations may have been configured but none actually exist.
Comment From: rstoyanchev
Addressed with 76c9306dda572ab1be9b888feeb7b56ceb989d85.
Comment From: wilkinsona
I wonder if the info logging is perhaps still a little too heavy. Here's some output from a WebFlux app with no static resources and no webjars using Framework 5.3.10:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.4.11)
2021-10-18 17:54:21.441 INFO 35036 --- [ main] c.e.d.StaticResourceLoggingApplication : Starting StaticResourceLoggingApplication using Java 11.0.10 on wilkinsona-a01.vmware.com with PID 35036 (/Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.4.x/static-resource-logging/bin/main started by awilkinson in /Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.4.x/static-resource-logging)
2021-10-18 17:54:21.443 INFO 35036 --- [ main] c.e.d.StaticResourceLoggingApplication : No active profile set, falling back to default profiles: default
2021-10-18 17:54:22.312 INFO 35036 --- [ main] o.s.b.web.embedded.netty.NettyWebServer : Netty started on port 8080
2021-10-18 17:54:22.320 INFO 35036 --- [ main] c.e.d.StaticResourceLoggingApplication : Started StaticResourceLoggingApplication in 1.189 seconds (JVM running for 1.497)
And here's the output from the same app after upgrading to Framework 5.3.12 snapshots:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.4.11)
2021-10-18 17:55:42.435 INFO 36614 --- [ main] c.e.d.StaticResourceLoggingApplication : Starting StaticResourceLoggingApplication using Java 11.0.10 on wilkinsona-a01.vmware.com with PID 36614 (/Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.4.x/static-resource-logging/bin/main started by awilkinson in /Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.4.x/static-resource-logging)
2021-10-18 17:55:42.437 INFO 36614 --- [ main] c.e.d.StaticResourceLoggingApplication : No active profile set, falling back to default profiles: default
2021-10-18 17:55:43.094 INFO 36614 --- [ main] o.s.w.r.resource.ResourceWebHandler : 0 locations in use.
2021-10-18 17:55:43.096 INFO 36614 --- [ main] o.s.w.r.resource.ResourceWebHandler : 0 locations in use.
2021-10-18 17:55:43.322 INFO 36614 --- [ main] o.s.b.web.embedded.netty.NettyWebServer : Netty started on port 8080
2021-10-18 17:55:43.330 INFO 36614 --- [ main] c.e.d.StaticResourceLoggingApplication : Started StaticResourceLoggingApplication in 1.2 seconds (JVM running for 1.516)
It's a similar story with MVC. Here's the output with Framework 5.3.10:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.4.11)
2021-10-18 17:56:31.919 INFO 36673 --- [ main] c.e.d.StaticResourceLoggingApplication : Starting StaticResourceLoggingApplication using Java 11.0.10 on wilkinsona-a01.vmware.com with PID 36673 (/Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.4.x/static-resource-logging/bin/main started by awilkinson in /Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.4.x/static-resource-logging)
2021-10-18 17:56:31.921 INFO 36673 --- [ main] c.e.d.StaticResourceLoggingApplication : No active profile set, falling back to default profiles: default
2021-10-18 17:56:32.555 INFO 36673 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2021-10-18 17:56:32.564 INFO 36673 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-10-18 17:56:32.565 INFO 36673 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.53]
2021-10-18 17:56:32.617 INFO 36673 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-10-18 17:56:32.618 INFO 36673 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 656 ms
2021-10-18 17:56:32.925 INFO 36673 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2021-10-18 17:56:32.934 INFO 36673 --- [ main] c.e.d.StaticResourceLoggingApplication : Started StaticResourceLoggingApplication in 1.345 seconds (JVM running for 1.649)
And with Framework 5.3.12-SNAPSHOT:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.4.11)
2021-10-18 17:56:56.916 INFO 36723 --- [ main] c.e.d.StaticResourceLoggingApplication : Starting StaticResourceLoggingApplication using Java 11.0.10 on wilkinsona-a01.vmware.com with PID 36723 (/Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.4.x/static-resource-logging/bin/main started by awilkinson in /Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.4.x/static-resource-logging)
2021-10-18 17:56:56.918 INFO 36723 --- [ main] c.e.d.StaticResourceLoggingApplication : No active profile set, falling back to default profiles: default
2021-10-18 17:56:57.591 INFO 36723 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2021-10-18 17:56:57.600 INFO 36723 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-10-18 17:56:57.600 INFO 36723 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.53]
2021-10-18 17:56:57.664 INFO 36723 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-10-18 17:56:57.664 INFO 36723 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 704 ms
2021-10-18 17:56:57.895 INFO 36723 --- [ main] o.s.w.s.r.ResourceHttpRequestHandler : 0 locations in use.
2021-10-18 17:56:57.898 INFO 36723 --- [ main] o.s.w.s.r.ResourceHttpRequestHandler : Locations in use: [ServletContext [/]]
2021-10-18 17:56:57.973 INFO 36723 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2021-10-18 17:56:57.983 INFO 36723 --- [ main] c.e.d.StaticResourceLoggingApplication : Started StaticResourceLoggingApplication in 1.391 seconds (JVM running for 1.716)
Unfortunately, the new log output doesn't feel useful enough to me to warrant being at info level. I would be quite happy if nothing was logged (as happens at the moment with 5.3.10) so dropping the new logging down to debug is my preference.
If something is logged at info level, I think it would make the logging more useful if it included the paths at which those locations will be served. It looks as if that may require the logging to be moved as I don't think the handlers know about the paths.
Comment From: rstoyanchev
I'm fine to drop the logging to debug. It would match what we do for other handler mappings. In terms of URL paths, AbstractHandlerMapping implements BeanNameAware and this is what other handler mappings use for logging. We can use the same and that would help to identify which resources HandlerMapping is which.
Comment From: rstoyanchev
At DEBUG level we actually have logging from the static resources SimpleUrlHandlerMapping which includes both the paths and individual resource handlers, each with its (already filtered) locations:
2021-10-19 12:22:05.017 DEBUG 1006119 --- [ main] _.s.web.servlet.HandlerMapping.Mappings : 'resourceHandlerMapping' {/webjars/**=ResourceHttpRequestHandler [], /**=ResourceHttpRequestHandler [classpath [static/], ServletContext [/]]}
So I've removed those log messages entirely since they don't add anything new and don't have all the relevant information anyway.