Improve output from logging the map of request mappings [SPR-17450]

[spring-projects-issues]

Gleb Tlaloc opened SPR-17450 and commented

MVC mappings was automatically logged in previous releases of Spring MVC. This was removed in June 2018 for v5.1.0, see the commit. The change was titled as "Logging improvements for WebFlux". But frankly, I don't see any improvement in removing a valuable log command without any appropriate replacement.

This was removed from o.s.w.s.h.AbstractHandlerMethodMapping.MappingRegistry.register(...):

if (logger.isInfoEnabled()) {
    logger.info("Mapped \"" + mapping + "\" onto " + handlerMethod);				}

Even with log level TRACE, this information is no longer logged by any Spring component. During development this logs are a very good (and fast) information source to self-review the final configuration of HTTP mappings.

I couldn't find any documentation that explains this change.

Could you please do a review to assess if this change is intended? And if it is intended can you please publish some kind of documentation to explain what to do/use instead? Or, can you please consider to reenable this log again (at least on DEBUG level)?

---

Affects: 5.1.2

Reference URL: 28a5c30#diff-b91ebdcf6fba7c4886849e8144a7e687

Referenced from: commits c89e6c6

[spring-projects-issues]

Rossen Stoyanchev commented

This has been given plenty of thought. The approach is documented on a wiki page but it's currently no linked to from the reference so it's not easy to find. The wiki mentions the case of request mappings. For further background, the request originated here, and the umbrella ticket for all changes is #21485.

The full request mappings are logged at TRACE but as a map and not on individual lines. I suppose we could change the way the map is logged but that would also blow up the output, and unless you have wrapping on for the IDE console, which is off by default, it takes a lot of awkward scrolling left and right to get to a specific detail. The advantage of printing a map is that it doesn't overwhelm the output as a single line, and yet  it's possible to search which is often needed anyway, and easy to copy the one line into an editor.  

I'm open to ideas for how to improve the debugging experience for request mappings, but simply dumping tens or potentially hundreds of lines with full method signatures and request mapping details at DEBUG, I'm afraid is not the best approach. It's worth pointing out the request mappings are available via RequestMappingHandlerMapping#getHandlerMethods() for anyone to access, log, or query. In a Boot app request mappings are available via actuator endpoints, so you can open a browser page or use curl from the command line. I find such on-demand lookup is a more fitting solution for the problem.

 

[spring-projects-issues]

Gleb Tlaloc commented

Thank you for the explanation.

You're right. I can enable some logging by adding this to my DEV configuration.

logging.level.org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping: "trace"

But the quality of the result is still not the same as before. You already pointed it out. I have to scroll right now and need to search(!) for the information I want to know.

Example: The log output changed from ...

Mapped "{[/api/documents/{id}],methods=[GET],produces=[application/json]}" onto public myservice.document.DocumentDto myservice.document.read.ReadDocumentController.read(java.lang.String)

... to ...

Mapped 1 handler method(s) for class myservice.document.read.ReadDocumentController: {public myservice.document.DocumentDto myservice.document.read.ReadDocumentController.read(java.lang.String)={[/api/documents/{id}],methods=[GET],produces=[application/json]}}

The new log output is longer, as you mentioned. The only reason it is still understandable is because I prevent multiple mappings in controllers (whenever possible). If I would have multiple mappings within my controller it would be even more difficult to look for the information of interest.

The previous log result puts the mapping almost at the beginning of the log message. I instantly can see that the endpoint GET /api/documents/... was initialized without the need to scroll to the right. This is very valuable, especially if you need to handle different configurations and feature toggles.

The new logging puts information about the implementing component at the beginning of the log message. This results in the need to scroll right and is usually less interesting and only important if I need to take a deeper look into a specific mapping.

The most typical questions (I usually face during development) that should be answered by this log output (as fast as possible):

• Is the mapping initialized and active?
• Is the mapping path correct?
• Is the HTTP method correct?

Some ideas:

• Bring back the original log message (in AbstractHandlerMethodMapping.MappingRegistry.register) but with TRACE level. You also can keep the new log message in AbstractHandlerMethodMapping.detectHandlerMethods by using different loggers to let the developer decide which one gives the better result.
• Use the Spring event system to send a notification about a registered mapping. Spring could provide 1 or more default implementations that could be enabled/disabled by using the Spring Boot configuration mechanisms. Also, developers can decide to implement a custom event listener and log the register-mapping event the way they want.

I think I understand the purpose of this change. You want to make the logs more clean. I totally support that, for production. But that doesn't have to mean that this rule must also apply for development.

