Table of Contents
JBossAS の起動オプション org.apache.coyote.http11.DEFAULT_CONNECTION_TIMEOUT につい
て誤解があったので、メモしておきます。
まず、ドキュメントの説明。デフォルトタイムアウト値が60秒ですね。
org.apache.coyote.http11.DEFAULT_CONNECTION_TIMEOUT Default socket timeout. The default value is 60000 ms.
説明だけでよく分からない、最初はサーバサイトワーカスレッドの処理時間タイムアウト値 と理解しました。
テストアプリでタイムアウト時の動作を確認する。
+----------+ +----------------+
| SoapUI +------------+ テストアプリ |
+----------+ | |
+----------------+
| JBossAS 7.x |
+----------------+
SoapUIのリードタイムアウトを120秒に変更する、テストアプリに Thread.sleep(70 * 1000)
コードを仕込んで処理時間を長くする。これでタイムアウトになると考えたのですが、結果的に
タイムアウトせず、正常なレスポンスでした。これで、 DEFAULT_CONNECTION_TIMEOUT はワー
カスレッドのタイムアウト値ではないことが分かりました。
説明文にソケットのタイムアウト値であることが書かれたので telnet でソケット通信の各
stepの処理時間をあえて長くして動作状況を観測してみました。
- telnetでコネクションを貼る
- ヘッダを途中まで送信する
- 60秒待つこと
$ telnet localhost 8080 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. POST http://localhost:8080/testapp/HelloWorld HTTP/1.1 Connection: close Accept-Encoding: gzip,deflate Content-Type: text/xml;charset=UTF-8 SOAPAction: "sayHello" Content-Length: 318 Host: localhost:8080 ★ここで60秒を待つ Connection closed by foreign host.
step3のところで60秒後、サーバからfinパケットが送出されてコネクションが切れた。
DEFAULT_CONNECTION_TIMEOUT パラメータの意味が少し掴みました。
少し掘り下げて見たいので、コードリーディングして実装の概要を以下に紹介します。
1 DEFAULT_CONNECTION_TIMEOUTオプションの役割
JBossASのJava起動オプションで指定する
-Dorg.apache.coyote.http11.DEFAULT_CONNECTION_TIMEOUT=xxxxx オプションの値は最終的に
ソケット操作のブロックタイムアウト値 java.net.ServerSocket.setSoTimeout(xx) に反映さ
れる。
サーバ側で以下のソケット操作でブロックされる時間が指定時間より超えるとタイムアウトさせ る機能です。
ServerSocket.accept(); SocketInputStream.read(); DatagramSocket.receive();
例えば、HTTPヘッダ受信途中クライアント側がストール状態になり、
SocketInputStream.read() 処理がずっと待ち続けるには行けないので（FDのリソース枯渇に
なるかも知らない）、タイムアウトさせる必要があります。
2 JBossASの実装
org.apache.coyote.http11.Constants にデフォルト値が60秒で定義されている。
public final class Constants { ............... //★ここでJavaオプションから値を参照している public static final int DEFAULT_CONNECTION_TIMEOUT = Integer.valueOf(System.getProperty("org.apache.coyote.http11.DEFAULT_CONNECTION_TIMEOUT", "60000")).intValue(); .............
この値は以下の流れで、 JIoEndpoint クラスの soTimeout 属性に反映される。
1.org.jboss.as.web.WebConnectorService.start() 2. org.apache.catalina.connector.Connectorのコンストラクタ処理 3. apache.coyote.http11.Http11Protocolのコンストラクタ処理 4. org.apache.tomcat.util.net.JIoEndpoint.setSoTimeout(xx)
acceptor スレッドで新規コネクションをacceptしワーカスレッドに渡した後にワーカスレッ
ドの run 関数内 java.net.ServerSocket.setSoTimeout(xx) 関数を呼び出し、値を設定す
る。具体的な流れは以下となります。
1. org.apache.tomcat.util.net.JIoEndpoint.Acceptor.run() 2. org.apache.tomcat.util.net.JIoEndpoint.processSocket(socket) 3. ★ここで分岐がある、別途検証する 4. org.apache.tomcat.util.net.JIoEndpoint.Workerが起動される 5. org.apache.tomcat.util.net.JIoEndpoint.Worker.run() 6. org.apache.tomcat.util.net.JIoEndpoint.setSocketOptions(socket) 7. socket.setSoTimeout(soTimeout);
3 タイムアウト時の挙動
3.1 HTTPヘッダー受信途中タイムアウトの場合
Cookiesが大きいの場合、HTTPヘッダー電文が複数パケットに分割する可能性が高い。 ネットワーク障害でHTTPヘッダー受信途中でタイムアウトが起きた場合サーバからFINパケット よりコネクションが切断される。
以下はHTTPヘッダー受信処理のコードの抜粋です。タイムアウトが起きた場合★３の部分が実 行される。 エラーログを吐かずに処理が終了してしまう。
org.apache.coyote.http11.Http11Processor
/** * Process pipelined HTTP requests on the specified socket. * * @param socket Socket from which the HTTP requests will be read * and the HTTP responses will be written. * * @throws IOException error during an I/O operation */ public SocketState process(Socket socket) throws IOException { RequestInfo rp = request.getRequestProcessor(); rp.setStage(org.apache.coyote.Constants.STAGE_PARSE); //★★★０ いろいろ省略する while (!error && keepAlive && !event) { // Parsing the request header try { if (!disableUploadTimeout && keptAlive) { if (keepAliveTimeout > 0) { socket.setSoTimeout(keepAliveTimeout); } else if (soTimeout > 0) { socket.setSoTimeout(soTimeout); } } //★★★１ HTTPヘッダー１行目の受信処理 inputBuffer.parseRequestLine(); request.setStartTime(System.currentTimeMillis()); keptAlive = true; if (!disableUploadTimeout) { socket.setSoTimeout(timeout); } //★★★２ HTTPヘッダーの受信処理 inputBuffer.parseHeaders(); } catch (IOException e) { //★★★３ ネットワークIOエラー時、処理を止める error = true; break; } catch (Throwable t) { CoyoteLogger.HTTP_LOGGER.errorParsingHeader(t); // 400 - Bad Request response.setStatus(400); error = true; }
★３の部分にエラー出力処理を追加しらた、タイムアウト時下記のエラートレースが出力され た。
19:23:49,020 ERROR [stderr] (http-/0.0.0.0:8080-1) java.net.SocketTimeoutException: Read timed out 19:23:49,020 ERROR [stderr] (http-/0.0.0.0:8080-1) at java.net.SocketInputStream.socketRead0(Native Method) 19:23:49,021 ERROR [stderr] (http-/0.0.0.0:8080-1) at java.net.SocketInputStream.read(SocketInputStream.java:152) 19:23:49,021 ERROR [stderr] (http-/0.0.0.0:8080-1) at java.net.SocketInputStream.read(SocketInputStream.java:122) 19:23:49,027 ERROR [stderr] (http-/0.0.0.0:8080-1) at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:721) 19:23:49,028 ERROR [stderr] (http-/0.0.0.0:8080-1) at org.apache.coyote.http11.InternalInputBuffer.parseHeader(InternalInputBuffer.java:660) 19:23:49,028 ERROR [stderr] (http-/0.0.0.0:8080-1) at org.apache.coyote.http11.InternalInputBuffer.parseHeaders(InternalInputBuffer.java:516) 19:23:49,029 ERROR [stderr] (http-/0.0.0.0:8080-1) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:828) 19:23:49,032 ERROR [stderr] (http-/0.0.0.0:8080-1) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653) 19:23:49,033 ERROR [stderr] (http-/0.0.0.0:8080-1) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:920) 19:23:49,034 ERROR [stderr] (http-/0.0.0.0:8080-1) at java.lang.Thread.run(Thread.java:745)
3.2 リクエスト本文受信途中タイムアウトの場合
以下、HTTP本文読み取り処理(HTTP POST)でブロックタイムアウトが起きた時のサーバログです。
Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) [rt.jar:1.7.0_65] at java.net.SocketInputStream.read(SocketInputStream.java:152) [rt.jar:1.7.0_65] at java.net.SocketInputStream.read(SocketInputStream.java:122) [rt.jar:1.7.0_65] at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:737) [jbossweb-7.2.2.Final-redhat-1.jar:7.2.2.Final-redhat-1] at org.apache.coyote.http11.InternalInputBuffer$InputStreamInputBuffer.doRead(InternalInputBuffer.java:767) [jbossweb-7.2.2.Final-redhat-1.jar:7.2.2.Final-redhat-1] at org.apache.coyote.http11.filters.IdentityInputFilter.doRead(IdentityInputFilter.java:116) [jbossweb-7.2.2.Final-redhat-1.jar:7.2.2.Final-redhat-1] at org.apache.coyote.http11.InternalInputBuffer.doRead(InternalInputBuffer.java:697) [jbossweb-7.2.2.Final-redhat-1.jar:7.2.2.Final-redhat-1] at org.apache.coyote.Request.doRead(Request.java:438) [jbossweb-7.2.2.Final-redhat-1.jar:7.2.2.Final-redhat-1] at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:341) [jbossweb-7.2.2.Final-redhat-1.jar:7.2.2.Final-redhat-1] ... 47 more
4 注意書き
org.apache.coyote.http11.DEFAULT_CONNECTION_TIMEOUT が次のように誤解されることもあ
るので、要注意です。
ワーカスレッドの実行時間のタイムアウト値
あくまでもソケットのブロックタイムアウト値なので、アプリのロジック処理時と関係ないで す。主にHTTPヘッダとHTTP本文の読み取り処理のブロック時間を監視するために使われる。