nothing logged when OAuth2 connection fails

[hauntingEcho]

Summary

No message is logged when an OIDC session fails to connect to the identity provider after a token is provided. This is likely a specific instance of #5262

Actual Behavior

trying to debug an OpenID-Connect application, I was receiving no hints until I added -Djavax.net.debug=all to read the communication between my application & the OIDC provider. My application was receiving a 401 response with:

{"error_description":"Client Authentication failed","error":"invalid_client"}

However, I was receiving no logging from Spring-Security, and my only hint on the frontend was a redirect loop (OIDC provider -> oauth consumer -> oauth error). The error page I was being brought to was /oauth2/authorization/wso2?error, with no value on the error parameter.

Expected Behavior

a message is logged when communication with the OAuth provider fails

Configuration

application.properties:

# Spring Security 5 property format
spring.security.oauth2.client.registration.wso2.client-id= # removed
spring.security.oauth2.client.registration.wso2.client-secret= # removed - was wrong
spring.security.oauth2.client.registration.wso2.client-name= # removed
spring.security.oauth2.client.registration.wso2.provider=wso2
# Note well:  The scope list MUST be separated by commas.  There are multiple uses for this and some will work
# if you use spaces but others will fail in significant ways (like bypassing OIDC support and using OAuth2).
spring.security.oauth2.client.registration.wso2.scope=openid,email,phone
spring.security.oauth2.client.registration.wso2.redirect-uri-template=${my_url}/login/oauth2/code/wso2
spring.security.oauth2.client.registration.wso2.client-authentication-method=basic
spring.security.oauth2.client.registration.wso2.authorization-grant-type=authorization_code

wso2.baseUrl =  # removed
wso2.issuer = ${wso2.baseUrl}/oauth2/token
wso2.logout = ${wso2.baseUrl}/oidc/logout
wso2.dashboard = ${wso2.baseUrl}/dashboard
spring.security.oauth2.client.provider.wso2.authorization-uri=${wso2.baseUrl}/oauth2/authorize
spring.security.oauth2.client.provider.wso2.token-uri=${wso2.issuer}
spring.security.oauth2.client.provider.wso2.user-info-uri=${wso2.baseUrl}/oauth2/userinfo
spring.security.oauth2.client.provider.wso2.jwk-set-uri=${wso2.baseUrl}/oauth2/jwks
spring.security.oauth2.client.provider.wso2.user-name-attribute=sub

#current property format
oidc.logout.url = ${wso2.logout}

# other
idp.dashboard = ${wso2.dashboard}
my_url =  # removed

#spring.datasource.testWhileIdle = true
spring.datasource.driver-class-name=com.mysql.cj.jdbc.Driver
spring.jpa.show-sql = false
spring.jpa.properties.hibernate.show_sql = false
spring.jpa.hibernate.ddl-auto = update
spring.jpa.properties.hibernate.dialect = org.hibernate.dialect.MySQL5Dialect

#Because without these properties, Spring will convert camelCase to snakecase and mess with the database
spring.jpa.hibernate.naming.implicit-strategy=org.hibernate.boot.model.naming.ImplicitNamingStrategyLegacyJpaImpl
spring.jpa.hibernate.naming.physical-strategy=org.hibernate.boot.model.naming.PhysicalNamingStrategyStandardImpl

#Hikari specific
spring.datasource.hikari.pool-name=SpringBootHikariCP
spring.datasource.hikari.connection-timeout=60000
spring.datasource.hikari.maximum-pool-size=5
spring.datasource.hikari.connection-test-query=SELECT 1

# TODO: Not sure this is the most correct mechanism but using this for now.
# Any login page in WebSecurityConfigurer will override the auto-generated page
# and this one takes us directly to the login page.
login_page=/oauth2/authorization/wso2

WebSecurityConfigurerAdapter:

@Configuration
@Slf4j
@EnableGlobalMethodSecurity(prePostEnabled = true)
class WebSecurityConfigurer extends WebSecurityConfigurerAdapter {

  private final UserService userService;
  private final SessionRegistry sessionRegistry;
  private final AjaxTimeoutRedirectFilter ajaxTimeoutRedirectFilter;
  private final String loginPage;
  private final String oidcLogoutUrl;
  private final String logoutSuccessUrl;

