Provide debug logs if http-method (POST) rejected with 401 when CSRF (default) enabled

[dopsun]

Summary

By default, Spring Boot web application with CSRF enabled, unless doing http.csrf().disabled() explicitly. HTTP POST to RESTful API with basic authentication, will be rejected as 401 UNAUTHORIZED. And server side, no specific logging even after enabling debug output.

Propose to provide debug logs in CsrfFilter after matches in Line 196 failed.

Actual Behavior

Client side receives 401 status code, and server side no specific logs.

Expected Behavior

Server side provides debug log "POST is not supported while CSRF enabled" or alike, to help developers trouble shoot.

Configuration

See Sample.

Version

5.1.6.RELEASE

Sample

@Override
protected void configure(HttpSecurity http) throws Exception {
    http.authorizeRequests()
            .anyRequest().authenticated()
            .and().httpBasic();

    // http.csrf().disable();  // comment this line, client POST failed with 401
}

[jzheaux]

Related to #6311

[dopsun]

@jzheaux thanks.

Let me put some more background for this enhancement request. It's not technical. I write this up to hopefully explain why I believe this enhancement could be helpful.

It started from POST failed with 401.

• Spend some time to ensure username/ password used is correct.
• Spend some time to enable debug log, run several times and nothing showing in the server.
• Spend some time to use curl to confirm this is not because of my client side Java code.
• Spend some time to Google, but queries like spring http post 401 are so comon and leads to no clue and sometimes misleading.
• Spend some time to change server end point to GET temporaries, and suddenly it reaches server! (well, I feel lucky). From here, I start suspecting request rejected earlier in the filter chain.
• Spend some time to put break points and tracing each filter... and find the CsrfFilter blocks.
• Spend some time to figure out how to disable it with http.csrf().disable().

Adds all these some time together, it took quit some time to get over this. And I guess a server side log to tell "POST not supported when CSRF enabled" with source from CsrfFilter can reduce a lot effort.

[marcusdacoregio]

Hello @dopsun.

I've tried to simulate the problem:

• I ran this sample with DEBUG log level
• Performed a POST using basic authentication

The logs showed me exactly what happened when enabling DEBUG.

DEBUG 19462 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Securing POST /
DEBUG 19462 --- [nio-8080-exec-1] s.s.w.c.SecurityContextPersistenceFilter : Set SecurityContextHolder to empty SecurityContext
DEBUG 19462 --- [nio-8080-exec-1] o.s.security.web.csrf.CsrfFilter         : Invalid CSRF token found for http://localhost:8080/
DEBUG 19462 --- [nio-8080-exec-1] o.s.s.w.access.AccessDeniedHandlerImpl   : Responding with 403 status code

The 401 status code comes because Spring Boot redirects to the /error endpoint upon an error, and that endpoint is also protected by Spring Security.

I'm closing this as invalid but if I missed something, please let's discuss.

[Bharghav1]

Hello @marcusdacoregio could you please provide an example using Maven project?

[marcusdacoregio]

Hi @Bharghav1, do you mean enabling the logs? If you are using Spring Boot, you can just add logging.level.org.springframework.security=DEBUG to your application.properties file. There should be no difference between Gradle and Maven for this.

[Bharghav1]

Thank you @marcusdacoregio , I was looking for csrfFilter loggings but I just saw a comment to add below line too in properties file,
logging.level.org.springframework.security.web.csrf.CsrfFilter=DEBUG

Hope this works. I'm trying now.

[Bharghav1]

I still couldn't see the below trace, @marcusdacoregio could you please guide to what I should do to see similar trace like below?

DEBUG 19462 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy : Securing POST /
DEBUG 19462 --- [nio-8080-exec-1] s.s.w.c.SecurityContextPersistenceFilter : Set SecurityContextHolder to empty SecurityContext
DEBUG 19462 --- [nio-8080-exec-1] o.s.security.web.csrf.CsrfFilter : Invalid CSRF token found for http://localhost:8080/
DEBUG 19462 --- [nio-8080-exec-1] o.s.s.w.access.AccessDeniedHandlerImpl : Responding with 403 status code

[marcusdacoregio]

What version of Spring Security are you using? Those logs are available from version 5.4 onwards.
If you can provide a minimal, reproducible sample it would be helpful in order to provide some guidance.

[Bharghav1]

Version 5.6.1, actually its s huge codebase, all I am trying to view the logs when a 403 error is generated for a failed crsf token validation. I tried all the patterns for application.properties but couldnt get a trace like above.

This is what I am using in the application.properties file,

log4j.logger.org.springframework.security=DEBUG
logging.level.org.springframework.security=DEBUG
logging.level.org.springframework.web=DEBUG
logging.level.org.springframework.security.web.FilterChainProxy=DEBUG
logging.level.org.springframework.web.FilterChainProxy=DEBUG
logging.level.org.springframework.security.web.csrf.CsrfFilter=DEBUG

[marcusdacoregio]

Without a sample, it's hard to know what is really happening. The best way to know if the logs are being generated is to put a breakpoint here and check if the code is executed.

[Bharghav1]

Hi @marcusdacoregio I figured a way via log4j properties file, it was not working via application.properties file but through log4j properties file it's working.

[marcusdacoregio]

I'm glad that you found a solution!