ファイヤープロジェクト
HttpClientでのロギング(HttpClient3.0-rc3)
2005-08-08T10:40+09:00   matsu
HttpClientでは,ロギングフレームワークを使用してログ出力できるようになっており,ログ出力詳細な設定可能なようなので試してみた.
HttpClientの依存パッケージの一つに,Jakarta CommonsのLoggingがあった. HttpClientはこれを使用してログ出力をしており,したがって実際のログ出力モジュールとして,以下などから選択することができる.
  • LoggingのSimpleLog
  • Log4j
  • java.util.logging(JDK 1.4以降)
また,HttpClientが出力するログは,大きく二種類に分類される.
Context
Httpリクエストを発行するHttpClientの内部動作情報を含む. 各クラスは,そのFQCNによって名前づけられるログを持つ. 設定ではこの名前毎にログレベルや,ログ出力実装によってはログ出力先などを指定できる. 例えばクラスHttpClientはorg.apache.commons.httpclient.HttpClientという名前のログを持つ. この名前は,FQCNによって階層化されたログカテゴリであり,例えばorg.apache.commons.httpclientに対して設定すると,このパッケージ配下の全クラスのログにその設定が反映される.
Wire
サーバとの全HTTP電文のやりとりがログ出力される. バイナリフォーマットも含み,大量のログデータが出力されるので,デバッグの場合にのみ有用でらしい. デバッグの観点からすると,HTTPの本文のデータは普通ヘッダの情報ほど重要でない. そこで,二種類のログカテゴリがある.
  • httpclient.wire.content
  • httpclient.wire.header
HTTP本文のログには前者を,ヘッダのみの場合には後者を設定する.
こらを踏まえた推奨設定が本家に記述されている. 本頁ではSimpleLogとLog4jを使用してログ出力するサンプルを作成してみた.
SimpleLogでは,System.errにログ出力する. プログラム中で以下のように設定する.
System.setProperty("org.apache.commons.logging.Log", "org.apache.commons.logging.impl.SimpleLog");
System.setProperty("org.apache.commons.logging.simplelog.showdatetime", "true");
System.setProperty("org.apache.commons.logging.simplelog.log.httpclient.wire.header", "debug");
System.setProperty("org.apache.commons.logging.simplelog.log.org.apache.commons.httpclient", "debug");
もちろん-Dにて設定してもよい. 今回のサンプルでは,antタスクにて設定してみた(※).
<target name="run" depends="jar"
        description="Run application.">
  <!-- Log4jが動かないように,Log4jの設定ファイルを消す -->
  <delete file="${build.main}/log4j.xml"/>
  <java dir="${build.main}" classname="${application.class}" fork="yes">
    <arg value="http://www.example.com" />
    <sysproperty key="org.apache.commons.logging.Log" value="org.apache.commons.logging.impl.SimpleLog" />
    <sysproperty key="org.apache.commons.logging.simplelog.showdatetime" value="true" />
    <sysproperty key="org.apache.commons.logging.simplelog.log.httpclient.wire.content" value="off" />
    <sysproperty key="org.apache.commons.logging.simplelog.log.httpclient.wire.header" value="debug" />
    <sysproperty key="org.apache.commons.logging.simplelog.log.org.apache.commons.httpclient" value="debug" />
    <classpath>
      <pathelement path="${build.main}" />
      <fileset dir="lib">
        <include name="*.jar" />
      </fileset>
    </classpath>
  </java>