Maybe you can give the Liquibase team some tips, they just changed they logging to be more blathering, without the possibility to shut it down ;) As a result: Spring reduced their logging (unwanted for development) and Liquibase increased it (unwanted for production).

Right now, this is what I don't like the most after upgrading to Spring Boot 2.1 and all the implied dependency upgrades. That is also a compliment, because (honestly) this is complaining on a high level ;)

[spring-projects-issues]

Gleb Tlaloc commented

One more thing.The WebMvcEndpointHandlerMapping still logs the Spring Boot Actuator mappings with the old/previous pattern. So even if you don't agree with me, right now the log output for the Controller components and the Actuator mappings are inconsistent. This is probably because WebMvcEndpointHandlerMapping is part of Spring Boot and not Spring MVC?!

See yourself by enabling TRACE logging for these 2 components:

logging.level.org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping: "trace"
logging.level.org.springframework.boot.actuate.endpoint.web.servlet.WebMvcEndpointHandlerMapping: "trace"

This inconsistence could be cleaned up. Please have a look at this snipped.

public abstract class AbstractHandlerMethodMapping<T> extends AbstractHandlerMapping implements InitializingBean {

    [...]

    public void registerMapping(T mapping, Object handler, Method method) {
        if (logger.isTraceEnabled()) {
            logger.trace("Register \"" + mapping + "\" to " + method.toGenericString());
        }
        this.mappingRegistry.register(mapping, handler, method);
    }

    [...]

    protected void registerHandlerMethod(Object handler, Method method, T mapping) {
        this.mappingRegistry.register(mapping, handler, method);
    }

    [...]
}

These 2 methods do exactly the same, except one of them has no logging. Why can't registerHandlerMethod() just invoke registerMapping()?

For now I'm using a workaround. I've created a logger component to print a consistent log output by using getHandlerMethods() of RequestMappingHandlerMapping and WebMvcEndpointHandlerMapping after the application context is ready. Thanks for the tip ;)

But it still feels odd to create extra code because something is no longer done right (my opinion) by the framework.

[spring-projects-issues]

Rossen Stoyanchev commented

 The WebMvcEndpointHandlerMapping still logs the Spring Boot Actuator mappings with the old/previous pattern.

That's a Boot issue and there is a ticket already for it spring-projects/spring-boot#14292.

These 2 methods do exactly the same, except one of them has no logging. Why can't registerHandlerMethod() just invoke registerMapping()

registerHandlerMethod is for methods auto-detected on startup, which we do print, once initialized as a complete map. registerMapping is an API for dynamic, programatic registrations and derigistration, which can occur individually and at any time when the application is starting or running. So that's more like a runtime event. This is why they are logged differently.

I totally support that, for production. But that doesn't have to mean that this rule must also apply for development.

I can suggest reading the original request again but I'm sure you've done that. Development logging needs to be human friendly and not overwhelming. For example Spring Boot does a lot of tuning of log levels when devtools is present, and the levels varyi by project, in order to get a good out of the box dev experience. Consider that up until Spring Framework 5.1, Boot did not consider it feasible to set org.springframework.web to DEBUG because it creates too much noise, and of course the next level up is INFO which produces too little. So there needs to be a friendly and responsible DEBUG level first and then TRACE.

For the suggestions, we already log what you need at TRACE. I can however improve the output from the Map so that it looks like before with the mapping at the front. I don't think sending events makes much sense. All of this is readily available to applications to access at any time.

[spring-projects-issues]

Gleb Tlaloc commented

[...] Development logging needs to be human friendly and not overwhelming.[...]

Exactly. As I see it, the way Spring MCV is doing it now, doesn't fulfill this requirements. To get some information during development (e.g the active request mappings for a single(!) moment after I startet the application), I have to change the log level to TRACE now, at least for specific components.

Result:

• I get a confusing output wich is hard to understand and inconvenient to use. (human friendly: fail)
• When I send test requests to my endpoints, now I get 4 additional TRACE log entries per request which are irrelevant most of the time. At a closer look it's just 2 log entries per request but for some reason it's logged twice, so it's 4. (not overwhelming: fail)

Keep in mind that it is easier to clear the logs after the server has started to get rid of the "overwhelming" logs which was produced by the bootstrap procedure. But because of the initial log configuration I have more unnecessary log output during (dev) runtime.

The funny thing is. You intended to reduce the noise. In reality (as least in my case): To get required information from the logs during dev, now I have to enable even more noise. So, what's the gain here?

Conclusion: Now I have to enable a log level to see what I want in a way that is harder to understand as before. I'm also forced to see things I don't want or need because of that log level.

