背景:同事发现我们系统和一个外部公司http交互消耗时间比较长,偶尔会达到10分多钟,但是明明设置了20s超时的呀。
于是我找到代码过来分析:
private String send(String param0, String requestXml) { CHANNEL_LOG.info("xxxx:" + requestXml); String response = null; org.apache.axis.client.Service ser = null; try { ser = new org.apache.axis.client.Service(); Call call = (Call) ser.createCall(); call.setTargetEndpointAddress(url); call.setOperationName(new QName(url, "dispatchCommand")); call.setTimeout(Integer.valueOf(20000));// 这里面超时时间设大点 Object result = call.invoke(new Object[] { param0, requestXml }); if(null == result){ LOGGER.error("xxx返回报文为空!!!!requestXml:" + requestXml); return null; } response = result.toString(); } catch (Exception e) { LOGGER.error("xxxx >>> send ERROR!", e); } CHANNEL_LOG.info("xxx响应报文:" + response); return response; }原来使用的是一个叫apache-axis的框架,静态的点进代码很理清楚,于是写个main函数debug跟进去。在Socket的connect、setSoTimeout方法处打上断点,很快搞清调用链。
连接超时和读超时的确设置的都是20s。把本地debug的请求地址故意改错,抛出timeout异常,也是20s左右。
奇怪呀,难道是封装里边还有其他耗时的地方或者其他的http请求?跟了半天代码,没看出个所以然。
笨啊,找错误日志啊,于是拉出线上那个时间点的错误日志,的确有:
线上错误日志:
AxisFault
faultCode: {http://schemas.xmlsoap.org/soap/envelope/}Server.userException
faultSubcode:
faultString: java.net.ConnectException: Connection timed out
faultActor:
faultNode:
faultDetail:
{http://xml.apache.org/axis/}stackTrace:java.net.ConnectException: Connection timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
at java.net.Socket.connect(Socket.java:529)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:570)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.<init>(SSLSocketImpl.java:371)
at com.sun.net.ssl.internal.ssl.SSLSocketFactoryImpl.createSocket(SSLSocketFactoryImpl.java:71)
at org.apache.axis.components.net.JSSESocketFactory.create(JSSESocketFactory.java:92)
at org.apache.axis.transport.http.HTTPSender.getSocket(HTTPSender.java:191)
at org.apache.axis.transport.http.HTTPSender.writeToSocket(HTTPSender.java:404)
at org.apache.axis.transport.http.HTTPSender.invoke(HTTPSender.java:138)
at org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.java:32)
at org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:118)
at org.apache.axis.SimpleChain.invoke(SimpleChain.java:83)
at org.apache.axis.client.AxisClient.invoke(AxisClient.java:165)
at org.apache.axis.client.Call.invokeEngine(Call.java:2784)
at org.apache.axis.client.Call.invoke(Call.java:2767)
at org.apache.axis.client.Call.invoke(Call.java:2443)
at org.apache.axis.client.Call.invoke(Call.java:2366)
at org.apache.axis.client.Call.invoke(Call.java:1812)
本地错误日志:
AxisFault
faultCode: {http://schemas.xmlsoap.org/soap/envelope/}Server.userException
faultSubcode:
faultString: java.net.SocketTimeoutException: connect timed out
faultActor:
faultNode:
faultDetail:
{http://xml.apache.org/axis/}stackTrace:java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:579)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.axis.components.net.DefaultSocketFactory.create(DefaultSocketFactory.java:153)
at org.apache.axis.components.net.DefaultSocketFactory.create(DefaultSocketFactory.java:120)
at org.apache.axis.transport.http.HTTPSender.getSocket(HTTPSender.java:191)
at org.apache.axis.transport.http.HTTPSender.writeToSocket(HTTPSender.java:404)
Disconnected from the target VM, address: '127.0.0.1:50856', transport: 'socket'
at org.apache.axis.transport.http.HTTPSender.invoke(HTTPSender.java:138)
at org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.java:32)
at org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:118)