search

mobi-projects / nail-case-server

https://mobi-projects.github.io/nail-case-server/
MIT License
2 stars 0 forks source link

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

Open dongminjang24 opened 1 month ago

dongminjang24 commented 1 month ago

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"

dongminjang24 commented 1 month ago

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

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

  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);

dongminjang24 commented 1 month ago

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); } }

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

dongminjang24 commented 1 month ago

좀더 연구해보니

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

ImageService 클래스 수정:

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

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