</target>
要素syspropertyにてログ出力設定している. 上記設定では,以下を設定している.
org.apache.commons.logging.Log
ログ出力クラス
org.apache.commons.logging.simplelog.showdatetime
ログに日付を出力するか.
org.apache.commons.logging.simplelog.log.httpclient.wire.header
Wireログのヘッダのログレベル.
org.apache.commons.logging.simplelog.log.org.apache.commons.httpclient
Contextログのログレベル.
以下に実行結果を示す.
...省略...
     [java] 2005/08/08 10:06:41:212 JST [DEBUG] DefaultHttpParams
  - Set parameter http.useragent = Jakarta Commons-HttpClient/3.0-rc3
     [java] 2005/08/08 10:06:41:217 JST [DEBUG] DefaultHttpParams - Set parameter http.protocol.version = HTTP/1.1
     [java] 2005/08/08 10:06:41:221 JST [DEBUG] DefaultHttpParams
  - Set parameter http.connection-manager.class = class org.apache.commons.httpclient.SimpleHttpConnectionManager
     [java] 2005/08/08 10:06:41:222 JST [DEBUG] DefaultHttpParams - Set parameter http.protocol.cookie-policy = rfc2109
     [java] 2005/08/08 10:06:41:222 JST [DEBUG] DefaultHttpParams - Set parameter http.protocol.element-charset = US-ASCII
     [java] 2005/08/08 10:06:41:223 JST [DEBUG] DefaultHttpParams - Set parameter http.protocol.content-charset = ISO-8859-1
     [java] 2005/08/08 10:06:41:227 JST [DEBUG] DefaultHttpParams
  - Set parameter http.method.retry-handler  = org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@b5f53a
     [java] 2005/08/08 10:06:41:229 JST [DEBUG] DefaultHttpParams
  - Set parameter http.dateparser.patterns
   = [EEE, dd MMM yyyy HH:mm:ss zzz, EEEE, dd-MMM-yy HH:mm:ss zzz, EEE MMM d HH:mm:ss yyyy, EEE, ...省略...
     [java] 2005/08/08 10:06:41:336 JST [DEBUG] DefaultHttpParams
  - Set parameter http.method.retry-handler = org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@12d7a10
     [java] 2005/08/08 10:06:41:377 JST [DEBUG] HttpConnection - Open connection to www.example.com:80
     [java] 2005/08/08 10:06:41:551 JST [DEBUG] header - >> "GET / HTTP/1.1[\r][\n]"
     [java] 2005/08/08 10:06:41:553 JST [DEBUG] HttpMethodBase - Adding Host request header
     [java] 2005/08/08 10:06:41:583 JST [DEBUG] header - >> "User-Agent: Jakarta Commons-HttpClient/3.0-rc3[\r][\n]"
     [java] 2005/08/08 10:06:41:584 JST [DEBUG] header - >> "Host: www.example.com[\r][\n]"
     [java] 2005/08/08 10:06:41:588 JST [DEBUG] header - >> "[\r][\n]"
     [java] 2005/08/08 10:06:41:768 JST [DEBUG] header - << "HTTP/1.1 200 OK[\r][\n]"
     [java] 2005/08/08 10:06:41:772 JST [DEBUG] header - << "Date: Mon, 08 Aug 2005 01:06:42 GMT[\r][\n]"
     [java] 2005/08/08 10:06:41:772 JST [DEBUG] header - << "Server: Apache/1.3.27 (Unix)  (Red-Hat/Linux)[\r][\n]"
     [java] 2005/08/08 10:06:41:773 JST [DEBUG] header - << "Last-Modified: Wed, 08 Jan 2003 23:11:55 GMT[\r][\n]"
     [java] 2005/08/08 10:06:41:773 JST [DEBUG] header - << "ETag: "3f80f-1b6-3e1cb03b"[\r][\n]"
     [java] 2005/08/08 10:06:41:773 JST [DEBUG] header - << "Accept-Ranges: bytes[\r][\n]"
     [java] 2005/08/08 10:06:41:773 JST [DEBUG] header - << "Content-Length: 438[\r][\n]"
     [java] 2005/08/08 10:06:41:773 JST [DEBUG] header - << "Connection: close[\r][\n]"
     [java] 2005/08/08 10:06:41:773 JST [DEBUG] header - << "Content-Type: text/html[\r][\n]"
     [java] statusCode = 200
     [java] headers[0] = Date: Mon, 08 Aug 2005 01:06:42 GMT
     [java] 2005/08/08 10:06:41:777 JST [DEBUG] HttpMethodBase - Buffering response body

     [java] headers[1] = Server: Apache/1.3.27 (Unix)  (Red-Hat/Linux)

     [java] headers[2] = Last-Modified: Wed, 08 Jan 2003 23:11:55 GMT

     [java] headers[3] = ETag: "3f80f-1b6-3e1cb03b"

     [java] headers[4] = Accept-Ranges: bytes

     [java] headers[5] = Content-Length: 438

     [java] headers[6] = Connection: close
     [java] 2005/08/08 10:06:41:779 JST [DEBUG] HttpMethodBase - Should close connection in response to directive: close

     [java] headers[7] = Content-Type: text/html

     [java] 2005/08/08 10:06:41:780 JST [DEBUG] HttpConnection - Releasing connection back to connection manager.
     [java] 2005/08/08 10:06:41:786 JST [DEBUG] HttpMethodBase - Default charset used: ISO-8859-1
...省略...
各行先頭の[java]はantによる出力である. カテゴリがheaderとなっている部分がWireログでり,カテゴリがそれ以外のクラス名らしきものになっているのがContextログである. Wireログは,今回はheaderとしたが,contentとした場合,カテゴリはcontentと出力される.
※ 本頁のサンプルは,
$ ant run
にてSimpleLogによるログ出力,
$ java -jar httpclient ...
にてLog4jによるログ出力がされるようになっている. 設定ファイルはディレクトリconf以下にある. SimpleLogはbuild.xml.eucjpを編集後,
$ ant n2abuildxml
で設定が反映される. Log4jはlog4j.xml.eucjpを編集後,
$ ant jar
で設定が反映される.
ログカテゴリの構成が大体分かれば,あとはログ出力機構の問題であって,あとはSimpleLogの場合とさほど変わらない. Log4jの設定は,プロパティファイルによる設定かXMLファイルによる設定のいずれかである. 前者は本家にあるので,サンプルではlog4j.xmlによる設定を試してみた.
やはりカテゴリとして,
  • httpclient.wire.content
  • httpclient.wire.header
  • org.apache.commons.httpclientおよびその配下のクラス.
がある. では,実行結果を以下に示す.
$> java -jar httpclientsample.jar http://www.example.com
2005-08-08 10:33:37,381 DEBUG [main] header Wire 69 - >> "GET / HTTP/1.1[\r][\n]"
2005-08-08 10:33:37,412 DEBUG [main] header Wire 69 - >> "User-Agent: Jakarta Commons-HttpClient/3.0-rc3[\r][\n]"
2005-08-08 10:33:37,420 DEBUG [main] header Wire 69 - >> "Host: www.example.com[\r][\n]"
2005-08-08 10:33:37,421 DEBUG [main] header Wire 69 - >> "[\r][\n]"
2005-08-08 10:33:37,604 DEBUG [main] header Wire 69 - << "HTTP/1.1 200 OK[\r][\n]"
2005-08-08 10:33:37,607 DEBUG [main] header Wire 69 - << "Date: Mon, 08 Aug 2005 01:33:38 GMT[\r][\n]"
2005-08-08 10:33:37,608 DEBUG [main] header Wire 69 - << "Server: Apache/1.3.27 (Unix)  (Red-Hat/Linux)[\r][\n]"
2005-08-08 10:33:37,609 DEBUG [main] header Wire 69 - << "Last-Modified: Wed, 08 Jan 2003 23:11:55 GMT[\r][\n]"
2005-08-08 10:33:37,609 DEBUG [main] header Wire 69 - << "ETag: "3f80f-1b6-3e1cb03b"[\r][\n]"
2005-08-08 10:33:37,610 DEBUG [main] header Wire 69 - << "Accept-Ranges: bytes[\r][\n]"
2005-08-08 10:33:37,611 DEBUG [main] header Wire 69 - << "Content-Length: 438[\r][\n]"
2005-08-08 10:33:37,611 DEBUG [main] header Wire 69 - << "Connection: close[\r][\n]"
2005-08-08 10:33:37,612 DEBUG [main] header Wire 69 - << "Content-Type: text/html[\r][\n]"
statusCode = 200
headers[0] = Date: Mon, 08 Aug 2005 01:33:38 GMT

headers[1] = Server: Apache/1.3.27 (Unix)  (Red-Hat/Linux)

headers[2] = Last-Modified: Wed, 08 Jan 2003 23:11:55 GMT

headers[3] = ETag: "3f80f-1b6-3e1cb03b"

headers[4] = Accept-Ranges: bytes

headers[5] = Content-Length: 438

headers[6] = Connection: close

headers[7] = Content-Type: text/html
...省略...
matsu(C)
Since 2002
Mail to matsu