问题描述:
生产环境上的定时任务执行一段时间后,定时任务没有继续执行。
问题排查:
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 out
at 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 out
at 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: null
2020-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: RUNNABLE
at 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: RUNNABLE
at 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链接僵死。