Tomcat 9 and Spring Security redirecting to login page after successful authentication

Question

Background:

We are using

Spring Version 5.3.2 Spring Security Version 5.4.1 Spring data 2.4.1 jstl 1.2 Servlet 3.1.0

Trying to Migrate from Weblogic to Apache Tomcat (TomEE)/9.0.71 (8.0.14). We have Custom Authentication, AuthenticationFilter extends UsernamePasswordAuthenticationFilter (code below).

Issue: These configurations works fine in Weblogic. Migrating to TomEE with the below configuration is authenticating successfully and invokes LoginSuccessHandler (custom class to insert data to a table) as well and setting the securityContext (can see the logs below). While redirecting to dashboard (the next page after success login) after success login I see from the logs it's showing as Anonymous user at some point and SecurityContextRepository not setting the SPRING_SECURITY_CONTEXT and redirects back to the login page instead of dashboard.

In the server logs I see 302 status code for /app/app_security_check and /app/login/dashboard Logs: Line 4 in logs (logs below enclosed in **) shows successfulAuthentication and line 44 (enclosed in **) shows Stored SecurityContext.

Can anybody please help me why the securityContext is null in Tomcat? Does Tomcat needs any configuration to hold the context?

---

web.xml

<listener>
    <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
</listener>

<context-param>
    <param-name>contextConfigLocation</param-name>
    <param-value>  /WEB-INF/spring-security.xml,   /WEB-INF/applicationContext.xml</param-value>   
</context-param>
<servlet>
    <servlet-name>dispatcher</servlet-name>
    <servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class> 
    <load-on-startup>1</load-on-startup>
    <async-supported>true</async-supported>
</servlet>
<servlet-mapping>
    <servlet-name>dispatcher</servlet-name>
    <url-pattern>/</url-pattern>
</servlet-mapping>
<filter>
    <filter-name>springSecurityFilterChain</filter-name>
    <filter-class>org.springframework.web.filter.DelegatingFilterProxy</filter-class>
    <async-supported>true</async-supported>
