После обновления до Spring Boot 2.0.1 у меня возникают необъяснимые проблемы с моими приложениями.
Есть два приложения. Запросы к приложению 1 выполняют внутренний вызов к приложению 2 для получения некоторых данных. Призыв к приложению 2 проходит через упругий балансировщик нагрузки AWS (ELB). Клиент, используемый для вызова, - это Apache Commons HttpClient, упакованный моей утилитой .
После того, как приложение 1 было обновлено до Boot 2.0.1, я наблюдаю небольшое количество вызовов из приложения 1 в приложение 2 в течение длительного времени (15 минут). Когда я использую JConsole, чтобы получить дамп потока зависших потоков, я вижу следующую трассировку стека:
Stack trace:
java.net.PlainSocketImpl.socketClose0(Native Method)
java.net.AbstractPlainSocketImpl.socketPreClose(AbstractPlainSocketImpl.java:693)
java.net.AbstractPlainSocketImpl.close(AbstractPlainSocketImpl.java:530)
- locked java.lang.Object@29a91ad3
java.net.SocksSocketImpl.close(SocksSocketImpl.java:1075)
java.net.Socket.close(Socket.java:1495)
- locked java.lang.Object@71e238ff
- locked java.net.Socket@73f58606
sun.security.ssl.BaseSSLSocketImpl.close(BaseSSLSocketImpl.java:624)
- locked sun.security.ssl.SSLSocketImpl@22264f18
sun.security.ssl.SSLSocketImpl.closeSocket(SSLSocketImpl.java:1585)
sun.security.ssl.SSLSocketImpl.closeInternal(SSLSocketImpl.java:1723)
sun.security.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:2020)
sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1135)
- locked sun.security.ssl.SSLSocketImpl@22264f18
- locked java.lang.Object@4338a60d
sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940)
sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
- locked sun.security.ssl.AppInputStream@23fd5b55
org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
org.apache.http.impl.BHttpConnectionBase.fillInputBuffer(BHttpConnectionBase.java:344)
org.apache.http.impl.BHttpConnectionBase.isStale(BHttpConnectionBase.java:364)
org.apache.http.impl.conn.CPool.validate(CPool.java:71)
org.apache.http.impl.conn.CPool.validate(CPool.java:45)
org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:249)
- locked org.apache.http.pool.AbstractConnPool$2@7c672c9a
org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:193)
org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:282)
org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:269)
org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:191)
org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72)
org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:221)
org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:165)
org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:140)
com.kendelong.util.http.HttpConnectionService.doExecuteAndGetResponse(HttpConnectionService.java:243)
com.kendelong.util.http.HttpConnectionService.getResult(HttpConnectionService.java:189)
com.kendelong.util.http.IHttpConnectionService$getResult$0.call(Unknown Source)
com.hatchbaby.sub.util.MainSiteHttpProxyService.getMemberData(MainSiteHttpProxyService.groovy:68)
com.hatchbaby.sub.util.MainSiteHttpProxyService$$FastClassBySpringCGLIB$$3cc5cf68.invoke(<generated>)
org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:747)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
com.kendelong.util.performance.PerformanceMonitoringAspect.monitorInvocation(PerformanceMonitoringAspect.java:108)
com.kendelong.util.performance.PerformanceMonitoringAspect.monitorAnnotatedClasses(PerformanceMonitoringAspect.java:83)
sun.reflect.GeneratedMethodAccessor177.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644)
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
com.hatchbaby.sub.util.MainSiteHttpProxyService$$EnhancerBySpringCGLIB$$edc027d4.getMemberData(<generated>)
com.hatchbaby.sub.service.security.HatchBabyAuthenticationUserDetailsService.loadUserDetails(HatchBabyAuthenticationUserDetailsService.java:39)
com.hatchbaby.sub.service.security.HatchBabyAuthenticationUserDetailsService.loadUserDetails(HatchBabyAuthenticationUserDetailsService.java:20)
org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationProvider.authenticate(PreAuthenticatedAuthenticationProvider.java:103)
org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:174)
org.springframework.security.web.authentication.preauth.AbstractPreAuthenticatedProcessingFilter.doAuthenticate(AbstractPreAuthenticatedProcessingFilter.java:184)
org.springframework.security.web.authentication.preauth.AbstractPreAuthenticatedProcessingFilter.doFilter(AbstractPreAuthenticatedProcessingFilter.java:118)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)
org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178)
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:357)
org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:270)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.springframework.web.filter.AbstractRequestLoggingFilter.doFilterInternal(AbstractRequestLoggingFilter.java:245)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
com.hatchbaby.sub.web.RequestInfoFilter.doFilter(RequestInfoFilter.java:99)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
com.hatchbaby.sub.web.SpecialRedirectFilter.doFilter(SpecialRedirectFilter.java:43)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.ebaysf.web.cors.CORSFilter.handleSimpleCORS(CORSFilter.java:302)
org.ebaysf.web.cors.CORSFilter.doFilter(CORSFilter.java:160)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
- locked org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6ca9f281
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.lang.Thread.run(Thread.java:748)
Поток висит в этом состоянии примерно на 15 минут (на самом деле 15 минут 44 секунды плюс / минус 5 секунд), или их грубое целое число. В конце концов запрос успешно выполняется.
Еще более странно то, что когда я сравниваю логи, я вижу запрос на вход в приложение 1 и звоню в приложение 2 (скажем, в 8:00). Поток зависает в методе socketClose0 (), как показано в дампе потока. Когда запрос, наконец, завершается через 15 минут (в 8:15), временные метки в журналах приложения 2 и его ELB показывают, что запрос прибыл позднее (8:15): как если бы сокет пытался закрыть Через 15 минут он окончательно закрывается (не связавшись с сервером App 2) и немедленно повторяет попытку. Обычно это удается, но иногда он снова застревает еще на 15 минут (следовательно, кратно 15 минутам). Но запрос даже не регистрируется в ELB приложения 2 до 15 минут спустя (8:15).
Я видел такое поведение в моей среде QA (по одному серверу) и в моей производственной среде (по 2 сервера). Если я откатил код до версии с Spring Boot 1.5.9, проблема исчезнет. Однако я поочередно вернул большинство подозрительных библиотек в версию Boot 1.5.9, и проблема сохраняется. Я вернул httpclient (очевидно), groovy, tomcat и commons-codec. Мне не удалось вернуть Spring (сбросить свойство spring.version), так как приложение не запустилось. В рамках обновления до Boot 2.0.1 я перешел с EhCache, распространяемого JGroups, на Hazelcast в качестве кэша второго уровня Hibernate, но я полностью удалил Hazelcast из приложения, и проблема сохраняется. Возврат данных Hibernate или Spring JPA сложнее из-за изменений кода.
Конечно, в моем приложении не установлено таймаутов на 15 минут. Тайм-ауты подключения и сокета для httpclient составляют 5 секунд.
У кого-нибудь есть какие-либо подсказки или предложения по устранению неполадок?
UPDATE
Установка -Djavax.net.debug=all дает этот вывод:
http-nio-8080-exec-6, setSoTimeout(1) called
[Raw read]: length = 5
0000: 15 03 03 00 1A .....
[Raw read]: length = 26
0000: 98 1C 7C C4 27 0B 2B 40 E5 AC D7 38 A9 6F F7 73 ....'.+@...8.o.s
0010: 83 18 E8 15 14 7C 52 10 47 5E ......R.G^
http-nio-8080-exec-6, READ: TLSv1.2 Alert, length = 26
Padded plaintext after DECRYPTION: len = 2
0000: 01 00 ..
http-nio-8080-exec-6, RECV TLSv1.2 ALERT: warning, close_notify
http-nio-8080-exec-6, called closeInternal(false)
http-nio-8080-exec-6, SEND TLSv1.2 ALERT: warning, description = close_notify
Padded plaintext before ENCRYPTION: len = 2
0000: 01 00 ..
http-nio-8080-exec-6, WRITE: TLSv1.2 Alert, length = 26
[Raw write]: length = 31
0000: 15 03 03 00 1A 00 00 00 00 00 00 00 02 1F A3 99 ................
0010: 4C CD 61 EB 02 2C 14 0D 00 27 03 51 05 F7 1F L.a..,...'.Q...
http-nio-8080-exec-6, called closeSocket(false)
В этот момент все зависает. Глядя на клиента с помощью netstat, я вижу, что сокет находится в состоянии LAST_ACK, что означает, что он ожидает окончательного пакета ACK.
Я удалил ELB из Приложения 2 из микса и подключился напрямую к серверу для Приложения 2. Проблема сохраняется. Когда клиентские соединения находятся в состоянии LAST_ACK, в netstat на стороне сервера нет соответствующих соединений. Если сервер не отправил окончательный ACK, он был бы в FIN_WAIT_2, но поскольку соединение уже установлено, он, должно быть, отправил окончательный ACK, но так и не получил клиента.
Как обновление Spring Boot может привести к блокировке пакетов ACK при операциях закрытия сокета?
Все это происходит в Amazon Linux 2017.9.
ОБНОВЛЕНИЕ 2
Пять месяцев спустя, то же самое. Я обновил App2 до Spring Boot 2.0.5, без проблем.
Приложение 1 при обновлении до 2.0.5 начинает зависать. Я включил протоколирование проводов по протоколу HttpClient, и то, что я вижу, когда он собирается совершить сетевой вызов, на регистраторе проводов нет исходящих данных, и через 15 минут 33 я получаю входящий «конец потока» и запрос, наконец, закрывается.