I know this is all about opinions. It would be interesting how other developers see this new logging behavior. From my perspective: this change is not(!) helping. It make things worse.

Before this change the request mapping was logged at INFO. Yes that was unnecessary. And to get rid of it, you don't just put it from the lobby to the basement. No, you put it deep underground. And to get to it I have to go through a lot more stuff now.

[spring-projects-issues]

Mark Jeffrey commented

Hi Rossen Stoyanchev

When I moved from JBoss to Spring Boot one of the many things I loved was that the mappings were output on startup!

A minor thing but it saves a lot of frustration when developing a web app (and particularly when you go back to a project after some time).

Today I had a 404 in a new Spring Boot 2.1 project. I checked the mappings and saw there were none! I assumed it was some new config parameter but  after digging through the source code I found it was removed from AbstractHandlerMethodMapping on 18-June.

Along with the listener port this is the most important startup output.

The new output on trace is nowhere near as useful as the previous output (it is there but well hidden).

For now I've reverted to Spring Boot 2.0 (at least during heavy development since we are targeting java 8). I would love to see this output restored (even as  DEBUG it would be good).

thanks,

Mark

[spring-projects-issues]

Rossen Stoyanchev commented

Mark Jeffrey, the key here is that mapping information becomes important when you are looking into a 404. I suspect that overall more time is spent developing the endpoints rather than changing mappings. And unlike the listener port, which is a simple int, mappings can easily overtake startup logging.

Did you consider using the Boot Actuator endpoint for mappings? Most IDEs also support options for working with Spring MVC mappings. 

I'll consider improvements for the new output on trace soon. It's hidden compared to what you are used to seeing, but at the same time there are a lots of options for getting this information.

[spring-projects-issues]

Mark Jeffrey commented

Rossen Stoyanchev Thanks for the reply. Indeed I checked in intellij and there is a possibility for seeing the endpoints in the Spring tab. Sorry to see the most useful logging in the SB startup go when some of the other logging is really useless (I realize that is a different project and I can turn it off).

Examples of useless logging, for me most of this could go:

