问题描述
线上部署的代码,部署在测试环境突然抛出接口请求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}
因为本接口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);
}
其中装换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);
}
在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());
}
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();
}
}
}
具体见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);
}
}
body的数据类型是MultiValueMap<String,String,对应的converter是AllEncompassingFormHttpMessageConverter
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());
}
}
虽然在这里进行赋值,但是代码一直以来缺正常运行。继续跟踪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();
}
}
}
真正执行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);
}
}
});
}
其中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-");
}
}
}
注意这里有个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");
}
最为关键的就是allowRestrictedHeaders根据sun.net.http.allowRestrictedHeaders参数读取的,一开始在pinpoint上面看应用的参数没有设置这个值,所以又浪费了一些时间,最终使用jinfo命令看到测试环境这个配置项为true,而开发环境是false。
解决方案:
简单的解决方法就是启动的时候将sun.net.http.allowRestrictedHeaders配置为false,后面将queryParam赋值给body的代码去掉。