当前位置: 代码迷 >> 综合 >> Https 请求僵死导致 @Scheduled 单线程定时任务挂起
  详细解决方案

Https 请求僵死导致 @Scheduled 单线程定时任务挂起

热度:53   发布时间:2023-12-06 09:03:33.0

问题描述:

生产环境上的定时任务执行一段时间后,定时任务没有继续执行。

问题排查:

1.通过筛查生产环境上的日志,发现定时任务每次中止执行都是在QjyServiceImpl中的方法执行后。既有错误执行后停止,也有正常执行后停止。
错误中止日志:

2020-08-29 05:40:10.976 ERROR 1 --- [scheduling-1] c.h.e.m.d.zenith.service.QjyServiceImpl  : response is error: org.springframework.web.client.ResourceAccessException: I/O error on GET request for "https://***.***.***/deviceStatePageQuery": Read timed out; nested exception is java.net.SocketTimeoutException: Read timed outat org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:748) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:641) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl.execute(QjyServiceImpl.java:332) [attend-backend-1.2-SNAPSHOT.jar!/:1.2-SNAPSHOT]at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl.deviceStatePageQuery(QjyServiceImpl.java:283) [attend-backend-1.2-SNAPSHOT.jar!/:1.2-SNAPSHOT]at com.hbd.edu.monitor.job.FindDeviceStateJob.execute(FindDeviceStateJob.java:43) [attend-backend-1.2-SNAPSHOT.jar!/:1.2-SNAPSHOT]at sun.reflect.GeneratedMethodAccessor1070.invoke(Unknown Source) ~[na:na]at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_222]at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_222]at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) [spring-context-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) [spring-context-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:93) [spring-context-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_222]at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_222]at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_222]at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_222]at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_222]at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_222]at java.lang.Thread.run(Thread.java:748) [na:1.8.0_222]Caused by: java.net.SocketTimeoutException: Read timed outat java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_222]at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_222]at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[na:1.8.0_222]at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_222]at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) ~[na:1.8.0_222]at sun.security.ssl.InputRecord.read(InputRecord.java:503) ~[na:1.8.0_222]at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975) ~[na:1.8.0_222]at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933) ~[na:1.8.0_222]at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) ~[na:1.8.0_222]at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) ~[na:1.8.0_222]at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) ~[na:1.8.0_222]at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[na:1.8.0_222]at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:735) ~[na:1.8.0_222]at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:678) ~[na:1.8.0_222]at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1593) ~[na:1.8.0_222]at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1498) ~[na:1.8.0_222]at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480) ~[na:1.8.0_222]at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:352) ~[na:1.8.0_222]at org.springframework.http.client.SimpleBufferingClientHttpRequest.executeInternal(SimpleBufferingClientHttpRequest.java:82) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:53) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:739) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]... 17 common frames omitted**正常中止日志:**2020-09-04 18:35:01.596  INFO 1 --- [scheduling-1] c.h.e.m.d.zenith.service.QjyServiceImpl  : token: QjyResponse(msg=????, code=200, result={"token":"194113Y293b110015321599215701128"})2020-09-04 18:35:01.597  INFO 1 --- [scheduling-1] c.h.e.m.d.zenith.service.QjyServiceImpl  : requestUrl: https://***.***.***/deviceStatePageQuery?limit=100&pageNum=1 body: null2020-09-04 18:35:05.667  INFO 1 --- [scheduling-1] c.h.e.m.d.zenith.service.QjyServiceImpl  : url--> https://***.***.***/deviceStatePageQuery?limit=100&pageNum=1 QjyResponse -->QjyResponse(msg=????, code=200, result={total=9, pageSize=100, list=[{isOnline=false, did=0106000353}, {isOnline=true, did=0106000316}, {isOnline=true, did=0106000250}, {isOnline=false, did=0106000261}, {isOnline=false, did=0106000279}, {isOnline=false, did=0106000272}, {isOnline=true, did=0106000298}, {isOnline=true, did=0106000238}, {isOnline=true, did=0106000063}], pageNum=1})**2.进入docker输出应用的堆栈信息到文件,找到对应的定时任务执行的线程【scheduling-1】:间隔20分钟,两次输出堆栈信息。****第一次定时任务线程状态:**"scheduling-1" #48 prio=5 os_prio=0 tid=0x00007ff061a38800 nid=0x39 runnable [0x00007fefc3692000]java.lang.Thread.State: RUNNABLEat java.net.SocketInputStream.socketRead0(Native Method)at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)at java.net.SocketInputStream.read(SocketInputStream.java:171)at java.net.SocketInputStream.read(SocketInputStream.java:141)at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)at sun.security.ssl.InputRecord.read(InputRecord.java:503)at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975)- locked <0x00000000dd210938> (a java.lang.Object)at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1367)- locked <0x00000000dd210a60> (a java.lang.Object)at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1395)at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1379)at sun.net.www.protocol.https.HttpsClient.afterConnect(HttpsClient.java:559)at sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:185)at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1570)- locked <0x00000000dd210ad0> (a sun.net.www.protocol.https.DelegateHttpsURLConnection)at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1498)- locked <0x00000000dd210ad0> (a sun.net.www.protocol.https.DelegateHttpsURLConnection)at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:352)at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl.lambda$getToken$0(QjyServiceImpl.java:138)at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl$$Lambda$1038/1351999069.call(Unknown Source)at com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:5058)at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3708)at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2416)at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2299)- locked <0x00000000dd210c28> (a com.google.common.cache.LocalCache$StrongAccessWriteEntry)at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2212)at com.google.common.cache.LocalCache.get(LocalCache.java:4147)at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:5053)at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl.getToken(QjyServiceImpl.java:132)at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl.deviceStatePageQuery(QjyServiceImpl.java:282)at com.hbd.edu.monitor.job.FindDeviceStateJob.execute(FindDeviceStateJob.java:43)at sun.reflect.GeneratedMethodAccessor950.invoke(Unknown Source)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)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:93)at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)at java.util.concurrent.FutureTask.run(FutureTask.java:266)at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)at java.lang.Thread.run(Thread.java:748)Locked ownable synchronizers:- <0x00000000dc2a5b08> (a java.util.concurrent.ThreadPoolExecutor$Worker)**第二次定时任务线程状态:**"scheduling-1" #48 prio=5 os_prio=0 tid=0x00007ff061a38800 nid=0x39 runnable [0x00007fefc3692000]java.lang.Thread.State: RUNNABLEat java.net.SocketInputStream.socketRead0(Native Method)at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)at java.net.SocketInputStream.read(SocketInputStream.java:171)at java.net.SocketInputStream.read(SocketInputStream.java:141)at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)at sun.security.ssl.InputRecord.read(InputRecord.java:503)at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975)- locked <0x00000000dd210938> (a java.lang.Object)at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1367)- locked <0x00000000dd210a60> (a java.lang.Object)at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1395)at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1379)at sun.net.www.protocol.https.HttpsClient.afterConnect(HttpsClient.java:559)at sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:185)at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1570)- locked <0x00000000dd210ad0> (a sun.net.www.protocol.https.DelegateHttpsURLConnection)at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1498)- locked <0x00000000dd210ad0> (a sun.net.www.protocol.https.DelegateHttpsURLConnection)at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:352)at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl.lambda$getToken$0(QjyServiceImpl.java:138)at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl$$Lambda$1038/1351999069.call(Unknown Source)at com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:5058)at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3708)at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2416)at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2299)- locked <0x00000000dd210c28> (a com.google.common.cache.LocalCache$StrongAccessWriteEntry)at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2212)at com.google.common.cache.LocalCache.get(LocalCache.java:4147)at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:5053)at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl.getToken(QjyServiceImpl.java:132)at com.hbd.edu.monitor.device.zenith.service.QjyServiceImpl.deviceStatePageQuery(QjyServiceImpl.java:282)at com.hbd.edu.monitor.job.FindDeviceStateJob.execute(FindDeviceStateJob.java:43)at sun.reflect.GeneratedMethodAccessor950.invoke(Unknown Source)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)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:93)at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)at java.util.concurrent.FutureTask.run(FutureTask.java:266)at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)at java.lang.Thread.run(Thread.java:748)Locked ownable synchronizers:- <0x00000000dc2a5b08> (a java.util.concurrent.ThreadPoolExecutor$Worker)**3.根据日志和堆栈信息分析,定时任务线程状态正常。**
**4.排查代码QjyServiceImpl,找到getToken方法,检查HttpsUtil.getHttpsURLConnection,发现没有设置connectTimeout、readTimeout。**

