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

14 篇文章 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 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链接僵死。

  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 打赏
    打赏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包

打赏作者

mister-big

你的鼓励将是我创作的最大动力

¥1 ¥2 ¥4 ¥6 ¥10 ¥20
扫码支付:¥1
获取中
扫码支付

您的余额不足,请更换扫码支付或充值

打赏作者

实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值