[product-analyzer] Select-score 생성 시 http parsing error

[tonykang22]

Select-score 생성 시 http parsing error

개요

• 23. 4. 1. : create select-score가 트리거 된 이후 약 20분 후 schedule 스레드가 동작을 멈추는 에러 발생
  • 그로부터 약 9 시간 뒤 o.a.c.h.Http11Processor - Error parsing HTTP request header 발생
  • 세부 내용 : Invalid character found in method name [0x000x000x00TZ0x000x000x000x000x000x000x000x000x010x000x000x040x010I0x000x000x000x000x800x0b0xa80xc00x000x0c)t ]. HTTP method names must be tokens

로그

• 23. 4. 1. 로그 일부
  • 21:40:44.252 이후 로그 없음
  • 다음날 로그 또한 없음

12:23:40.177 [scheduling-1] INFO  c.g.k.p.s.s.j.ItemScoutService - Getting ItemScoutIndicator start. keyword: 비상
12:23:40.177 [scheduling-1] INFO  c.g.k.p.s.s.j.ItemScoutService - Getting keyword_id start. Keyword: 비상
12:23:40.185 [scheduling-1] INFO  c.g.k.p.s.s.j.ItemScoutService - Getting keyword_id complete. Keyword: 비상, keyword_id: 7750854
12:23:41.185 [scheduling-1] INFO  c.g.k.p.s.s.j.ItemScoutService - Getting itemscout-stat start. keyword_id: 7750854, URL: https://api.itemscout.io/api/v2/keyword/stats/7750854
21:40:44.252 [http-nio-8000-exec-1] INFO  o.a.c.h.Http11Processor - Error parsing HTTP request header
 Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.
java.lang.IllegalArgumentException: Invalid character found in method name [0x000x000x00TZ0x000x000x000x000x000x000x000x000x010x000x000x040x010I0x000x000x000x000x800x0b0xa80xc00x000x0c)t ]. HTTP method names must be tokens
    at org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:419)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:269)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1726)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
    at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.base/java.lang.Thread.run(Thread.java:829)

Thread dump

• Schedule thread 를 확인해보면 2일 전의 ItemScoutService.getItemScoutStat 가 스택에 들어있는 것을 확인할 수 있다.
  • 다른 스레드는 정상 상태
• Thread.State : WAITING (on object monitor)
  • 해당 스레드는 cron job(시간)에 의해 트리거 되고 그 외의 방법으로는 notify() 되지 않을 것이다.
  • TIMED_WAITING 상태인 경우, 외부적인 변화뿐만 아니라 시간에 의해서도 WAITING 상태가 해제될 수 있다.
  • 현재는 WAITING 상태이기 때문에 cron job이 작동하지 않은 것으로 생각된다.

