비동기 처리과정에서 security 정보를 잃어버림

[hidongmin37]

2024-07-22T13:05:40.757+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.security.web.FilterChainProxy : Securing POST /shops/1/announcements/images
2024-07-22T13:05:40.757+09:00 INFO 6954 --- [nail-case-sever] [nio-8081-exec-7] .n.j.f.JwtAuthenticationProcessingFilter : JWT 인증 처리 필터: URI /api/v1/shops/1/announcements/images 처리 중
2024-07-22T13:05:40.759+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.d.redis.core.RedisConnectionUtils : Fetching Redis Connection from RedisConnectionFactory
2024-07-22T13:05:40.761+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.d.redis.core.RedisConnectionUtils : Closing Redis Connection
2024-07-22T13:05:40.761+09:00 INFO 6954 --- [nail-case-sever] [nio-8081-exec-7] .n.j.f.JwtAuthenticationProcessingFilter : 유효한 액세스 토큰, 인증 정보 저장 진행
2024-07-22T13:05:40.762+09:00 INFO 6954 --- [nail-case-sever] [nio-8081-exec-7] .n.j.f.JwtAuthenticationProcessingFilter : 토큰에서 추출된 정보 - 역할: MANAGER, 사용자 ID: 1, 이메일: manager@example.com
2024-07-22T13:05:40.765+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] tor$SharedEntityManagerInvocationHandler : Creating new EntityManager for shared EntityManager invocation
2024-07-22T13:05:40.789+09:00 INFO 6954 --- [nail-case-sever] [nio-8081-exec-7] .n.j.f.JwtAuthenticationProcessingFilter : SecurityContextHolder에 인증 정보 설정 완료: UsernamePasswordAuthenticationToken [Principal=com.nailcase.model.dto.NailArtistDetails [Username=manager@example.com, Password=[PROTECTED], Enabled=true, AccountNonExpired=true, CredentialsNonExpired=true, AccountNonLocked=true, Granted Authorities=[ROLE_MANAGER]], Credentials=[PROTECTED], Authenticated=true, Details=null, Granted Authorities=[ROLE_MANAGER]]
2024-07-22T13:05:40.790+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.security.web.FilterChainProxy : Secured POST /shops/1/announcements/images
2024-07-22T13:05:40.790+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.web.servlet.DispatcherServlet : POST "/api/v1/shops/1/announcements/images", parameters={multipart}
2024-07-22T13:05:40.792+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.nailcase.controller.PostController#uploadImages(List, NailArtistDetails, Long)
2024-07-22T13:05:40.793+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] horizationManagerBeforeMethodInterceptor : Authorizing method invocation ReflectiveMethodInvocation: public java.util.concurrent.CompletableFuture com.nailcase.controller.PostController.uploadImages(java.util.List,com.nailcase.model.dto.NailArtistDetails,java.lang.Long); target is of class [com.nailcase.controller.PostController]
2024-07-22T13:05:40.793+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] horizationManagerBeforeMethodInterceptor : Authorized method invocation ReflectiveMethodInvocation: public java.util.concurrent.CompletableFuture com.nailcase.controller.PostController.uploadImages(java.util.List,com.nailcase.model.dto.NailArtistDetails,java.lang.Long); target is of class [com.nailcase.controller.PostController]
2024-07-22T13:05:40.793+09:00 INFO 6954 --- [nail-case-sever] [nio-8081-exec-7] com.nailcase.controller.PostController : Uploading images for shopId: 1
2024-07-22T13:05:40.793+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.nailcase.service.PostService.uploadImages]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2024-07-22T13:05:40.793+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1118904255)] for JPA transaction
2024-07-22T13:05:40.794+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@4a113710]
2024-07-22T13:05:40.795+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2024-07-22T13:05:40.795+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(1118904255)]
2024-07-22T13:05:40.795+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager : Closing JPA EntityManager [SessionImpl(1118904255)] after transaction
2024-07-22T13:05:40.796+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.w.c.request.async.WebAsyncManager : Started async request for "/api/v1/shops/1/announcements/images"
2024-07-22T13:05:40.796+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-7] o.s.web.servlet.DispatcherServlet : Exiting but response remains open for further handling
2024-07-22T13:05:40.796+09:00 INFO 6954 --- [nail-case-sever] [onPool-worker-2] com.nailcase.service.ImageService : Current authentication in async method imageService: UsernamePasswordAuthenticationToken [Principal=com.nailcase.model.dto.NailArtistDetails [Username=manager@example.com, Password=[PROTECTED], Enabled=true, AccountNonExpired=true, CredentialsNonExpired=true, AccountNonLocked=true, Granted Authorities=[ROLE_MANAGER]], Credentials=[PROTECTED], Authenticated=true, Details=null, Granted Authorities=[ROLE_MANAGER]]
2024-07-22T13:05:40.796+09:00 INFO 6954 --- [nail-case-sever] [onPool-worker-3] com.nailcase.service.ImageService : Current authentication in async method imageService: UsernamePasswordAuthenticationToken [Principal=com.nailcase.model.dto.NailArtistDetails [Username=manager@example.com, Password=[PROTECTED], Enabled=true, AccountNonExpired=true, CredentialsNonExpired=true, AccountNonLocked=true, Granted Authorities=[ROLE_MANAGER]], Credentials=[PROTECTED], Authenticated=true, Details=null, Granted Authorities=[ROLE_MANAGER]]
2024-07-22T13:05:40.814+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-3] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2024-07-22T13:05:40.814+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-2] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2024-07-22T13:05:40.814+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-3] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1703774454)] for JPA transaction
2024-07-22T13:05:40.814+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-3] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@70d00bec]
2024-07-22T13:05:40.814+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-2] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(160289681)] for JPA transaction
2024-07-22T13:05:40.815+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-3] o.s.d.auditing.AuditingHandlerSupport : Touched com.nailcase.model.entity.PostImage@782 - Last modification at 2024-07-22T13:05:40.815220 by unknown
2024-07-22T13:05:40.819+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-2] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@27c94bd2]
2024-07-22T13:05:40.819+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-2] o.s.d.auditing.AuditingHandlerSupport : Touched com.nailcase.model.entity.PostImage@782 - Last modification at 2024-07-22T13:05:40.819310 by unknown
2024-07-22T13:05:40.821+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-3] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2024-07-22T13:05:40.821+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-3] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(1703774454)]
2024-07-22T13:05:40.822+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-2] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2024-07-22T13:05:40.822+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-2] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(160289681)]
2024-07-22T13:05:40.823+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-3] o.s.orm.jpa.JpaTransactionManager : Closing JPA EntityManager [SessionImpl(1703774454)] after transaction
2024-07-22T13:05:40.823+09:00 DEBUG 6954 --- [nail-case-sever] [onPool-worker-2] o.s.orm.jpa.JpaTransactionManager : Closing JPA EntityManager [SessionImpl(160289681)] after transaction
2024-07-22T13:05:40.824+09:00 DEBUG 6954 --- [nail-case-sever] [ Image-2] o.s.w.c.request.async.WebAsyncManager : Async result set to: [com.nailcase.model.dto.PostImageDto@51c11395, com.nailcase.model.dto.PostImageDto@5f06f7dd] for "/api/v1/shops/1/announcements/images"
2024-07-22T13:05:40.824+09:00 DEBUG 6954 --- [nail-case-sever] [ Image-2] o.s.w.c.request.async.WebAsyncManager : Performing async dispatch for "/api/v1/shops/1/announcements/images"
2024-07-22T13:05:40.825+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.security.web.FilterChainProxy : Securing POST /shops/1/announcements/images
2024-07-22T13:05:40.825+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.s.w.a.AnonymousAuthenticationFilter : Set SecurityContextHolder to anonymous SecurityContext
2024-07-22T13:05:40.826+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.s.w.s.HttpSessionRequestCache : Saved request http://localhost:8081/api/v1/shops/1/announcements/images?continue to session
2024-07-22T13:05:40.827+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.s.w.a.Http403ForbiddenEntryPoint : Pre-authenticated entry point called. Rejecting access
2024-07-22T13:05:40.827+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.security.web.FilterChainProxy : Securing POST /error
2024-07-22T13:05:40.827+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.s.w.a.AnonymousAuthenticationFilter : Set SecurityContextHolder to anonymous SecurityContext
2024-07-22T13:05:40.827+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.s.w.s.HttpSessionRequestCache : Saved request http://localhost:8081/api/v1/error?continue to session
2024-07-22T13:05:40.827+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.s.w.a.Http403ForbiddenEntryPoint : Pre-authenticated entry point called. Rejecting access
2024-07-22T13:05:40.828+09:00 DEBUG 6954 --- [nail-case-sever] [nio-8081-exec-8] o.s.w.c.request.async.WebAsyncManager : Servlet container error notification for "/api/v1/shops/1/announcements/images"