</filter>
<filter-mapping>
    <filter-name>springSecurityFilterChain</filter-name>
    <url-pattern>/*</url-pattern>
    <dispatcher>REQUEST</dispatcher>
    <dispatcher>ASYNC</dispatcher>
</filter-mapping> 
<filter>
    <filter-name>ActiveCustomFilter</filter-name>
    <filter-class>.......ActiveCustomFilter</filter-class>
</filter>
<filter-mapping>
    <filter-name>ActiveCustomFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>
<session-config>
    <session-timeout>60</session-timeout>
</session-config>
<listener>
    <listener-class>org.springframework.security.web.session.HttpSessionEventPublisher</listener-class>
</listener>

---

Logs: 
 
2023-04-04T09:36:31.605-0400 [test.login.service.UserLoginService] [loadUserByUsername] [128] INFO :::Returning user: test.login.service.CustomUserDetails@afbd74f0
2023-04-04T09:36:31.805-0400 [org.springframework.security.authentication.dao.AbstractUserDetailsAuthenticationProvider] [createSuccessAuthentication] [199] DEBUG :::Authenticated user
2023-04-04T09:36:31.805-0400 [org.springframework.security.web.session.HttpSessionEventPublisher] [extracted] [85] DEBUG :::Publishing event: org.springframework.security.web.session.HttpSessionCreatedEvent[source=org.apache.catalina.session.StandardSessionFacade@7b246da]
**2023-04-04T09:36:31.805-0400 [org.springframework.security.core.session.SessionRegistryImpl] [registerNewSession] [136] DEBUG :::Registering session 935153B9FF5E463D3377915F17389702, for principal test.login.service.CustomUserDetails@afbd74f0
2023-04-04T09:36:31.805-0400 [org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter] [successfulAuthentication] [315] DEBUG :::Set SecurityContextHolder to UsernamePasswordAuthenticationToken [Principal=test.login.service.CustomUserDetails@afbd74f0, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=127.0.0.1, SessionId=null], Granted Authorities=[ADD_MODIFY, REPORTS_RUN, .......................]]** 
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [postLoginProcess] [87] INFO :::About to call printAllHttpHeaders method
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [115] INFO :::*******************************
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [116] INFO :::Enter printAllHttpHeaders method
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [120] INFO :::header name:accept
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [121] INFO :::header value:text/plain, */*
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [120] INFO :::header name:content-type
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [121] INFO :::header value:application/x-www-form-urlencoded;charset=UTF-8
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [120] INFO :::header name:content-length
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [121] INFO :::header value:115
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [120] INFO :::header name:host
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [121] INFO :::header value:localhost:11003
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [120] INFO :::header name:connection
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [121] INFO :::header value:Keep-Alive
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [120] INFO :::header name:user-agent
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [121] INFO :::header value:Apache-HttpClient/4.5.13 (Java/11.0.8)
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [120] INFO :::header name:accept-encoding
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [121] INFO :::header value:gzip,deflate
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [123] INFO :::Iterating over header names done
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [124] INFO :::Exit printAllHttpHeaders method
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [printAllHttpHeaders] [125] INFO :::*******************************
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [postLoginProcess] [97] INFO :::Logged in user id: testUser, profile id: 1111
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [postLoginProcess] [100] INFO :::X-FORWARDED-FOR ipaddr:null
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [postLoginProcess] [105] INFO :::request.getParameter(ipAddr):0:0:0:0:0:0:0:1
2023-04-04T09:36:31.805-0400 [test.login.handler.LoginSuccessHandler] [postLoginProcess] [106] INFO :::request.getRemoteAddr():127.0.0.1
2023-04-04T09:36:31.816-0400 [test.login.handler.LoginSuccessHandler] [postLoginProcess] [107] INFO :::About to save to db, ipaddrL:0:0:0:0:0:0:0:1
2023-04-04T09:36:31.816-0400 [org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler] [invoke] [302] DEBUG :::Creating new EntityManager for shared EntityManager invocation
2023-04-04T09:36:31.880-0400 [org.springframework.transaction.support.AbstractPlatformTransactionManager] [getTransaction] [370] DEBUG :::Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.saveAll]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2023-04-04T09:36:31.880-0400 [org.springframework.orm.jpa.JpaTransactionManager] [doBegin] [412] DEBUG :::Opened new EntityManager [org.eclipse.persistence.internal.jpa.EntityManagerImpl@30b2560f] for JPA transaction
2023-04-04T09:36:31.880-0400 [org.springframework.orm.jpa.JpaTransactionManager] [doBegin] [447] DEBUG :::Not exposing JPA transaction [org.eclipse.persistence.internal.jpa.EntityManagerImpl@30b2560f] as JDBC transaction because JpaDialect [org.springframework.orm.jpa.DefaultJpaDialect@2b5122f8] does not support JDBC Connection retrieval
2023-04-04T09:36:31.927-0400 [org.springframework.transaction.support.AbstractPlatformTransactionManager] [processCommit] [740] DEBUG :::Initiating transaction commit
2023-04-04T09:36:31.927-0400 [org.springframework.orm.jpa.JpaTransactionManager] [doCommit] [557] DEBUG :::Committing JPA transaction on EntityManager [org.eclipse.persistence.internal.jpa.EntityManagerImpl@30b2560f]
2023-04-04T09:36:31.990-0400 [org.springframework.orm.jpa.JpaTransactionManager] [doCleanupAfterCompletion] [648] DEBUG :::Closing JPA EntityManager [org.eclipse.persistence.internal.jpa.EntityManagerImpl@30b2560f] after transaction
2023-04-04T09:36:31.990-0400 [org.springframework.transaction.support.AbstractPlatformTransactionManager] [getTransaction] [370] DEBUG :::Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2023-04-04T09:36:31.990-0400 [org.springframework.orm.jpa.JpaTransactionManager] [doBegin] [412] DEBUG :::Opened new EntityManager [org.eclipse.persistence.internal.jpa.EntityManagerImpl@22fe3e74] for JPA transaction
2023-04-04T09:36:31.990-0400 [org.springframework.orm.jpa.JpaTransactionManager] [doBegin] [447] DEBUG :::Not exposing JPA transaction [org.eclipse.persistence.internal.jpa.EntityManagerImpl@22fe3e74] as JDBC transaction because JpaDialect [org.springframework.orm.jpa.DefaultJpaDialect@2b5122f8] does not support JDBC Connection retrieval
2023-04-04T09:36:32.022-0400 [org.springframework.transaction.support.AbstractPlatformTransactionManager] [processCommit] [740] DEBUG :::Initiating transaction commit
2023-04-04T09:36:32.022-0400 [org.springframework.orm.jpa.JpaTransactionManager] [doCommit] [557] DEBUG :::Committing JPA transaction on EntityManager [org.eclipse.persistence.internal.jpa.EntityManagerImpl@22fe3e74]
2023-04-04T09:36:32.052-0400 [org.springframework.orm.jpa.JpaTransactionManager] [doCleanupAfterCompletion] [648] DEBUG :::Closing JPA EntityManager [org.eclipse.persistence.internal.jpa.EntityManagerImpl@22fe3e74] after transaction
2023-04-04T09:36:32.052-0400 [org.springframework.security.web.DefaultRedirectStrategy] [sendRedirect] [57] DEBUG :::Redirecting to /app/
**2023-04-04T09:36:32.052-0400 [org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper] [saveContext] [362] DEBUG :::Stored SecurityContextImpl [Authentication=UsernamePasswordAuthenticationToken [Principal=test.login.service.CustomUserDetails@afbd74f0, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=127.0.0.1, SessionId=null], Granted Authorities=[ADD_MODIFY, REPORTS_RUN, .......................]]] to HttpSession** [org.apache.catalina.session.StandardSessionFacade@7b246da]
2023-04-04T09:36:32.052-0400 [org.springframework.security.web.context.SecurityContextPersistenceFilter] [doFilter] [118] DEBUG :::Cleared SecurityContextHolder to complete request
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "HTTP/1.1 302 [\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Set-Cookie: JSESSIONID=935153B9FF5E463D3377915F17389702; Path=/; HttpOnly[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Cache-Control: no-cache, no-store, max-age=0, must-revalidate[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Pragma: no-cache[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Expires: 0[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "X-XSS-Protection: 1; mode=block[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "X-Frame-Options: DENY[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "X-Content-Type-Options: nosniff[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Location: http://localhost:11003/app/[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Content-Length: 0[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Date: Tue, 04 Apr 2023 13:36:32 GMT[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Keep-Alive: timeout=200[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Connection: keep-alive[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "Server: Apache TomEE[\r][\n]"
2023-04-04T09:36:32.066-0400 [org.apache.http.impl.conn.Wire] [wire] [73] DEBUG :::http-outgoing-0 << "[\r][\n]"
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [122] DEBUG :::http-outgoing-0 << HTTP/1.1 302 
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Set-Cookie: JSESSIONID=935153B9FF5E463D3377915F17389702; Path=/; HttpOnly
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Cache-Control: no-cache, no-store, max-age=0, must-revalidate
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Pragma: no-cache
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Expires: 0
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << X-XSS-Protection: 1; mode=block
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << X-Frame-Options: DENY
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << X-Content-Type-Options: nosniff
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Location: http://localhost:11003/app/
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Content-Length: 0
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Date: Tue, 04 Apr 2023 13:36:32 GMT
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Keep-Alive: timeout=200
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Connection: keep-alive
2023-04-04T09:36:32.082-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [onResponseReceived] [125] DEBUG :::http-outgoing-0 << Server: Apache TomEE
2023-04-04T09:36:32.099-0400 [org.apache.http.impl.execchain.MainClientExec] [execute] [285] DEBUG :::Connection can be kept alive for 200000 MILLISECONDS
2023-04-04T09:36:32.099-0400 [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] [releaseConnection] [344] DEBUG :::Connection [id: 0][route: {}->http://localhost:11003] can be kept alive for 200.0 seconds
2023-04-04T09:36:32.099-0400 [org.apache.http.impl.conn.LoggingManagedHttpClientConnection] [setSocketTimeout] [88] DEBUG :::http-outgoing-0: set socket timeout to 0
2023-04-04T09:36:32.099-0400 [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] [releaseConnection] [351] DEBUG :::Connection released: [id: 0][route: {}->http://localhost:11003][total available: 1; route allocated: 1 of 2; total allocated: 1 of 20]
2023-04-04T09:36:32.105-0400 [org.apache.http.client.protocol.ResponseProcessCookies] [processCookies] [119] DEBUG :::Cookie accepted [JSESSIONID="935153B9FF5E463D3377915F17389702", version:0, domain:localhost, path:/, expiry:null]
2023-04-04T09:36:32.121-0400 [org.springframework.core.log.CompositeLog] [debug] [147] DEBUG :::Response 302 FOUND
2023-04-04T09:36:32.128-0400 [test.login.controller.LoginController] [authenticateWithProfile] [315] INFO :::((((((((((((((((( 935153B9FF5E463D3377915F17389702; Path=/; HttpOnly
2023-04-04T09:36:32.128-0400 [test.login.controller.LoginController] [authenticateWithProfile] [317] INFO :::Exited authenticateWithProfile() of LoginController
2023-04-04T09:36:32.128-0400 [org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor] [writeWithMessageConverters] [255] DEBUG :::Using 'application/json', given [application/json, text/plain, */*] and supported [application/json, application/*+json]
2023-04-04T09:36:32.128-0400 [org.springframework.core.log.LogFormatUtils] [traceDebug] [91] DEBUG :::Writing [test.user.model.CdrUserProfile@20542935]
2023-04-04T09:36:32.128-0400 [org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper] [saveContext] [348] DEBUG :::Did not store anonymous SecurityContext
2023-04-04T09:36:32.128-0400 [org.springframework.web.servlet.FrameworkServlet] [logResult] [1131] DEBUG :::Completed 200 OK
2023-04-04T09:36:32.128-0400 [org.springframework.security.web.context.SecurityContextPersistenceFilter] [doFilter] [118] DEBUG :::Cleared SecurityContextHolder to complete request
2023-04-04T09:36:32.169-0400 [org.springframework.security.web.FilterChainProxy] [doFilterInternal] [208] DEBUG :::Securing GET /login/dashboard
2023-04-04T09:36:32.169-0400 [org.springframework.security.web.context.SecurityContextPersistenceFilter] [doFilter] [102] DEBUG :::Set SecurityContextHolder to empty SecurityContext
2023-04-04T09:36:32.169-0400 [org.springframework.security.web.authentication.AnonymousAuthenticationFilter] [doFilter] [96] DEBUG :::Set SecurityContextHolder to anonymous SecurityContext
2023-04-04T09:36:32.170-0400 [org.springframework.security.access.intercept.AbstractSecurityInterceptor] [attemptAuthorization] [246] DEBUG :::Failed to authorize filter invocation [GET /login/dashboard] with attributes [authenticated]
2023-04-04T09:36:32.192-0400 [org.springframework.security.web.session.HttpSessionEventPublisher] [extracted] [85] DEBUG :::Publishing event: org.springframework.security.web.session.HttpSessionCreatedEvent[source=org.apache.catalina.session.StandardSessionFacade@26a138cc]
2023-04-04T09:36:32.192-0400 [org.springframework.security.web.savedrequest.HttpSessionRequestCache] [saveRequest] [75] DEBUG :::Saved request http://localhost:11003/app/login/dashboard to session
2023-04-04T09:36:32.197-0400 [org.springframework.security.web.DefaultRedirectStrategy] [sendRedirect] [57] DEBUG :::Redirecting to http://localhost:11003/app/login/loginPage
2023-04-04T09:36:32.197-0400 [org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper] [saveContext] [345] DEBUG :::Did not store empty SecurityContext
2023-04-04T09:36:32.198-0400 [org.springframework.security.web.context.SecurityContextPersistenceFilter] [doFilter] [118] DEBUG :::Cleared SecurityContextHolder to complete request
2023-04-04T09:36:32.203-0400 [org.springframework.security.web.FilterChainProxy] [doFilterInternal] [208] DEBUG :::Securing GET /login/loginPage
2023-04-04T09:36:32.203-0400 [org.springframework.security.web.context.SecurityContextPersistenceFilter] [doFilter] [102] DEBUG :::Set SecurityContextHolder to empty SecurityContext
2023-04-04T09:36:32.203-0400 [org.springframework.security.web.authentication.AnonymousAuthenticationFilter] [doFilter] [96] DEBUG :::Set SecurityContextHolder to anonymous SecurityContext
2023-04-04T09:36:32.204-0400 [org.springframework.security.access.intercept.AbstractSecurityInterceptor] [beforeInvocation] [210] DEBUG :::Authorized filter invocation [GET /login/loginPage] with attributes [permitAll]
2023-04-04T09:36:32.204-0400 [org.springframework.security.web.FilterChainProxy$VirtualFilterChain] [doFilter] [323] DEBUG :::Secured GET /login/loginPage
2023-04-04T09:36:32.204-0400 [org.springframework.core.log.LogFormatUtils] [traceDebug] [91] DEBUG :::GET "/app/login/loginPage", parameters={}
2023-04-04T09:36:32.205-0400 [org.springframework.web.servlet.handler.AbstractHandlerMapping] [getHandler] [510] DEBUG :::Mapped to test.login.controller.LoginController#showLoginPage(String, String, HttpServletRequest)
2023-04-04T09:36:32.205-0400 [test.login.controller.LoginController] [showLoginPage] [71] DEBUG :::request urlhttp://localhost:11003/app/login/loginPage
2023-04-04T09:36:32.205-0400 [test.login.controller.LoginController] [showLoginPage] [72] INFO :::Entered showLoginPage() of LoginController
2023-04-04T09:36:32.205-0400 [test.login.controller.LoginController] [showLoginPage] [73] DEBUG ::: LoginController param error null
2023-04-04T09:36:32.205-0400 [test.login.controller.LoginController] [showLoginPage] [74] DEBUG ::: LoginController param logout null
2023-04-04T09:36:32.205-0400 [test.login.controller.LoginController] [showLoginPage] [81] INFO :::^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ anonymousUser anonymousUser
2023-04-04T09:36:32.205-0400 [test.login.controller.LoginController] [showLoginPage] [102] INFO :::Exited showLoginPage() of LoginController
2023-04-04T09:36:32.206-0400 [org.springframework.web.servlet.view.AbstractView] [render] [309] DEBUG :::View name '/main/login', model {}
2023-04-04T09:36:32.207-0400 [org.springframework.web.servlet.view.InternalResourceView] [renderMergedOutputModel] [169] DEBUG :::Forwarding to [/WEB-INF/jsp//main/login.jsp]
2023-04-04T09:36:32.208-0400 [org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper] [saveContext] [348] DEBUG :::Did not store anonymous SecurityContext
2023-04-04T09:36:32.210-0400 [org.springframework.web.servlet.FrameworkServlet] [logResult] [1131] DEBUG :::Completed 200 OK
2023-04-04T09:36:32.210-0400 [org.springframework.security.web.context.SecurityContextPersistenceFilter] [doFilter] [118] DEBUG :::Cleared SecurityContextHolder to complete request

---

Update: Client is the browser. 21457B6DC399CC4C3FC510EF9AEC4B0C is the Session Id created. For /app/login/authenticateWithProfile API is using the earlier JSession ID in the response header. For /dashboard API and for the rest of .js and .css is using E8BBF1EB52BC1264F2A92522D95607AB. See the logs below.

[10/Apr/2023:11:59:12 -0400] 127.0.0.1 - 21457B6DC399CC4C3FC510EF9AEC4B0C - "POST /app/app_security_check HTTP/1.1" 302 - JSESSIONID=21457B6DC399CC4C3FC510EF9AEC4B0C; Path=/app; Secure; HttpOnly
[10/Apr/2023:11:59:12 -0400] 0:0:0:0:0:0:0:1 - BC4A44606D9D49831DEA7DDD2C0D3C2E BC4A44606D9D49831DEA7DDD2C0D3C2E "POST /app/login/authenticateWithProfile HTTP/1.1" 200 629 JSESSIONID=\"21457B6DC399CC4C3FC510EF9AEC4B0C; Path=/app; Secure; HttpOnly\"; Version=1
[10/Apr/2023:11:59:12 -0400] 0:0:0:0:0:0:0:1 - E8BBF1EB52BC1264F2A92522D95607AB - "GET /app/login/dashboard HTTP/1.1" 302 - JSESSIONID=E8BBF1EB52BC1264F2A92522D95607AB; Path=/app; Secure; HttpOnly
[10/Apr/2023:11:59:12 -0400] 0:0:0:0:0:0:0:1 - E8BBF1EB52BC1264F2A92522D95607AB E8BBF1EB52BC1264F2A92522D95607AB "GET /app/login/loginPage HTTP/1.1" 200 22268 -

---

Update:The API /authenticateWithProfile is invoking /app_security_check API (which is spring security's filterProcessesUrl). 
The API /app_security_check is generating the cookie 21457B6DC399CC4C3FC510EF9AEC4B0C. We are setting this as cookie to the response header and is expected to use post authentication but that is not happening. 
From the logs while redirecting to /dashboard in the response header I'm seeing a different session id.
Does Tomcat needs any additional configuration to  that I'm missing?   

---

Found that in the response header of /authenticateWithProfile API session id is set as below JSESSIONID="53E9FA013FAAC0CF98F65FDF22A9EB69; Expires=Sat, 15 Apr 2023 06:12:18 GMT; Path=/app; HttpOnly"; Version=1

and while redirecting to /dashboard in the request header the Session ID is prepended with " like this JSESSIONID="53E9FA013FAAC0CF98F65FDF22A9EB69

I'm using in context.xml If I use Rfc6265CookieProcessor I get this error java.lang.IllegalArgumentException: An invalid character [59] was present in the Cookie value. Which cookieProcesser do I need to use for Tomcat 9.0.71 and am I missing any attributes?

Answer 1

You are setting your cookie value incorrectly.

Check the difference in syntax between the Set-Cookie and Cookie headers and it will explain what you are seeing in your server logs. For example, you should be getting a response from the server like this:

Set-Cookie JSESSIONID=21457B6DC399CC4C3FC510EF9AEC4B0C; Path=/app; Secure; HttpOnly

The value of the Set-Cookie header is the whole text JSESSIONID=21457B6DC399CC4C3FC510EF9AEC4B0C; Path=/app; Secure; HttpOnly and not just the session identifier. It's got all that other junk in it as well.

When you use that value as the cookie, you are doing this:

Cookie JSESSIONID="21457B6DC399CC4C3FC510EF9AEC4B0C; Path=/app; Secure; HttpOnly"

which is wrong. You want this instead:

Cookie JSESSIONID=21457B6DC399CC4C3FC510EF9AEC4B0C

You will have to parse the value of the Set-Cookie response or, if you are using a wrapper library around your HTTP request (e.g. commons-http-client, etc.) then you can probably use their tools for that kind of parsing.