箱猫日和

[java]apache httpclient timeout waiting for connection

本文是公司内一个问题的分析记录。涉及的框架为apache的commons-httpclient 3.x。

问题特征

  • 无法从连接池中获取连接，异常描述为timeout waiting for connection
  • netstat看到连接状态为CLOSE_WAIT
  • 目标服务器ping得通，甚至curl等方式亦可以获取结果

看到这些特征的，请怀疑你的代码是否没有releaseConnection。
本次分析的存在bug的代码，已去除业务相关信息。

try {
  int statuCode = client.executeMethod(method);
  if (statuCode == HttpStatus.SC_OK) {
    return method.getResponseBody();
  }
} catch (IOException e) {
  e.printStackTrace();
} finally {
  // required
  // method.releaseConnection();
}

问题位于第三行到第五行。判断了响应码之后再决定是否getResponseBody，这里会造成连接泄露。
假如你按照例程补上了method.releaseConnection，那就不会造成泄露。
这里可能会有人反对，为什么我没加releaseConnection的代码运行了很长时间都没有出现问题？
那我造一段可以凸显上面问题的代码

final DefaultConfig config = new DefaultConfig();
// a mock server returning 404 every time
config.setDomain("localhost:3000");
Runnable runnable = new Runnable() {

    @Override
    public void run() {
        sendRequest(config);
    }
};

int nThreads = 10;
Thread[] threads = new Thread[nThreads];
for (int i = 0; i < nThreads; i++) {
    threads[i] = new Thread(runnable);
    threads[i].start();
}

for (Thread thread : threads) {
    thread.join();
}

sendRequest(config);

这段代码造了这样一个场景

  1. 现有10个线程通过客户端访问目标服务器
  2. 之后有1个访问请求
  3. 目标服务器只返回404
  4. httpclient使用MultiThreadedHttpConnectionManager
  5. 最大连接数设置为10，与第一条中的数量一致

你会看到这段代码的执行日志

Thread-2 404 not found
Thread-0 404 not found
Thread-4 404 not found
Thread-7 404 not found
Thread-8 404 not found
Thread-5 404 not found
Thread-3 404 not found
Thread-9 404 not found
Thread-1 404 not found
Thread-6 404 not found
main Timeout waiting for connection

Thread-x是线程的名字，main就是主线程。我们的目标服务器localhost:3000处理非常快，10ms内返回，但是执行到最后一行代码时出现了timeout waiting for connection。事实上，上面的场景并不特殊，如果你的目标服务器上地址迁移了（导致404），你会发现你所有的客户端全部无法从连接池获取连接，是不是很恐怖？
在这里，大部分人应该都可以明白第一段的问题代码的严重性了，但是为什么原来的代码可以执行没有出现大范围无法获取连接的情况，即200下为什么不会出现问题？还有造成上面问题的原因是什么？

让我们使用例程代码来回答：

private static final Log log = LogFactory.getLog(HttpClientTest.class);

public static void main(String[] args) throws InterruptedException {
    HttpClientParams params = new HttpClientParams();
    params.setConnectionManagerClass(MultiThreadedHttpConnectionManager.class);
    HttpClient client = new HttpClient(params);
    getPage(client);
}

private static void getPage(HttpClient client) {
    GetMethod method = new GetMethod("http://xnnyygn.in");
    try {
        client.executeMethod(method);
        log.info("get response");
        method.getResponseBodyAsString();
    } catch (IOException e) {
        log.error("failed to get page", e);
    } finally {
        // method.releaseConnection();
    }
}

注意我把releaseConnection注释掉了。在开启了DEBUG级别日志之后，你可以看到日志中输出

17:28:15,998  DEBUG MultiThreadedHttpConnectionManager : HttpConnectionManager.getConnection:  config = HostConfiguration[host=http://xnnyygn.in], timeout = 0
17:28:15,999  DEBUG MultiThreadedHttpConnectionManager$ConnectionPool : Allocating new connection, hostConfig=HostConfiguration[host=http://xnnyygn.in]
17:28:16,003  DEBUG HttpConnection : Open connection to xnnyygn.in:80
17:28:19,866  DEBUG HttpMethodBase : Adding Host request header
17:28:20,063  INFO  HttpClientTest : get response
17:28:20,064  DEBUG HttpMethodBase : Buffering response body
17:28:20,067  DEBUG HttpMethodBase : Should NOT close connection in response to directive: keep-alive
17:28:20,067  DEBUG HttpConnection : Releasing connection back to connection manager.
17:28:20,068  DEBUG MultiThreadedHttpConnectionManager$ConnectionPool : Freeing connection, hostConfig=HostConfiguration[host=http://xnnyygn.in]

注意get response的位置，和之后的Releasing connection back to connection manager。代码中没有显示调用releaseConnection，但是连接被回收了。简单来说，这是getResponseBody和关联方法比如getResponseBodyAsString本身的特性。理论上获取了全部响应之后，你不太可能再从socket的input中读取数据了，所以connection的使命也完成了，可以销毁或者回收进入连接池了。你可以阅读httpclient的源码了解这一逻辑。另外还有根据rfc2612(http)不可能有body的响应码，比如304，遇到这种响应码，在executeMethod之后你的connection就被回收了。这些逻辑是httpclient内部在最小化connection的使用，尽快结束重型资源的使用的设计。但是这不代表你可以依赖这种特性。

另一方面，当你没有调用getResponseBody时，httpclient无法帮你关闭connection，必须你手动releaseConnection。这也是造成第二段代码中前10次请求没有关闭connection导致连接池被占满，第11次请求无法获取连接的原因。

到这里，相信大部分人应该都明白了。最开始的代码在不知道的情况下依赖了自动关闭connection这个特性，但是遇到非200的响应码时就没辙了。解决方法就是加上method.releaseConnection，就如例程一样。

小结一下，虽然是大家平时一直使用的httpclient，但是很多人还是存在误用。在你不了解的情况，务必严格按照例程的方式写代码，否则容易造成各种诡异的问题。

xnnyygn