  @Inject
  public WebSecurityConfigurer(
      final UserService userService,
      final SessionRegistry sessionRegistry,
      final AjaxTimeoutRedirectFilter ajaxTimeoutRedirectFilter,
      @Value("${login_page}") final String loginPage,
      @Value("${oidc.logout.url}") final String oidcLogoutUrl,
      @Value("${logout.success.url:/}") final String logoutSuccessUrl
  ) {
    this.userService = userService;
    this.sessionRegistry = sessionRegistry;
    this.ajaxTimeoutRedirectFilter = ajaxTimeoutRedirectFilter;
    this.loginPage = loginPage;
    this.oidcLogoutUrl = oidcLogoutUrl;
    this.logoutSuccessUrl = logoutSuccessUrl;
  }

  @Override
  public void configure(final WebSecurity web) {
    web.ignoring()
        .antMatchers("/css/**")
        .antMatchers("/images/**")
        .antMatchers("/js/**")
        .antMatchers("/resources/**")
        .antMatchers("/webjars/**")
    ;
  }

  @Override
  protected void configure(HttpSecurity http) throws Exception {
    http
        .addFilterAfter(ajaxTimeoutRedirectFilter, ExceptionTranslationFilter.class) // return 401 when attempting unauthenticated AJAX
        .logout().logoutSuccessHandler(oidcLogoutRedirectHandler()).permitAll()  // should go away with support in spring-security 5.2
        .and()
        .authorizeRequests()
          .antMatchers("/removed1.html").hasRole("removed1")
          .antMatchers("/removed2.html").hasRole("removed2")
          .anyRequest().authenticated() // functional controllers responsible for their own authorization
        .and()
        .oauth2Login()
          .loginPage(loginPage) // only one identity provider should be configured - just go directly there
          .userInfoEndpoint().oidcUserService(userService) // add internal numeric user ID which maps to incoming subject
        .and().and()
        .sessionManagement().maximumSessions(1).sessionRegistry(sessionRegistry) // allows session-killing to refresh authorization grants when they change
        .expiredSessionStrategy(new CallFailureSessionInformationExpiredStrategy(loginPage)); // on expired sessions: redirect synchronous requests, 401 async requests
  }

  /**
   * Returns a logout success handler that redirects the user to the OIDC logout page for the IdP, which will THEN
   * send them to the logout success URL.  This is to force the IdP session to be logged out.
   *
   * @return logout handler created
   */
  protected LogoutSuccessHandler oidcLogoutRedirectHandler() {
    return new SimpleUrlLogoutSuccessHandler() {
      @Override
      public void onLogoutSuccess(HttpServletRequest request, HttpServletResponse response,
          Authentication authentication) throws IOException {

        try {
          User user = (User) authentication.getPrincipal();

          // Post logout URI needs to be absolute so use request as the source for this server/host/port.
          URI requestUrl = new URI(request.getRequestURL().toString());
          URI postLogoutRedirectUri = new URI(requestUrl.getScheme(), requestUrl.getUserInfo(), requestUrl.getHost(),
              requestUrl.getPort(), logoutSuccessUrl, null, null);

          String url = oidcLogoutUrl
              + "?id_token_hint=" + user.getIdToken().getTokenValue()
              + "&post_logout_redirect_uri=" + postLogoutRedirectUri.toString();
          response.sendRedirect(url);
        } catch (URISyntaxException x) {
          log.error("Invalid URL in logout success handler (IdP session not logged out)", x);
          response.sendError(SC_INTERNAL_SERVER_ERROR);
        }
      }
    };
  }
}

Version

5.1.5-RELEASE

[pthorson]

If you configure a custom .failureHandler you might be able to get the error message (and prevent the loop).

Something simple like this will spit out the error messages anyway

        .oauth2Login()
            .loginPage(loginPage) // should send us directly to oidc login
            .successHandler(customSuccessHandler())
            .failureHandler(new CustomAuthenticationFailureHandler())
            .tokenEndpoint()

...

public class CustomAuthenticationFailureHandler implements AuthenticationFailureHandler {

    @Override
    public void onAuthenticationFailure(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, AuthenticationException e) throws IOException, ServletException {
        httpServletResponse.setStatus(HttpStatus.UNAUTHORIZED.value());

        String jsonPayload = "{\"message\" : \"%s\", \"timestamp\" : \"%s\" }";
        httpServletResponse.getOutputStream().println(String.format(jsonPayload, e.getMessage(), Calendar.getInstance().getTime()));
    }
}

EDIT: In case someone finds this while searching. Above is just meant for debugging in development. Do NOT write out security exceptions to the user.

[jgrandja]

@hauntingEcho This is a duplicate of #5262. As the ticket indicates, we need to add logging in the oauth2 modules as logging is non-existent at the moment. We're trying to get to this but there are other higher priority items we need to add into the upcoming 5.2 release. I'm going to close this issue and please keep track of #5262.