[hidongmin37]

이슈의 핵심은 비동기 처리에서의 보안 컨텍스트 관리

동기 처리에서는 새로운 스레드에서 작업이 실행되기 때문에, 원래 요청의 보안 컨텍스트(인증 정보 등)가 자동으로 전달되지 않습니다

1. WebMvcConfig를 통한 인터셉터 등록
   @configuration
   public class WebMvcConfig implements WebMvcConfigurer {
   @OverRide
   public void addInterceptors(InterceptorRegistry registry) {
   registry.addInterceptor(securityContextAsyncHandlerInterceptor);
   }
   }

2. 비동기 메서드에서 수동으로 SecurityContextHolder 설정
   SecurityContextHolder.setContext(SecurityContextHolder.createEmptyContext());
   SecurityContextHolder.getContext().setAuthentication(auth);

[hidongmin37]

DelegatingSecurityContextAsyncTaskExecutor 사용:
Spring Security에서 제공하는 이 executor를 사용하여 보안 컨텍스트를 자동으로 전파할 수 있습니다.
javaCopy@Configuration
public class AsyncConfig implements AsyncConfigurer {
@OverRide
public Executor getAsyncExecutor() {
ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
// executor 설정
executor.initialize();
return new DelegatingSecurityContextAsyncTaskExecutor(executor);
}
}

원래는 이게 자동으로 전파한다고 알고는 있었느나 자동으로 전파가 안되는 점이 있음

[hidongmin37]

좀더 연구해보니

상속 구조와 @async 어노테이션의 사용 방식 때문에 자동 전파가 제대로 이루어지지 않았기 때문에 비동기를 실행할때 제대로 전달이 되지 않았었음.

ImageService 클래스 수정:

@async 어노테이션을 제거하고, 대신 CompletableFuture를 직접 사용

@async 어노테이션을 사용하되, DelegatingSecurityContextAsyncTaskExecutor를 직접 주입받아 사용