jvm参数造成http请求Read time out

问题描述

线上部署的代码，部署在测试环境突然抛出接口请求Read time out的异常。查看线上日志，接口请求正常。重新启动，部署测试环境代码都没有效果，接口还是必现Read time out。

原因分析：

1. 排查网络原因

直接在测试环境服务器上执行使用curl命令执行http请求，接口正常返回，所以排查网络，第三方服务的原因。

2. 网络抓包

解决这类问题，最简单的方法就是抓一个正常的http请求包，抓一个Read time out异常的http请求包，对比两个的报文。但是事与愿违，容器环境禁用tcpdump命令，也就抓不了包。

3. 本地代码debug

启动本地代码连接测试环境配置，再出发相同的请求，接口返回正常。

4. 调整日志等级

项目统一使用spring cloud体系微服务架构，将日志等级该为debug，日志会打印一些http请求信息。观查到报错前的http请求日志如下：

2022-12-05 09:47:21.209 DEBUG 1 --- [http-nio-8080-exec-44] s.n.www.protocol.http.HttpURLConnection  : [TxId : xxx-1^1670143309480^7363 , SpanId : 1300305726613613085] sun.net.www.MessageHeader@11ef701319 pairs: 
{GET /xxxx/audiorid?recordId=9776d4f1-8b89-488a-b00c-cd430f39c003&recordDate=1670146625251 HTTP/1.1: null}
{Accept: application/octet-stream, application/json, application/*+json, */*}
{System-Id: xxxapi}
{sign: xxxxxxxxxxxx}
{Sign-Type: RSA}
{Sign-Timestamp: 1670204841194}
{Content-Type: application/x-www-form-urlencoded}
{Content-Length: 135}
{request-source-app: xxxapi}
{Pinpoint-TraceID: xxx-1^1670143309480^7363}
{Pinpoint-SpanID: 3740963636577534541}
{Pinpoint-pSpanID: 1300305726613613085}
{Pinpoint-Flags: 0}{Pinpoint-pAppName: xxxapi}
{Pinpoint-pAppType: 1210}
{Pinpoint-Host: xxx.com}
{User-Agent: Java/1.8.0_231}
{Host: xxxxx.com}
{Connection: keep-alive}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

因为本接口Method是GET，Content-Length应该为0，但是日志缺显示为135

5. 排查代码

http代码是基于restTemplate封装抽象统一实现的，以下是执行get请求的抽象方法：

public String executeGet(String systemName, String requestUrl, Map<String,Object> params, Map<String,Object> headerParams){
	HttpEntity<MutiValueMap<String, String>> entity = RestHttpUtils.getEntity(params, headerParams);
	return execute(systemName, requestUrl, HttpMethod.GET, entity, params);
}
1
2
3
4

其中装换entity有点问题

public static HttpEntity<MultiValueMap<String,String>> getEntity(Map<String,Object> params, Map<String,Object> headerParams){
	MultiValueMap<String,String> mvm = getMultiValueMap(params);
	HttpHeaders headers = getHeaders(headersParams);
	return new HttpEntity<MultiValueMap<String,String>>(mvm, headers);
}
1
2
3
4
5

在HttpEntity中，param被赋值给body，get请求中的param应该是queryParam，不应该在body中。现在赋值到Body，那么Content-Length就会有值。

public HttpEntity(@Nullable T body, @Nullable MultiValueMap<String, String> headers) {
		this.body = body;
		this.headers = HttpHeaders.readOnlyHttpHeaders(headers != null ? headers : new HttpHeaders());
	}
1
2
3
4

Content-Length在restTemplate#doExecute中进行赋值