2018-11-08 16:16:11.151  INFO 14944 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2018-11-08 16:16:11.152  INFO 14944 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 2154 ms
2018-11-08 16:16:11.220  INFO 14944 --- [           main] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'characterEncodingFilter' to: [/*]
2018-11-08 16:16:11.222  INFO 14944 --- [           main] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2018-11-08 16:16:11.222  INFO 14944 --- [           main] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'formContentFilter' to: [/*]
2018-11-08 16:16:11.222  INFO 14944 --- [           main] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'requestContextFilter' to: [/*]
2018-11-08 16:16:11.223  INFO 14944 --- [           main] .s.DelegatingFilterProxyRegistrationBean : Mapping filter: 'springSecurityFilterChain' to: [/*]
2018-11-08 16:16:11.224  INFO 14944 --- [           main] o.s.b.w.servlet.ServletRegistrationBean  : Servlet dispatcherServlet mapped to [/]
2018-11-08 16:16:11.389  INFO 14944 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2018-11-08 16:16:12.236  INFO 14944 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2018-11-08 16:16:13.124  INFO 14944 --- [           main] liquibase.database.core.OracleDatabase   : Could not set remarks reporting on OracleDatabase: com.zaxxer.hikari.pool.HikariProxyConnection.setRemarksReporting(boolean)
2018-11-08 16:16:13.196  INFO 14944 --- [           main] liquibase.database.core.OracleDatabase   : Could not set check compatibility mode on OracleDatabase, assuming not running in any sort of compatibility mode: Cannot read from v$parameter: ORA-00942: table or view does not exist

2018-11-08 16:16:13.414  INFO 14944 --- [           main] liquibase.executor.jvm.JdbcExecutor      : SELECT COUNT(*) FROM IBIS.DATABASECHANGELOGLOCK
2018-11-08 16:16:13.422  INFO 14944 --- [           main] liquibase.executor.jvm.JdbcExecutor      : SELECT COUNT(*) FROM IBIS.DATABASECHANGELOGLOCK
2018-11-08 16:16:13.424  INFO 14944 --- [           main] liquibase.executor.jvm.JdbcExecutor      : SELECT LOCKED FROM IBIS.DATABASECHANGELOGLOCK WHERE ID=1 FOR UPDATE
2018-11-08 16:16:13.440  INFO 14944 --- [           main] l.lockservice.StandardLockService        : Successfully acquired change log lock
2018-11-08 16:16:14.134  INFO 14944 --- [           main] liquibase.executor.jvm.JdbcExecutor      : SELECT MD5SUM FROM IBIS.DATABASECHANGELOG WHERE MD5SUM IS NOT NULL AND ROWNUM=1
2018-11-08 16:16:14.136  INFO 14944 --- [           main] liquibase.executor.jvm.JdbcExecutor      : SELECT COUNT(*) FROM IBIS.DATABASECHANGELOG
2018-11-08 16:16:14.138  INFO 14944 --- [           main] l.c.StandardChangeLogHistoryService      : Reading from IBIS.DATABASECHANGELOG
2018-11-08 16:16:14.138  INFO 14944 --- [           main] liquibase.executor.jvm.JdbcExecutor      : SELECT * FROM IBIS.DATABASECHANGELOG ORDER BY DATEEXECUTED ASC, ORDEREXECUTED ASC
2018-11-08 16:16:14.158  INFO 14944 --- [           main] l.lockservice.StandardLockService        : Successfully released change log lock
2018-11-08 16:16:14.302  INFO 14944 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [
	name: default
	...]
2018-11-08 16:16:14.445  INFO 14944 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate Core {5.3.7.Final}
2018-11-08 16:16:14.452  INFO 14944 --- [           main] org.hibernate.cfg.Environment            : HHH000206: hibernate.properties not found
2018-11-08 16:16:14.662  INFO 14944 --- [           main] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {5.0.4.Final}
2018-11-08 16:16:14.849  INFO 14944 --- [           main] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.Oracle12cDialect
2018-11-08 16:16:14.927  INFO 14944 --- [           main] o.h.e.j.e.i.LobCreatorBuilderImpl        : HHH000421: Disabling contextual LOB creation as hibernate.jdbc.lob.non_contextual_creation is true
2018-11-08 16:16:14.934  INFO 14944 --- [           main] org.hibernate.type.BasicTypeRegistry     : HHH000270: Type registration [byte[]] overrides previous : org.hibernate.type.BinaryType@38a38ed4
2018-11-08 16:16:14.935  INFO 14944 --- [           main] org.hibernate.type.BasicTypeRegistry     : HHH000270: Type registration [[B] overrides previous : org.hibernate.type.BinaryType@38a38ed4
2018-11-08 16:16:14.936  INFO 14944 --- [           main] org.hibernate.type.BasicTypeRegistry     : HHH000270: Type registration [Byte[]] overrides previous : org.hibernate.type.WrapperBinaryType@4bbf20d1
2018-11-08 16:16:14.936  INFO 14944 --- [           main] org.hibernate.type.BasicTypeRegistry     : HHH000270: Type registration [[Ljava.lang.Byte;] overrides previous : org.hibernate.type.WrapperBinaryType@4bbf20d1
2018-11-08 16:16:15.936  INFO 14944 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2018-11-08 16:16:17.244  INFO 14944 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2018-11-08 16:16:17.629  INFO 14944 --- [           main] .i.w.c.BasicWebSecurityConfigurerAdapter : Content Security Policy: block-all-mixed-content; object-src 'none'; frame-src 'none'; default-src 'self'; img-src 'self' data:; style-src 'self'; connect-src 'self' 
2018-11-08 16:16:17.686  INFO 14944 --- [           main] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: any request, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@411933, org.springframework.security.web.context.SecurityContextPersistenceFilter@5008559a, org.springframework.security.web.header.HeaderWriterFilter@f5f8de2, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@490fbeaa, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@39c1e7b7, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@393e7546, org.springframework.security.web.session.SessionManagementFilter@1002b06d, org.springframework.security.web.access.ExceptionTranslationFilter@68f264bf, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@70ad0854]

[spring-projects-issues]

Rossen Stoyanchev commented

Mark Jeffrey, indeed good logging takes extra thought, continuous feedback and multiple iterations. I'm afraid the quality of logging is often an afterthought. This is very much the spirit of the extensive improvements made to web logging in 5.1 to change that, and I welcome paying closer attention like the messages you've pointed out above.

Most of the examples aren't in the Spring Framework. There is only the ContextLoader message with the startup time which I think is useful to know but debatable if the startup is already known.

For the Boot servlet registrations, creating a ticket against Boot, for this and if you have others, would be the way to go (/cc Brian Clozel). I can see replacing the filter registration log statements with a single line that lists active filters and patterns, something like below, and the log level is also debatable:

CharacterEncodingFilter [/*], HiddenHttpMethodFilter [/*], FormContentFilter [/*], ...

 
The Spring Security filter chain logging also has room for improvement (/cc Rob Winch), and for that use the Spring Security issue tracker. For once I don't think the full package names are necessary, I don't think anyone will have any trouble finding a class by its name in an IDE with the full classpath present. So something like this perhaps:

Security chain: WebAsyncManagerIntegrationFilter -> SecurityContextPersistenceFilter -> ...

For the others Boot does tweak logging for specific packages as far as I know, so they might be able to turn some of that noise down.

[spring-projects-issues]

Brian Clozel commented

Thanks for the heads up rstoyanchev, I've created spring-boot#15166.

[spring-projects-issues]

Rossen Stoyanchev commented

Below is sample output after the changes, based on these test controllers:

17:06:21.238 [main] TRACE org.springframework.web.reactive.result.method.annotation.RequestMappingHandlerMapping - 
	o.s.w.r.r.m.a.PersonCreateController:
	{POST /person-create/single}: createWithSingle(Single)
	{POST /person-create/rxjava2-single}: createWithRxJava2Single(Single)
	{POST /person-create/flux}: createWithFlux(Flux)
	{POST /person-create/publisher}: createWithPublisher(Publisher)
	{POST /person-create/mono}: createWithMono(Mono)
	{POST /person-create/observable}: createWithObservable(Observable)
	{POST /person-create/rxjava2-observable}: createWithRxJava2Observable(Observable)
	{POST /person-create/flowable}: createWithFlowable(Flowable)
17:06:21.270 [main] TRACE org.springframework.web.reactive.result.method.annotation.RequestMappingHandlerMapping - 
	o.s.w.r.r.m.a.PersonResponseBodyController:
	{GET /person-response/completable-future}: getCompletableFuture()
	{GET /person-response/mono}: getMono()
	{GET /person-response/mono-declared-as-object}: getMonoDeclaredAsObject()
	{GET /person-response/single}: getSingle()
	{GET /person-response/mono-response-entity}: getMonoResponseEntity()
	{GET /person-response/mono-response-entity-xml}: getMonoResponseEntityXml()
	{GET /person-response/list}: getList()
	{GET /person-response/publisher}: getPublisher()
	{GET /person-response/flux}: getFlux()
	{GET /person-response/observable}: getObservable()
	{GET /person-response/person}: getPerson()
17:06:21.311 [main] TRACE org.springframework.web.reactive.result.method.annotation.RequestMappingHandlerMapping - 
	o.s.w.r.r.m.a.PersonTransformationController:
	{POST /person-transform/completable-future}: transformCompletableFuture(CompletableFuture)
	{POST /person-transform/mono}: transformMono(Mono)
	{POST /person-transform/single}: transformSingle(Single)
	{POST /person-transform/rxjava2-single}: transformRxJava2Single(Single)
	{POST /person-transform/rxjava2-maybe}: transformRxJava2Maybe(Maybe)
	{POST /person-transform/publisher}: transformPublisher(Publisher)
	{POST /person-transform/flux}: transformFlux(Flux)
	{POST /person-transform/observable}: transformObservable(Observable)
	{POST /person-transform/rxjava2-observable}: transformObservable(Observable)
	{POST /person-transform/flowable}: transformFlowable(Flowable)
	{POST /person-transform/person}: transformPerson(Person)
17:06:21.339 [main] TRACE org.springframework.web.reactive.result.method.annotation.RequestMappingHandlerMapping - 
	o.s.w.r.r.m.a.RawResponseBodyController:
	{GET /raw-response/publisher}: getPublisher()
	{GET /raw-response/flux}: getFlux()
	{GET /raw-response/observable}: getObservable()
	{GET /raw-response/rxjava2-observable}: getRxJava2Observable()
	{GET /raw-response/mono}: getMonoString()
	{GET /raw-response/flowable}: getFlowable()
 

The output is tailored for request mapping purposes and aims to show only what's relevant for finding the method for a given request mapping. For example there is no need to show return type information in order to identify a method uniquely, and likewise there is no need to show full type information for method parameters. Indenting all logging information makes it easy to visually skip over it to subsequent log messages.

Gleb Tlaloc this should meet one of your options, i.e.:

Bring back the original log message (in AbstractHandlerMethodMapping.MappingRegistry.register) but with TRACE level.

Let me know if you think anything is missing or could be added.

[spring-projects-issues]

Rossen Stoyanchev commented

Resolving for now.

[marnee01]

Rossen Stoyanchev commented:

In a Boot app request mappings are available via actuator endpoints

Which actuator endpoint lists all the service endpoints? I haven't found that info in documentation.

[bclozel]

It’s the mappings endpoint.
See https://docs.spring.io/spring-boot/docs/current/reference/html/production-ready-features.html#production-ready-endpoints and https://docs.spring.io/spring-boot/docs/2.3.0.RELEASE/actuator-api/html/#mappings