Grails 3.2.5 REST security plugin, Bearer tokens. This started because the custom AuthenticationSuccessListener is getting hit twice for every request, authenticating via a valid token. Debug shows the FilterChainProxy processing to start with, doing the token validation/authentication. Then, after the filter chain is done it starts in all over again. The difference is that the second time through it ends up calling the GrailsDispatcherServlet to actually process the request.
Do I have filters configured wrong? How can I prevent the double-hit on authentication?
Here is most of the debug log:
2018-05-15 14:12:52,240 DEBUG org.grails.web.servlet.mvc.GrailsWebRequestFilter - Bound Grails request context to thread: org.grails.web.filters.HiddenHttpMethodFilter$HttpMethodRequestWrapper@8e95813
2018-05-15 14:12:52,241 DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher - Request '/picklists' matched by universal pattern '/**'
2018-05-15 14:12:52,241 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 1 of 10 in additional filter chain; firing Filter: 'SecurityRequestHolderFilter'
2018-05-15 14:12:52,241 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 2 of 10 in additional filter chain; firing Filter: 'RestLogoutFilter'
2018-05-15 14:12:52,241 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 3 of 10 in additional filter chain; firing Filter: 'MutableLogoutFilter'
2018-05-15 14:12:52,241 DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/picklists'; against '/logoff'
2018-05-15 14:12:52,241 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 4 of 10 in additional filter chain; firing Filter: 'X509AuthenticationFilter'
2018-05-15 14:12:52,242 DEBUG org.springframework.security.web.authentication.preauth.x509.X509AuthenticationFilter - Checking secure context token: null
2018-05-15 14:12:52,242 DEBUG org.springframework.security.web.authentication.preauth.x509.X509AuthenticationFilter - No client certificate found in request.
2018-05-15 14:12:52,242 DEBUG org.springframework.security.web.authentication.preauth.x509.X509AuthenticationFilter - No client certificate found in request.
2018-05-15 14:12:52,242 DEBUG org.springframework.security.web.authentication.preauth.x509.X509AuthenticationFilter - No pre-authenticated principal found in request
2018-05-15 14:12:52,242 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 5 of 10 in additional filter chain; firing Filter: 'RestAuthenticationFilter'
2018-05-15 14:12:52,242 DEBUG grails.plugin.springsecurity.rest.RestAuthenticationFilter - Actual URI is /picklists; endpoint URL is /login
2018-05-15 14:12:52,242 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 6 of 10 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
2018-05-15 14:12:52,242 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 7 of 10 in additional filter chain; firing Filter: 'GrailsAnonymousAuthenticationFilter'
2018-05-15 14:12:52,242 DEBUG grails.plugin.springsecurity.web.filter.GrailsAnonymousAuthenticationFilter - Populated SecurityContextHolder with anonymous token: 'grails.plugin.springsecurity.authentication.GrailsAnonymousAuthenticationToken@dc6bc2c: Principal: org.springframework.security.core.userdetails.User@dc730200: Username: __grails.anonymous.user__; Password: [PROTECTED]; Enabled: false; AccountNonExpired: false; credentialsNonExpired: false; AccountNonLocked: false; Granted Authorities: ROLE_ANONYMOUS; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@21a2c: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 67230647BB61B7D23EDDA393E83F19B9; Granted Authorities: ROLE_ANONYMOUS'
2018-05-15 14:12:52,242 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 8 of 10 in additional filter chain; firing Filter: 'RestTokenValidationFilter'
2018-05-15 14:12:52,242 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Looking for bearer token in Authorization header, query string or Form-Encoded body parameter
2018-05-15 14:12:52,242 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Found bearer token in Authorization header
2018-05-15 14:12:52,242 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Token: 2u2rbakp0d5rn45i1p5hlb9n9dhbllvq
2018-05-15 14:12:52,242 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Token found: 2u2rbakp0d5rn45i1p5hlb9n9dhbllvq
2018-05-15 14:12:52,242 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Trying to authenticate the token
2018-05-15 14:12:52,244 DEBUG grails.plugin.springsecurity.rest.RestAuthenticationProvider - Use JWT: false
2018-05-15 14:12:52,245 DEBUG grails.plugin.springsecurity.rest.RestAuthenticationProvider - Trying to validate token 2u2rbakp0d5rn45i1p5hlb9n9dhbllvq
2018-05-15 14:12:52,245 DEBUG grails.plugin.springsecurity.rest.RestAuthenticationProvider - Authentication result: grails.plugin.springsecurity.rest.token.AccessToken(accessToken:2u2rbakp0d5rn45i1p5hlb9n9dhbllvq, expiration:null, refreshToken:null, principal:com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER, super:grails.plugin.springsecurity.rest.token.AccessToken@b349335e: Principal: com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: ROLE_CAN_ADJUDICATE, ROLE_CAN_ADMINISTER_PICKLISTS, ROLE_CAN_ADMINISTER_ROLES, ROLE_CAN_ADMINISTER_USERS, ROLE_CAN_CHANGE_USERS, ROLE_CAN_CREATE_ASSIGNMENTS, ROLE_CAN_CREATE_NOTIFICATIONS, ROLE_CAN_CREATE_ROLES, ROLE_CAN_CREATE_USERS, ROLE_CAN_DELETE_ROLES, ROLE_CAN_DELETE_USERS, ROLE_CAN_EDIT_ASSIGNMENTS, ROLE_CAN_EDIT_USERS, ROLE_CAN_SHOW_USERS, ROLE_CAN_SWITCH_USERS, ROLE_CAN_VIEW_ASSIGNMENTS, ROLE_CAN_VIEW_ROLES, ROLE_CAN_VIEW_USERS, ROLE_COMMENTER, ROLE_LEAD_AGENT, ROLE_SYS_ADMIN, ROLE_USER)
2018-05-15 14:12:52,245 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Token authenticated. Storing the authentication result in the security context
2018-05-15 14:12:52,246 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Authentication result: grails.plugin.springsecurity.rest.token.AccessToken(accessToken:2u2rbakp0d5rn45i1p5hlb9n9dhbllvq, expiration:null, refreshToken:null, principal:com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER, super:grails.plugin.springsecurity.rest.token.AccessToken@b349335e: Principal: com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: ROLE_CAN_ADJUDICATE, ROLE_CAN_ADMINISTER_PICKLISTS, ROLE_CAN_ADMINISTER_ROLES, ROLE_CAN_ADMINISTER_USERS, ROLE_CAN_CHANGE_USERS, ROLE_CAN_CREATE_ASSIGNMENTS, ROLE_CAN_CREATE_NOTIFICATIONS, ROLE_CAN_CREATE_ROLES, ROLE_CAN_CREATE_USERS, ROLE_CAN_DELETE_ROLES, ROLE_CAN_DELETE_USERS, ROLE_CAN_EDIT_ASSIGNMENTS, ROLE_CAN_EDIT_USERS, ROLE_CAN_SHOW_USERS, ROLE_CAN_SWITCH_USERS, ROLE_CAN_VIEW_ASSIGNMENTS, ROLE_CAN_VIEW_ROLES, ROLE_CAN_VIEW_USERS, ROLE_COMMENTER, ROLE_LEAD_AGENT, ROLE_SYS_ADMIN, ROLE_USER)
2018-05-15 14:12:52,249 DEBUG org.springframework.boot.actuate.audit.listener.AuditListener - AuditEvent [timestamp=Tue May 15 14:12:52 EDT 2018, principal=admin, type=AUTHENTICATION_SUCCESS, data={}]
2018-05-15 14:12:52,252 DEBUG com.penbaymedia.jdeis5.security.AuthenticationSuccessListener - In AuthenticationSuccessListener
2018-05-15 14:12:52,254 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Looking for bearer token in Authorization header, query string or Form-Encoded body parameter
2018-05-15 14:12:52,254 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Found bearer token in Authorization header
2018-05-15 14:12:52,254 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Token: 2u2rbakp0d5rn45i1p5hlb9n9dhbllvq
2018-05-15 14:12:52,255 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Continuing the filter chain
2018-05-15 14:12:52,255 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 9 of 10 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
2018-05-15 14:12:52,255 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 10 of 10 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
2018-05-15 14:12:52,264 DEBUG org.springframework.security.web.access.intercept.FilterSecurityInterceptor - Public object - authentication not attempted
2018-05-15 14:12:52,265 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name reached end of additional filter chain; proceeding with original chain
2018-05-15 14:12:52,265 DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher - Request '/picklists' matched by universal pattern '/**'
2018-05-15 14:12:52,266 INFO grails.plugin.springsecurity.web.filter.DebugFilter -
************************************************************
Request received for '/picklists?sortFieldName=name':
SecurityContextHolderAwareRequestWrapper[ FirewalledRequest[ org.grails.web.filters.HiddenHttpMethodFilter$HttpMethodRequestWrapper@8e95813]]
servletPath:/picklists
pathInfo:null
Security filter chain: [
SecurityRequestHolderFilter
RestLogoutFilter
MutableLogoutFilter
X509AuthenticationFilter
RestAuthenticationFilter
SecurityContextHolderAwareRequestFilter
GrailsAnonymousAuthenticationFilter
RestTokenValidationFilter
ExceptionTranslationFilter
FilterSecurityInterceptor
]
************************************************************
2018-05-15 14:12:52,266 DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher - Request '/picklists' matched by universal pattern '/**'
2018-05-15 14:12:52,266 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 1 of 10 in additional filter chain; firing Filter: 'SecurityRequestHolderFilter'
2018-05-15 14:12:52,266 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 2 of 10 in additional filter chain; firing Filter: 'RestLogoutFilter'
2018-05-15 14:12:52,266 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 3 of 10 in additional filter chain; firing Filter: 'MutableLogoutFilter'
2018-05-15 14:12:52,266 DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/picklists'; against '/logoff'
2018-05-15 14:12:52,266 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 4 of 10 in additional filter chain; firing Filter: 'X509AuthenticationFilter'
2018-05-15 14:12:52,266 DEBUG org.springframework.security.web.authentication.preauth.x509.X509AuthenticationFilter - Checking secure context token: grails.plugin.springsecurity.rest.token.AccessToken(accessToken:2u2rbakp0d5rn45i1p5hlb9n9dhbllvq, expiration:null, refreshToken:null, principal:com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER, super:grails.plugin.springsecurity.rest.token.AccessToken@b349335e: Principal: com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: ROLE_CAN_ADJUDICATE, ROLE_CAN_ADMINISTER_PICKLISTS, ROLE_CAN_ADMINISTER_ROLES, ROLE_CAN_ADMINISTER_USERS, ROLE_CAN_CHANGE_USERS, ROLE_CAN_CREATE_ASSIGNMENTS, ROLE_CAN_CREATE_NOTIFICATIONS, ROLE_CAN_CREATE_ROLES, ROLE_CAN_CREATE_USERS, ROLE_CAN_DELETE_ROLES, ROLE_CAN_DELETE_USERS, ROLE_CAN_EDIT_ASSIGNMENTS, ROLE_CAN_EDIT_USERS, ROLE_CAN_SHOW_USERS, ROLE_CAN_SWITCH_USERS, ROLE_CAN_VIEW_ASSIGNMENTS, ROLE_CAN_VIEW_ROLES, ROLE_CAN_VIEW_USERS, ROLE_COMMENTER, ROLE_LEAD_AGENT, ROLE_SYS_ADMIN, ROLE_USER)
2018-05-15 14:12:52,266 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 5 of 10 in additional filter chain; firing Filter: 'RestAuthenticationFilter'
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.rest.RestAuthenticationFilter - Actual URI is /picklists; endpoint URL is /login
2018-05-15 14:12:52,267 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 6 of 10 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
2018-05-15 14:12:52,267 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 7 of 10 in additional filter chain; firing Filter: 'GrailsAnonymousAuthenticationFilter'
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.web.filter.GrailsAnonymousAuthenticationFilter - SecurityContextHolder not populated with anonymous token, as it already contained: 'grails.plugin.springsecurity.rest.token.AccessToken(accessToken:2u2rbakp0d5rn45i1p5hlb9n9dhbllvq, expiration:null, refreshToken:null, principal:com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER, super:grails.plugin.springsecurity.rest.token.AccessToken@b349335e: Principal: com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: ROLE_CAN_ADJUDICATE, ROLE_CAN_ADMINISTER_PICKLISTS, ROLE_CAN_ADMINISTER_ROLES, ROLE_CAN_ADMINISTER_USERS, ROLE_CAN_CHANGE_USERS, ROLE_CAN_CREATE_ASSIGNMENTS, ROLE_CAN_CREATE_NOTIFICATIONS, ROLE_CAN_CREATE_ROLES, ROLE_CAN_CREATE_USERS, ROLE_CAN_DELETE_ROLES, ROLE_CAN_DELETE_USERS, ROLE_CAN_EDIT_ASSIGNMENTS, ROLE_CAN_EDIT_USERS, ROLE_CAN_SHOW_USERS, ROLE_CAN_SWITCH_USERS, ROLE_CAN_VIEW_ASSIGNMENTS, ROLE_CAN_VIEW_ROLES, ROLE_CAN_VIEW_USERS, ROLE_COMMENTER, ROLE_LEAD_AGENT, ROLE_SYS_ADMIN, ROLE_USER)'
2018-05-15 14:12:52,267 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 8 of 10 in additional filter chain; firing Filter: 'RestTokenValidationFilter'
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Looking for bearer token in Authorization header, query string or Form-Encoded body parameter
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Found bearer token in Authorization header
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Token: 2u2rbakp0d5rn45i1p5hlb9n9dhbllvq
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Token found: 2u2rbakp0d5rn45i1p5hlb9n9dhbllvq
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Trying to authenticate the token
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.rest.RestAuthenticationProvider - Use JWT: false
2018-05-15 14:12:52,267 DEBUG grails.plugin.springsecurity.rest.RestAuthenticationProvider - Trying to validate token 2u2rbakp0d5rn45i1p5hlb9n9dhbllvq
2018-05-15 14:12:52,268 DEBUG grails.plugin.springsecurity.rest.RestAuthenticationProvider - Authentication result: grails.plugin.springsecurity.rest.token.AccessToken(accessToken:2u2rbakp0d5rn45i1p5hlb9n9dhbllvq, expiration:null, refreshToken:null, principal:com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER, super:grails.plugin.springsecurity.rest.token.AccessToken@b349335e: Principal: com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: ROLE_CAN_ADJUDICATE, ROLE_CAN_ADMINISTER_PICKLISTS, ROLE_CAN_ADMINISTER_ROLES, ROLE_CAN_ADMINISTER_USERS, ROLE_CAN_CHANGE_USERS, ROLE_CAN_CREATE_ASSIGNMENTS, ROLE_CAN_CREATE_NOTIFICATIONS, ROLE_CAN_CREATE_ROLES, ROLE_CAN_CREATE_USERS, ROLE_CAN_DELETE_ROLES, ROLE_CAN_DELETE_USERS, ROLE_CAN_EDIT_ASSIGNMENTS, ROLE_CAN_EDIT_USERS, ROLE_CAN_SHOW_USERS, ROLE_CAN_SWITCH_USERS, ROLE_CAN_VIEW_ASSIGNMENTS, ROLE_CAN_VIEW_ROLES, ROLE_CAN_VIEW_USERS, ROLE_COMMENTER, ROLE_LEAD_AGENT, ROLE_SYS_ADMIN, ROLE_USER)
2018-05-15 14:12:52,268 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Token authenticated. Storing the authentication result in the security context
2018-05-15 14:12:52,268 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Authentication result: grails.plugin.springsecurity.rest.token.AccessToken(accessToken:2u2rbakp0d5rn45i1p5hlb9n9dhbllvq, expiration:null, refreshToken:null, principal:com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER, super:grails.plugin.springsecurity.rest.token.AccessToken@b349335e: Principal: com.penbaymedia.jdeis5.security.JdeisUserDetails@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_CAN_ADJUDICATE,ROLE_CAN_ADMINISTER_PICKLISTS,ROLE_CAN_ADMINISTER_ROLES,ROLE_CAN_ADMINISTER_USERS,ROLE_CAN_CHANGE_USERS,ROLE_CAN_CREATE_ASSIGNMENTS,ROLE_CAN_CREATE_NOTIFICATIONS,ROLE_CAN_CREATE_ROLES,ROLE_CAN_CREATE_USERS,ROLE_CAN_DELETE_ROLES,ROLE_CAN_DELETE_USERS,ROLE_CAN_EDIT_ASSIGNMENTS,ROLE_CAN_EDIT_USERS,ROLE_CAN_SHOW_USERS,ROLE_CAN_SWITCH_USERS,ROLE_CAN_VIEW_ASSIGNMENTS,ROLE_CAN_VIEW_ROLES,ROLE_CAN_VIEW_USERS,ROLE_COMMENTER,ROLE_LEAD_AGENT,ROLE_SYS_ADMIN,ROLE_USER; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: ROLE_CAN_ADJUDICATE, ROLE_CAN_ADMINISTER_PICKLISTS, ROLE_CAN_ADMINISTER_ROLES, ROLE_CAN_ADMINISTER_USERS, ROLE_CAN_CHANGE_USERS, ROLE_CAN_CREATE_ASSIGNMENTS, ROLE_CAN_CREATE_NOTIFICATIONS, ROLE_CAN_CREATE_ROLES, ROLE_CAN_CREATE_USERS, ROLE_CAN_DELETE_ROLES, ROLE_CAN_DELETE_USERS, ROLE_CAN_EDIT_ASSIGNMENTS, ROLE_CAN_EDIT_USERS, ROLE_CAN_SHOW_USERS, ROLE_CAN_SWITCH_USERS, ROLE_CAN_VIEW_ASSIGNMENTS, ROLE_CAN_VIEW_ROLES, ROLE_CAN_VIEW_USERS, ROLE_COMMENTER, ROLE_LEAD_AGENT, ROLE_SYS_ADMIN, ROLE_USER)
2018-05-15 14:12:52,269 DEBUG org.springframework.boot.actuate.audit.listener.AuditListener - AuditEvent [timestamp=Tue May 15 14:12:52 EDT 2018, principal=admin, type=AUTHENTICATION_SUCCESS, data={}]
2018-05-15 14:12:52,269 DEBUG com.penbaymedia.jdeis5.security.AuthenticationSuccessListener - In AuthenticationSuccessListener
2018-05-15 14:12:52,269 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Looking for bearer token in Authorization header, query string or Form-Encoded body parameter
2018-05-15 14:12:52,269 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Found bearer token in Authorization header
2018-05-15 14:12:52,269 DEBUG grails.plugin.springsecurity.rest.token.bearer.BearerTokenReader - Token: 2u2rbakp0d5rn45i1p5hlb9n9dhbllvq
2018-05-15 14:12:52,269 DEBUG grails.plugin.springsecurity.rest.RestTokenValidationFilter - Continuing the filter chain
2018-05-15 14:12:52,269 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 9 of 10 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
2018-05-15 14:12:52,269 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name at position 10 of 10 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
2018-05-15 14:12:52,269 DEBUG org.springframework.security.web.FilterChainProxy - /picklists?sortFieldName=name reached end of additional filter chain; proceeding with original chain
2018-05-15 14:12:52,269 DEBUG org.grails.web.servlet.mvc.GrailsDispatcherServlet - DispatcherServlet with name 'grailsDispatcherServlet' processing GET request for [/picklists]
The log continues on with the request being processed by the application controller and returning the result.
Oh, here is the filter chain spec:
filterChain.chainMap:
- { pattern: '/**', filters: 'JOINED_FILTERS,-exceptionTranslationFilter,-authenticationProcessingFilter,-securityContextPersistenceFilter,-rememberMeAuthenticationFilter'}
From what I can glean from the debug trace, the RestTokenValidationFilter validates the request token and sets
SecurityContextHolder.context.setAuthentication(accessToken)
authenticationEventPublisher.publishAuthenticationSuccess(accessToken)
Then the filter chain completes and we drop into the actual request handling, where again in the filter chain the RestTokenValidationFilter is invoked and the same authentication happens all over again. What is supposed to happen to avoid this redundant processing?
This symptom is caused by "grails.plugin.springsecurity.web.filter.DebugFilter", which wraps the HTTP request, effectively re-issuing it. However, the debug filter is located below the FilterChainProxy filter (at least in my setup), so the FilterChainProxy was being executed twice. Note that this only affects my debug environment, in which the debug filter is enabled/disabled via the "grails.plugin.springsecurity.debug.useFilter" setting. So, not an issue.