HttpClientでのロギング(HttpClient3.0-rc3)

埋火/HttpClient/

2005-08-08T10:40+09:00 matsu

HttpClientでは,ロギングフレームワークを使用してログ出力できるようになっており,ログ出力詳細な設定可能なようなので試してみた.

概要
LoggingのSimpleLogによるログ出力
Log4jによるログ出力

概要

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を使用してログ出力するサンプルを作成してみた.

LoggingのSimpleLogによるログ出力

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

で設定が反映される.

Log4jによるログ出力

ログカテゴリの構成が大体分かれば,あとはログ出力機構の問題であって,あとは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
...省略...