public SimpleMessage deviceStatePageQuery(Map<String, Object> filterMap) {
UriComponentsBuilder uriComponentsBuilder = UriComponentsBuilder.fromHttpUrl(url + “/cloud/device/deviceStatePageQuery”);
filterMap.forEach(uriComponentsBuilder::queryParam);
RequestEntity requestEntity = RequestEntity.get(uriComponentsBuilder.build().toUri())
.header(token, getToken()).build();
return execute(requestEntity);
}

	public String getToken() {try {return CACHE.get(appId, () -> {InputStream is = null;HttpsURLConnection connection = null;try {String data = "?appid=" + appId + "&appkey=" + URLEncoder.encode(appKey, "UTF-8");connection = HttpsUtil.getHttpsURLConnection(url + "/cloud/getToken" + data, "GET");int code = connection.getResponseCode();StringBuilder str = new StringBuilder();if (code == 200) {//相应成功,获得相应的数据is = connection.getInputStream();//得到数据流(输入流)str.append(IOUtils.toString(is, StandardCharsets.UTF_8));}QjyResponse qjyResponse = JSON.parseObject(str.toString(), QjyResponse.class);JSONObject jsonObject = (JSONObject) qjyResponse.getResult();log.info("token: {}", qjyResponse);return jsonObject.getString(token);} catch (IOException e) {log.error("[getToken] 获取 token 出错了。");return null;} finally {if (is != null) {org.apache.tomcat.util.http.fileupload.IOUtils.closeQuietly(is);}if (connection != null) {IOUtils.close(connection);}}});} catch (ExecutionException e) {return null;}}
## 问题解决:
设置HttpsUtil的connectTimeout、readTimeout。定时任务中,发起http/https链接后,当链接成功,第三方服务接口持续不返回,会导致当前线程挂起,线程状态正常。类似于http/https链接僵死。
  相关解决方案