"scheduling-1" #44 prio=5 os_prio=0 cpu=743923.86ms elapsed=1595247.95s tid=0x00007f9f4e158000 nid=0x10e47 in Object.wait()  [0x00007f9e0a5f5000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(java.base@11.0.11/Native Method)
    - waiting on <no object reference available>
    at java.lang.Object.wait(java.base@11.0.11/Object.java:328)
    at okhttp3.internal.framed.FramedStream.waitForIo(FramedStream.java:584)
    at okhttp3.internal.framed.FramedStream.getResponseHeaders(FramedStream.java:139)
    - waiting to re-lock in wait() <0x00000000d680ec20> (a okhttp3.internal.framed.FramedStream)
    at okhttp3.internal.http.Http2xStream.readResponseHeaders(Http2xStream.java:145)
    at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:53)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:109)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:124)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:170)
    at okhttp3.RealCall.execute(RealCall.java:60)
    at org.springframework.http.client.OkHttp3ClientHttpRequest.executeInternal(OkHttp3ClientHttpRequest.java:73)
    at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48)
    at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:66)
    at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:776)
    at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:711)
    at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:602)
    at com.github.kingwaggs.productanalyzer.service.selectscore.job.ItemScoutService.getItemScoutStat(ItemScoutService.java:171)
    at com.github.kingwaggs.productanalyzer.service.selectscore.job.ItemScoutService.getIndicator(ItemScoutService.java:45)
    at com.github.kingwaggs.productanalyzer.service.selectscore.job.ItemScoutWorker.getIndicatorList(ItemScoutWorker.java:47)
    at com.github.kingwaggs.productanalyzer.service.selectscore.job.ItemScoutWorker$$FastClassBySpringCGLIB$$6f9b8a34.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
    at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
    at com.github.kingwaggs.productanalyzer.util.PerformanceAspect.logPerformance(PerformanceAspect.java:22)
    at jdk.internal.reflect.GeneratedMethodAccessor262.invoke(Unknown Source)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.11/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@11.0.11/Method.java:566)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)
    at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
    at com.github.kingwaggs.productanalyzer.service.selectscore.job.ItemScoutWorker$$EnhancerBySpringCGLIB$$40b162bb.getIndicatorList(<generated>)
    at com.github.kingwaggs.productanalyzer.service.selectscore.SelectScoreService.createSelectScore(SelectScoreService.java:77)
    at com.github.kingwaggs.productanalyzer.service.ProductAnalyzerService.createSelectScoreResult(ProductAnalyzerService.java:136)
    at com.github.kingwaggs.productanalyzer.service.ProductAnalyzerService.lambda$createSelectScores$0(ProductAnalyzerService.java:44)
    at com.github.kingwaggs.productanalyzer.service.ProductAnalyzerService$$Lambda$1598/0x00000008001dfc40.accept(Unknown Source)
    at java.util.Spliterators$ArraySpliterator.forEachRemaining(java.base@11.0.11/Spliterators.java:948)
    at java.util.stream.ReferencePipeline$Head.forEach(java.base@11.0.11/ReferencePipeline.java:658)
    at com.github.kingwaggs.productanalyzer.service.ProductAnalyzerService.createSelectScores(ProductAnalyzerService.java:44)
    at com.github.kingwaggs.productanalyzer.service.ProductAnalyzerService$$FastClassBySpringCGLIB$$7009058c.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
    at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
    at com.github.kingwaggs.productanalyzer.util.PerformanceAspect.logPerformance(PerformanceAspect.java:22)
    at jdk.internal.reflect.GeneratedMethodAccessor262.invoke(Unknown Source)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.11/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@11.0.11/Method.java:566)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)
    at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
    at com.github.kingwaggs.productanalyzer.service.ProductAnalyzerService$$EnhancerBySpringCGLIB$$e635abc3.createSelectScores(<generated>)
    at com.github.kingwaggs.productanalyzer.ProductAnalyzerRunner.createSelectScores(ProductAnalyzerRunner.java:21)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.11/Native Method)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.11/NativeMethodAccessorImpl.java:62)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.11/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@11.0.11/Method.java:566)
    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84)
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
    at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:95)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.11/Executors.java:515)
    at java.util.concurrent.FutureTask.run(java.base@11.0.11/FutureTask.java:264)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.11/ScheduledThreadPoolExecutor.java:304)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

원인

• 아직까지 정확한 원인은 파악하지 못했다.
  • 파악되는 대로 comment 에 추가 예정
• 해당 에러가 발생하는 경우의 대부분은 https 통신이 불가한 서버에 https 통신을 하려고 하는 경우라고 한다.
  • 참고 : Java Error Invalid Character Found in Method Name. HTTP Method Names Must Be Tokens

[tonykang22]

원인

• o.a.c.h.Http11Processor - Error parsing HTTP request header의 원인은 외부에서 PA API를 https 로 호출하여 발생한 것으로 확인된다.
  • 해당 에러가 select-score 작업을 blocking하지는 않은 것으로 판단된다.

결론

• PA의 select-score 생성 배치에서 스레드가 blocking 되어 있기 때문에 상품 소싱 배치가 돌지 못한 것이 문제
  • 해당 작업들은 @Scheduled를 사용 중이다.

PA 에서 TestService 를 생성하여 @Scheduled 를 사용했을 때 몇 개의 스레드가 사용되는지 파악

00:11:00.003 [scheduling-1] INFO  c.g.k.p.s.TestService - 테스트1 호출 시작합니다.
00:11:01.010 [scheduling-1] INFO  c.g.k.p.s.TestService - 1초 자고 인남
00:11:01.013 [scheduling-1] INFO  c.g.k.p.s.TestService - 테스트2 호출 시작합니다.
00:11:03.014 [scheduling-1] INFO  c.g.k.p.s.TestService - 2초 자고 인남

• spring.task.scheduling.pool.size의 default 값은 1이기 때문에 해당 문제 발생
  • 값을 3으로 변경 후 다시 애플리케이션 구동

00:13:40.005 [scheduling-2] INFO  c.g.k.p.s.TestService - 테스트1 호출 시작합니다.
00:13:40.005 [scheduling-1] INFO  c.g.k.p.s.TestService - 테스트2 호출 시작합니다.
00:13:41.007 [scheduling-2] INFO  c.g.k.p.s.TestService - 1초 자고 인남
00:13:42.010 [scheduling-1] INFO  c.g.k.p.s.TestService - 2초 자고 인남

원하는 시간에 정확하게 두 개의 작업이 트리거 되는 것 확인

• 결과적으로 spring.task.scheduling.pool.size 값을 PA 서버의 CPU 수와 동일하게 32 로 변경하기로 한다.