Update warn log message for empty static resource locations

[rstoyanchev]

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.

[rstoyanchev]

Addressed with 76c9306.

[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.

[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.

[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.