트랜잭션을 공부했다고 생각하고 업무에 임했던 나였는데, 도저히 풀리지않는 느낌으로 예외를 받았던게 있다. 이전에 한번 포스팅했던 Stream Closed 에러였는데 이게 또 한번 나를 붙잡았다. 처음 개발환경에서 OpenFeign을 사용하면서 또 logging level에서 IOException이 나는줄알고 이부분으로 삽질을 했다.
근데 그게 아니어서 이 포스팅을 작성했다.
HelloController.java
@RestController
@RequiredArgsConstructor
public class TestController {
private final TransactionParentService transactionParentService;
@GetMapping("/transaction/test")
public ResponseEntity<?> test() {
transactionParentService.size();
return ResponseEntity.ok().build();
}
}
TransactionParentService.java
@Service
@RequiredArgsConstructor
public class TransactionParentService {
private final MemberService memberService;
private final TransactionErrorService transactionErrorService;
@Transactional
public int size() {
transactionErrorService.throwExceptionLog();
return memberService.allSize();
}
}
TransactionErrorService.java
@Slf4j
@Service
@RequiredArgsConstructor
public class TransactionErrorService {
private final MemberService memberService;
@Transactional
public void throwExceptionLog() {
try {
memberService.saveAndException();
} catch (RuntimeException e) {
log.error("error : {}", e.getMessage());
}
System.out.println("끝");
}
}
MemberService.java
@Service
@Transactional
@RequiredArgsConstructor
public class MemberService {
private final MemberRepository memberRepository;
public void save() {
memberRepository.save(new Member(1L, "홍길동"));
}
@Transactional
public void saveAndException() {
memberRepository.save(new Member(null, "홍길동"));
throw new RuntimeException();
}
public int allSize() {
return memberRepository.findAll().size();
}
}
TransactionParentService -> TransactionErrorService -> MemberService 순서로 서비스는 동작하게 되고, 기본적으로 Service에는 메소드마다 @Transactional 어노테이션이 붙어있다.
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Getting transaction for [com.github.lsj8367.service.TransactionParentService.size]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Getting transaction for [com.github.lsj8367.service.TransactionErrorService.throwExceptionLog]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Getting transaction for [com.github.lsj8367.service.MemberService.saveAndException]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Completing transaction for [com.github.lsj8367.service.MemberService.saveAndException] after exception: java.lang.RuntimeException
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Completing transaction for [com.github.lsj8367.service.TransactionErrorService.throwExceptionLog]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Getting transaction for [com.github.lsj8367.service.MemberService.allSize]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Completing transaction for [com.github.lsj8367.service.MemberService.allSize]
TRACE 66119 --- [nio-8080-exec-1] o.s.t.i.TransactionInterceptor : Completing transaction for [com.github.lsj8367.service.TransactionParentService.size]
여기서 보면 정상적으로 트랜잭션을 처음엔 쭉 획득한다. 그리고나서 memberService.save()를 통해 SimpleJpaRepository까지 하기위한 transaction을 얻게된다.
에러가 나는 부분
우리의 코드에서는 save 이후 throw new RuntimeException()이 있다. 여기서 부터 after Exception : java.lang ...으로 보이는 rollback 마킹이 존재한다.
org.springframework.transaction.UnexpectedRollbackException: Transaction silently rolled back because it has been marked as rollback-only
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:752) ~[spring-tx-5.3.22.jar:5.3.22]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) ~[spring-tx-5.3.22.jar:5.3.22]
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:654) ~[spring-tx-5.3.22.jar:5.3.22]
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:407) ~[spring-tx-5.3.22.jar:5.3.22]
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.22.jar:5.3.22]
...생략
at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
이게 도대체 어떻게 동작하는것인가? 추상클래스인 TransactionAspectSupport.invokeWithinTransaction 메소드를 사용하는 TransactionInterceptor의 invoke를 호출해서 안쪽에 추상클래스의 메소드를 사용한다.
해당 @Transactional이 붙은 메소드에서 던져진 exception을 Throwable 객체로 catch절에서 받고있다.
DefaultTransactionAttribute
rollbackOn 메소드
이 스프링 기본 구성인 DefaultTransactionAttribute구현에서 rollbackOn 메소드를 사용하게 되는데 이 rollbackOn에서 그토록 얘기했던 말들이 나온다.
RuntimeException이 여기서 채택되어 instanceof로 체크하고 있다!!!
그래서 rollback 마크를 하나를 진행해두고 나머지 트랜잭션 어노테이션에 대해서도 commit을 할거냐 rollback을 할거냐에 대한 작업을 이 해당 aop를 통해 동작한다.
TransactionManager
각 트랜잭션 매니저들은 AbstractPlatformTransactionManager 추상클래스를 상속하여 사용한다.
그래서 트랜잭션 매니저가 전부 commit을 수행하는데, rollback 전용 마크가 하나라도 붙게되면 UnexpectedRollbackException 이 에러가 나타나게 된다. 그래서 보이게되는 예외 메시지가 Transaction silently rolled back because it has been marked as rollback-only로 나오게 된다.
그럼 Stream Closed 는?
ㅋㅋㅋㅋ.. 그러게 말이다. 이거 왜뜬건지 도저히 이해가 되지 않는데, dev환경에선 이 로그만 보였지 위의 로그가 안보였었다. 근데 로컬에서 이 부분을 수정하니 말끔히 해결됐다. 아무튼 원초적인 문제는 이 무지성 붙이기 @Transactional이었다. 막판에 이게 떠올라서 지웠더니 해결되서 꿀잠각이다.
물론 @EnableFeignClients 는 별도의 Configuration 클래스 파일에 설정을 해주었었다!
여기까지는 일단 기본적인 설정이지만, 아래의 레벨 설명이 진짜다.
Feing Logging Level은 총 4단계로 이루어져있다.
NONE: 로깅 없음(Default)
BASIC: 요청 방법 및 URL, 응답 상태 코드 및 실행 시간 기록
HEADERS: 요청 및 응답 헤더와 함께 기본 정보를 기록
FULL: 요청과 응답 모두에 대한 헤더, 본문 및 메타데이터를 기록
기본적으로 BASIC, HEADERS에는 정상작동을 했던 우리의 소스였다.
일단 소스가 어떤 구성이냐면...
회사의 정보를 많이 노출할 수는 없기에 간략하게 설명한다.
일명 스크래핑이라고 하는 기술, 흔히 크롤링이라고도 할 수 있을것이다.
해당 작업을 외부 API로 연동하여 응답값을 받아 파싱해주는 작업이 있다.
근데 우리의 규칙상 해당 스크래핑의 원문 데이터라는 아예 크롤링의 전체에 해당하는 xml양식의 데이터도 같이 받아오는 방식을 정책으로 정했기 때문에 우리는 Google Cloud 를 사용하기에 Google Cloud Storage에 원문 데이터를 저장하고, 나머지 데이터를 데이터베이스에 저장하는 구조로 구성이 되어있다.
여기서 문제가 발생한다.
일단 원문 데이터가 포함이되기에 응답값의 길이가 상당히 길다.
길지않고 정상적인 응답을 받는 스크래핑 로직의 경우에는 이런 디버깅이 해당되지 않는다.
근데 글자가 길었고, 내가 핸드폰에서 슬랙으로 알림을 받았던 에러메시지는 다음과 같았다.
에러 로그.... 정보유출되는 것이 너무 많아 다 지워버렸다 ㅋㅋㅋ...
아무튼 이러한 예외가 발생했다.
에러 메시지를 보면 해당 응답값의 타입이 application/json이 아니라는데
디버깅을 찍어보면 정상 json응답값이 파싱이 되고 있었다.
아래부분이 좀 더 의심스러웠었는데, buffer Length : 8192
그러니까... 버퍼길이가 8192 제한인데 길이가 더 커서 담기지 않아서 에러가 발생한다는 것이다.
이 부분이 왜 나왔는지를 보니까
해당 스크래핑 작업을 하는 로직에서 우리는 로그를 찍는다.
스크래핑 작업 전후로 시작했고 완료되었다는 외부의 로직 실행결과를 로그로 담고 있다.
그런데 이 담는 로직에서 예외를 이렇게 뱉는다는 것이다.
feign 의 기본 클라이언트는 어떤것을 쓰냐면 바로 ApacheHttpClient를 사용한다.
아래는 구현체의 내용 일부분이며, 빨간 네모의 asInputStream으로 body를 출력하고 있다.
httpResponse에서 받는 해당 entity의 content를 찍어내는 것인데, 이 부분에서 에러가 발생한다.
기본 maxContentLength 가 8192이기 때문에 정상적으로 스트림 반환을 하지 않고 저렇게 예외를 띄우게 되는 것이다!
이부분이 TCP 연결에서의 최대 길이이기 때문에 HttpClient를 사용하면 이런 예외가 발생된다.
아래는 ByteArrayBody이다.
해당 부분에서는 ByteArrayInputStream을 사용하기 때문에 TCP length 제한보다 더 쓸수 있는 것 같다.
이것이 바로 ByteArrayInputStream....?
아무든 이 두 asInputStream()을 보는 이유는 아래에서 설명하겠다.
아무튼 이 ByteArrayInputStream은 tcp max content length와 관계없이 스트림을 출력하기에 길이제한이 없다.
이 두개의 차이를 가르는 것은 Log 였다!!!
그래서 소스를 파고들었다.
해당 로그 부분이 BASIC레벨 보다 수준이 낮은 경우 수행되는 로직인데,
그래서 FULL로직에서만 정상적으로 데이터 파싱이 된다.
왜? - response.toBuilder().body(bodyData).build() 를 통해 새로운 ByteArrayInputStream으로 생성되기 때문이다.
그래서 이 부분을 재정의를 해주어 BASIC 레벨에서도 길이가 아무리 길더라도 데이터를 파싱할 수 있게 설정해주었다.
로직이 정상적으로 수행되며 아래 로그부분에서 객체를 다시 만들어주게 되는걸 보고나서 넘 행복했다는것...😇😇😇
해결방안
해당 Feign의 Logger를 상속받아서 log찍는 부분을 override 시켜주었다.
그래서 기존 로직을 또 건드리고 싶지는 않았다. <- 로그는 이대로 찍어주는게 마음 편했으니까?
그래서 분기처리 하는 부분을 제거하고 정말로 필요없는 부분만을 제거해주고 나머지 로직은 유지했다.
아무튼 데이터가 길었기 때문에 로그레벨에 따라 값이 파싱이 되고 안되고 났던게 좀 신기했다.
길이가 짧은 응답을 사용했다면 오히려 이런것도 모르고 그냥 설정따라 파싱해주고 안해주고로 넘어갔을 것 같다!!!!
오랜만에 포스팅하는데 회사에서 그동안 앱 2.0 버전을 출시한다고 이래저래 바빴던 나날을 보냈다.
결과적으로는 만족스러운 출시..? 였던것 같다 ㅋㅋㅋ
버그도 많았고, QA 엔지니어께서 고생을 많이 하셨을 수도 있고 내가 구현한 메시지 플랫폼도 테스트하기가 정말 까다로웠다.
각설하고..
해당 에러사항을 구현하는건 Kafka를 이용하지 않아도 되기 때문에 RestAPI로 구현했다. (+ 테스트코드로만)
모든 코드는 깃허브에 있다.
이번엔 무슨 버그였냐?
이런 에러가 쏟아져나왔다. 기존 레거시 푸시는 NHN Toast를 이용한 푸시서비스로 구성되어 있었다.
변경한다고 해도 과도기가 존재하기 때문에 바로 지울수는 없고 이전 앱을 사용하는 사용자들에게는 해당 푸시로 알림은 계속 받아야되기 때문이다.
왜 났던 에러였는지 더듬어봤더니
Async 설정
기본적으로 @Async 를 사용하기 위해서는 Configuration 클래스를 하나 만들어주고 비동기 실행기에 대한 설정을 해주어야 한다.
이런식으로 에러를 일부러 내기 위해서 큐 사이즈를 5개 기본 스레드 1, 최대 스레드 2, 그리고 비동기로 처리할 큐 사이즈를 5로 구성했다.
문제상황 1
nhn 푸시를 보내기 위해선 Kafka에 Producer를 통해 메세지를 넣어주면, 내가 구현한 메시지 플랫폼에서 해당 메시지를 Consume하여 동작하는 방식으로 구성되어있다.
그런데 나는 비동기로 구현하겠다고만 생각하고 사이즈를 제한해두지는 않았었다.
그래서 Consume은 계속해서 KafkaListener를 통해 무제한으로 하고 있는 와중에 이 컨슘 속도가 너무 빠르니까
위에서 설정한 비동기 처리 큐 사이즈를 200으로 잡아놓아도 예를 들어 1000건이 한방에 producer를 통해 적재된 후 바로 consume을 해버리니까
100개 큐를 훌쩍 넘어버려서도 막는게 아니라 지속적 컨슘이 일어나기에 큐 사이즈를 넘어서는 순간에도 이 메소드 실행을 밀어 넣는 오류였다.
그래서 맨위의 이미지처럼 Exception이 발생하게 되는 것이다.
에러 직접 구현
정확한 코드는 깃허브에서 보면 되지만 여기서는 간략하게 대충 구현하도록 하겠다.
JDK 17버전이기 때문에 record class를 사용함. (record를 사용하면 클래스는 final로 선언되며 equals & hashCode를 재정의하여 갖고있음)
/hello 를 호출하면 printAsync라는 비동기 메소드를 100번호출하게끔 만드는 로직이 있다.
HelloController.java
@RestController
public record HelloController(HelloService helloService) {
@GetMapping("/hello")
public ResponseEntity<?> hello() {
int i = 0;
while (true) {
helloService.printAsync();
i++;
if (i == 100) {
break;
}
}
return ResponseEntity.ok(Map.of("data", "success"));
}
}
HelloService.java
@Slf4j
@Service
public class HelloService {
@Async("threadPoolTaskExecutor")
public void printAsync() {
try {
Thread.sleep(5000);
log.info(Thread.currentThread().getName());
log.info("hello service print!!!");
} catch (InterruptedException e) {
log.error("error : {}", e.getMessage());
} catch (Exception e) {
log.error(e.getMessage());
}
}
}
printAsync()는 비동기로 호출하며 5초를 기다리고 log를 찍게 되는데, 우리가 처음 전역적으로 설정해준 스레드 설정은
요청이 들어오면 maxQueue 사이즈인 5까지만 담을 수 있게 되어있고 작업이 느려서 큐 데이터를 하나 소진하지 못한다면 에러가 발생하는데
그 에러는 이렇다.
이미지로 한방에 찍어지지 않아 글자로 첨부한다.
Caused by: org.springframework.core.task.TaskRejectedException: Executor [java.util.concurrent.ThreadPoolExecutor@265c1a7c[Running, pool size = 2, active threads = 2, queued tasks = 5, completed tasks = 0]] did not accept task: org.springframework.aop.interceptor.AsyncExecutionInterceptor$$Lambda$967/0x00000008010a7dc0@740a0d5e
at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.submit(ThreadPoolTaskExecutor.java:391)
at org.springframework.aop.interceptor.AsyncExecutionAspectSupport.doSubmit(AsyncExecutionAspectSupport.java:292)
at org.springframework.aop.interceptor.AsyncExecutionInterceptor.invoke(AsyncExecutionInterceptor.java:129)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708)
at com.github.lsj8367.application.HelloService$$EnhancerBySpringCGLIB$$7321912.printAsync(<generated>)
at com.github.lsj8367.presentation.HelloController.hello(HelloController.java:17)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1070)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
... 87 more
Caused by: java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@29013ef2[Not completed, task = org.springframework.aop.interceptor.AsyncExecutionInterceptor$$Lambda$967/0x00000008010a7dc0@740a0d5e] rejected from java.util.concurrent.ThreadPoolExecutor@265c1a7c[Running, pool size = 2, active threads = 2, queued tasks = 5, completed tasks = 0]
at java.base/java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2065)
at java.base/java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:833)
at java.base/java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1365)
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:145)
at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.submit(ThreadPoolTaskExecutor.java:388)
... 107 more
처음 봤던 이미지와 같은 예외가 발생하는걸 볼 수 있다.
그러니까 큐 공간이 가득차기 전에 계속해서 비동기를 호출하며 작업큐에 메소드를 태우려고 하다보니 이런 예외가 발생한 것이다.
해결은?
그래서 나는 일단 푸시 발송이 그렇게 오래걸리는 로직이 아니라서 일단은 동기 상태로 바꿔놓았지만,
지속적인 모니터링을 하여 트래픽이 많아지게 되면 그때는 batchListener를 적용하여 비동기로 여러개를 한방에 처리하는 방법을 고려중이다.