protected <T> T doExecute(URI url, @Nullable HttpMethod method, @Nullable RequestCallback requestCallback,
	@Nullable ResponseExtractor<T> responseExtractor) throws RestClientException {

	Assert.notNull(url, "URI is required");
	Assert.notNull(method, "HttpMethod is required");
	ClientHttpResponse response = null;
	try {
		ClientHttpRequest request = createRequest(url, method);
		if (requestCallback != null) {
			requestCallback.doWithRequest(request);
		}
		response = request.execute();
		handleResponse(url, method, response);
		return (responseExtractor != null ? responseExtractor.extractData(response) : null);
	}
	catch (IOException ex) {
		String resource = url.toString();
		String query = url.getRawQuery();
		resource = (query != null ? resource.substring(0, resource.indexOf('?')) : resource);
		throw new ResourceAccessException("I/O error on " + method.name() +
				" request for \"" + resource + "\": " + ex.getMessage(), ex);
	}
	finally {
		if (response != null) {
			response.close();
		}
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28

具体见requestCallback.doWithRequest(request)，有body有值，所以Content-Length 没有赋值为0，而是在converter中序列化body并赋值。

public void doWithRequest(ClientHttpRequest httpRequest) throws IOException {
		super.doWithRequest(httpRequest);
		Object requestBody = this.requestEntity.getBody();
		if (requestBody == null) {
			HttpHeaders httpHeaders = httpRequest.getHeaders();
			HttpHeaders requestHeaders = this.requestEntity.getHeaders();
			if (!requestHeaders.isEmpty()) {
				requestHeaders.forEach((key, values) -> httpHeaders.put(key, new ArrayList<>(values)));
			}
			if (httpHeaders.getContentLength() < 0) {
				httpHeaders.setContentLength(0L);
			}
		}
		else {
			Class<?> requestBodyClass = requestBody.getClass();
			Type requestBodyType = (this.requestEntity instanceof RequestEntity ?
					((RequestEntity<?>)this.requestEntity).getType() : requestBodyClass);
			HttpHeaders httpHeaders = httpRequest.getHeaders();
			HttpHeaders requestHeaders = this.requestEntity.getHeaders();
			MediaType requestContentType = requestHeaders.getContentType();
			for (HttpMessageConverter<?> messageConverter : getMessageConverters()) {
				if (messageConverter instanceof GenericHttpMessageConverter) {
					GenericHttpMessageConverter<Object> genericConverter =
							(GenericHttpMessageConverter<Object>) messageConverter;
					if (genericConverter.canWrite(requestBodyType, requestBodyClass, requestContentType)) {
						if (!requestHeaders.isEmpty()) {
							requestHeaders.forEach((key, values) -> httpHeaders.put(key, new ArrayList<>(values)));
						}
						logBody(requestBody, requestContentType, genericConverter);
						genericConverter.write(requestBody, requestBodyType, requestContentType, httpRequest);
						return;
					}
				}
				else if (messageConverter.canWrite(requestBodyClass, requestContentType)) {
					if (!requestHeaders.isEmpty()) {
						requestHeaders.forEach((key, values) -> httpHeaders.put(key, new ArrayList<>(values)));
					}
					logBody(requestBody, requestContentType, messageConverter);
					((HttpMessageConverter<Object>) messageConverter).write(
							requestBody, requestContentType, httpRequest);
					return;
				}
			}
			String message = "No HttpMessageConverter for " + requestBodyClass.getName();
			if (requestContentType != null) {
				message += " and content type \"" + requestContentType + "\"";
			}
			throw new RestClientException(message);
		}
	}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50

body的数据类型是MultiValueMap

public void write(MultiValueMap<String, ?> map, @Nullable MediaType contentType, HttpOutputMessage outputMessage)
			throws IOException, HttpMessageNotWritableException {

	if (isMultipart(map, contentType)) {
		writeMultipart((MultiValueMap<String, Object>) map, contentType, outputMessage);
	}
	else {
		writeForm((MultiValueMap<String, Object>) map, contentType, outputMessage);
	}
}
	
private void writeForm(MultiValueMap<String, Object> formData, @Nullable MediaType contentType,
			HttpOutputMessage outputMessage) throws IOException {

	contentType = getFormContentType(contentType);
	outputMessage.getHeaders().setContentType(contentType);

	Charset charset = contentType.getCharset();
	Assert.notNull(charset, "No charset"); // should never occur

	byte[] bytes = serializeForm(formData, charset).getBytes(charset);
	outputMessage.getHeaders().setContentLength(bytes.length);

	if (outputMessage instanceof StreamingHttpOutputMessage) {
		StreamingHttpOutputMessage streamingOutputMessage = (StreamingHttpOutputMessage) outputMessage;
		streamingOutputMessage.setBody(outputStream -> StreamUtils.copy(bytes, outputStream));
	}
	else {
		StreamUtils.copy(bytes, outputMessage.getBody());
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31

虽然在这里进行赋值，但是代码一直以来缺正常运行。继续跟踪restTemplate代码。restTemplate第一层使用的是InterceptingClientHttpRequest，使用pipeline的模式，支持对http请求拓展。

protected final ClientHttpResponse executeInternal(HttpHeaders headers, byte[] bufferedOutput) throws IOException {
	InterceptingRequestExecution requestExecution = new InterceptingRequestExecution();
	return requestExecution.execute(this, bufferedOutput);
}
private class InterceptingRequestExecution implements ClientHttpRequestExecution {

	private final Iterator<ClientHttpRequestInterceptor> iterator;

	public InterceptingRequestExecution() {
		this.iterator = interceptors.iterator();
	}

	@Override
	public ClientHttpResponse execute(HttpRequest request, byte[] body) throws IOException {
		if (this.iterator.hasNext()) {
			ClientHttpRequestInterceptor nextInterceptor = this.iterator.next();
			return nextInterceptor.intercept(request, body, this);
		}
		else {
			HttpMethod method = request.getMethod();
			Assert.state(method != null, "No standard HTTP method");
			ClientHttpRequest delegate = requestFactory.createRequest(request.getURI(), method);
			request.getHeaders().forEach((key, value) -> delegate.getHeaders().addAll(key, value));
			if (body.length > 0) {
				if (delegate instanceof StreamingHttpOutputMessage) {
					StreamingHttpOutputMessage streamingOutputMessage = (StreamingHttpOutputMessage) delegate;
					streamingOutputMessage.setBody(outputStream -> StreamUtils.copy(body, outputStream));
				}
				else {
					StreamUtils.copy(body, delegate.getBody());
				}
			}
			return delegate.execute();
		}
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36

真正执行http请求的是SimpleBufferingClientHttpRequest

@Override
protected ClientHttpResponse executeInternal(HttpHeaders headers, byte[] bufferedOutput) throws IOException {
	addHeaders(this.connection, headers);
	// JDK <1.8 doesn't support getOutputStream with HTTP DELETE
	if (getMethod() == HttpMethod.DELETE && bufferedOutput.length == 0) {
		this.connection.setDoOutput(false);
	}
	if (this.connection.getDoOutput() && this.outputStreaming) {
		this.connection.setFixedLengthStreamingMode(bufferedOutput.length);
	}
	this.connection.connect();
	if (this.connection.getDoOutput()) {
		FileCopyUtils.copy(bufferedOutput, this.connection.getOutputStream());
	}
	else {
		// Immediately trigger the request in a no-output scenario as well
		this.connection.getResponseCode();
	}
	return new SimpleClientHttpResponse(this.connection);
}

static void addHeaders(HttpURLConnection connection, HttpHeaders headers) {
	String method = connection.getRequestMethod();
	if (method.equals("PUT") || method.equals("DELETE")) {
		if (!StringUtils.hasText(headers.getFirst(HttpHeaders.ACCEPT))) {
			// Avoid "text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"
			// from HttpUrlConnection which prevents JSON error response details.
			headers.set(HttpHeaders.ACCEPT, "*/*");
		}
	}
	headers.forEach((headerName, headerValues) -> {
		if (HttpHeaders.COOKIE.equalsIgnoreCase(headerName)) {  // RFC 6265
			String headerValue = StringUtils.collectionToDelimitedString(headerValues, "; ");
			connection.setRequestProperty(headerName, headerValue);
		}
		else {
			for (String headerValue : headerValues) {
				String actualHeaderValue = headerValue != null ? headerValue : "";
				connection.addRequestProperty(headerName, actualHeaderValue);
			}
		}
	});
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43

其中addHeaders(this.connection, headers)就是对header进行处理的地方，这里的connection就是HttpURLConnection

public synchronized void addRequestProperty(String var1, String var2) {
       if (!this.connected && !this.connecting) {
           if (var1 == null) {
               throw new NullPointerException("key is null");
           } else {
               if (this.isExternalMessageHeaderAllowed(var1, var2)) {
                   this.requests.add(var1, var2);
                   if (!var1.equalsIgnoreCase("Content-Type")) {
                       this.userHeaders.add(var1, var2);
                   }
               }

           }
       } else {
           throw new IllegalStateException("Already connected");
       }
   }
private boolean isExternalMessageHeaderAllowed(String var1, String var2) {
       this.checkMessageHeader(var1, var2);
       return !this.isRestrictedHeader(var1, var2);
   }
private boolean isRestrictedHeader(String var1, String var2) {
       if (allowRestrictedHeaders) {
           return false;
       } else {
           var1 = var1.toLowerCase();
           if (restrictedHeaderSet.contains(var1)) {
               return !var1.equals("connection") || !var2.equalsIgnoreCase("close");
           } else {
               return var1.startsWith("sec-");
           }
       }
   }
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33

注意这里有个isExternalMessageHeaderAllowed判断，条件成立的情况下，才往this.requests中添加header。

static {
      String var0 = (String)AccessController.doPrivileged(new GetPropertyAction("http.agent"));
       if (var0 == null) {
           var0 = "Java/" + version;
       } else {
           var0 = var0 + " Java/" + version;
       }

       userAgent = var0;
       String var1 = getNetProperty("jdk.http.auth.tunneling.disabledSchemes");
       disabledTunnelingSchemes = schemesListToSet(var1);
       var1 = getNetProperty("jdk.http.auth.proxying.disabledSchemes");
       disabledProxyingSchemes = schemesListToSet(var1);
       validateProxy = (Boolean)AccessController.doPrivileged(new GetBooleanAction("http.auth.digest.validateProxy"));
       validateServer = (Boolean)AccessController.doPrivileged(new GetBooleanAction("http.auth.digest.validateServer"));
       enableESBuffer = (Boolean)AccessController.doPrivileged(new GetBooleanAction("sun.net.http.errorstream.enableBuffering"));
       timeout4ESBuffer = (Integer)AccessController.doPrivileged(new GetIntegerAction("sun.net.http.errorstream.timeout", 300));
       if (timeout4ESBuffer <= 0) {
           timeout4ESBuffer = 300;
       }

       bufSize4ES = (Integer)AccessController.doPrivileged(new GetIntegerAction("sun.net.http.errorstream.bufferSize", 4096));
       if (bufSize4ES <= 0) {
           bufSize4ES = 4096;
       }

       allowRestrictedHeaders = (Boolean)AccessController.doPrivileged(new GetBooleanAction("sun.net.http.allowRestrictedHeaders"));
       if (!allowRestrictedHeaders) {
           restrictedHeaderSet = new HashSet(restrictedHeaders.length);

           for(int var2 = 0; var2 < restrictedHeaders.length; ++var2) {
               restrictedHeaderSet.add(restrictedHeaders[var2].toLowerCase());
           }
       } else {
           restrictedHeaderSet = null;
       }

       EXCLUDE_HEADERS = new String[]{"Proxy-Authorization", "Authorization"};
       EXCLUDE_HEADERS2 = new String[]{"Proxy-Authorization", "Authorization", "Cookie", "Cookie2"};
       logger = PlatformLogger.getLogger("sun.net.www.protocol.http.HttpURLConnection");
   }
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41

最为关键的就是allowRestrictedHeaders根据sun.net.http.allowRestrictedHeaders参数读取的，一开始在pinpoint上面看应用的参数没有设置这个值，所以又浪费了一些时间，最终使用jinfo命令看到测试环境这个配置项为true，而开发环境是false。

解决方案：

简单的解决方法就是启动的时候将sun.net.http.allowRestrictedHeaders配置为false，后面将queryParam赋值给body的代码去掉。