アプリやミドルウェの動作の正常性確認や問題発生時の問題切り分けのために、HTTPリクエストやレスポンスのヘッダやボディを確認したい場合がある。Java系のアプリではApacheのHttpClientが使用されることが多いため、ここではApacheのHttpClientによる通信をダンプ(ロギング)する方法を説明します。
（ここではApache HttpClient 4.5を前提として説明します。HttpClientの場合、バージョンが変わるとAPI等が大きく変わる場合があるので、ここでの説明と異なる動作をする場合があります。）
目次
HttpClientのロギング
ログ出力内容の種類
大きく分けて次の3種類のログを出力できます。
後述のログ出力例の設定例のように、使用するログ名を指定することで出力内容を変更できます。これらのログ名を全て含むorg.apache.httpを使うと全てのログを出力できます。
| 種類 | 説明 | ログ名 |
|---|---|---|
| Context Logging (各クラスの内部動作) | HttpClientに含まれる各クラスの動作をログ出力します。ログを出力したいクラスの完全修飾クラス名を指定します。例えば、DefaultHttpClientのログを出力したい場合、org.apache.http.impl.client.DefaultHttpClientを指定します。HttpClientのクラスは慣例的にorg.apache.http.impl.clientというログ名を含んでいるので、このログ名を指定すれば全てのクラスのログを出力できます。 | org.apache.http.impl.client |
| Wire Logging (通信内容全て) | HTTPリクエスト/HTTPレスポンスのヘッダとボディを出力します。１回の通信毎に大量のログが出力されるので、ログの肥大化や性能劣化に注意が必要です。 | org.apache.http.wire |
| HTTP header Logging (HTTPヘッダのみ) | HTTPリクエスト/HTTPレスポンスのヘッダのみを出力します。 | org.apache.http.headers |
ログ出力先
HttpClientはログ出力にCommons Loggingを使用しており、Log4jやjava.util.Loggingへの出力の他に、Commons Loggingに含まれるSimpleLogを使ってログを出力できます。
SimpleLogは簡単に使用できるので、以降ではこのSimpleLogを使用する前提で説明します。
Log4j, java.util.Loggingを使用する場合は、HttpClientのリファレンスを参照のこと。
設定方法
SimpleLogを使ってログ出力する場合、システムプロパティ(Java起動時の-Dオプション)としてパラメータを指定するか、クラスパス上に配置された”simplelog.properties”ファイルで指定します。使用できるプロパティは次の通りです。
詳細はjavadocを参照のこと。
| プロパティ名(*1) | 説明 | 既定値 |
|---|---|---|
defaultlog | 既定のログレベル(*2) log.xxxxxで個別の指定がない限り、ここで指定したログレベル以上のログが出力されます。 | info |
log.xxxxx | ログ名xxxxxに対するログレベル(*2) 例えばlog.Xyz=traceと指定した場合、defaultLogの設定に関わらず、Xyzからのログはtrace以上を出力します。 | (既定のログレベル) |
showlogname | ログ名を出力するかを指定 下記showShortLognameの値によって出力形式が異なる。 | false |
showShortLogname | ログ名を出力する際、短縮表示するかを指定 trueの場合は”RequestAuthCache”、falseの場合は”org….protocol.RequestAuthCache”のように完全なログ名が出力される。 | true |
showdatetime | 日時を出力するかを指定 出力形式は下記dateTimeFormatで指定する。 | false |
dateTimeFormat | 日時出力時の書式を指定 (SimpleDateFormat書式) | yyyy/MM/dd HH:mm:ss:SSS zzz |
*1: 先頭に”
*2: ログレベルは”trace”, “debug”, “info”, “warn”, “error”, “fatal”のいずれか。
org.apache.commons.logging.simplelog.“を付ける前提です。*2: ログレベルは”trace”, “debug”, “info”, “warn”, “error”, “fatal”のいずれか。
（参考）
eclipseでアプリケーションとして実行時にシステムプロパティとしてパラメータを指定する場合は、実行対象のクラスファイルを右クリックし、[実行]-[実行の構成]で実行構成ウインドウを表示します。[Javaアプリケーション]を選択して必須事項を入力し、[引数]タブでシステムプロパティを指定します。
出力例
- HTTP POSTを行うサンプルプログラムを例題とし、ログ出力にはSimpleLogを使用する前提で、システムプロパティの設定例とログ出力例を記載します。
- 下記の設定例では、本来は”2019/07/14 22:52:49:716 JST [DEBUG]…”等の日時項目が出力されますが、便宜上記載を割愛しています。
- HTTPリクエスト(クライアント->サーバ)は”
>>“、HTTPレスポンス(クライアント<-サーバ)は"<<“で表現されています。
出力例1：ヘッダ＋コンテキスト
データ量が比較的多いボディ部を除外して全てのログを出力します。リファレンスにも記載がありますが、デバッグに最適なログ出力設定です。
- プロパティ設定：
-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.SimpleLog-Dorg.apache.commons.logging.simplelog.showdatetime=true-Dorg.apache.commons.logging.simplelog.log.org.apache.http=DEBUG-Dorg.apache.commons.logging.simplelog.log.org.apache.http.wire=ERROR
補足: org.apache.http=DEBUGは「全て出力」、org.apache.http.wire=ERRORは「ボディ部は除外」 - ログ出力例：1234567891011121314151617181920212223242526...[DEBUG] RequestAddCookies - CookieSpec selected: default...[DEBUG] RequestAddCookies - Cookie ......[DEBUG] RequestAuthCache - Auth cache not set in the context...[DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {}->http://localhost:8080][total kept alive: 1; route allocated: 1 of 2; total allocated: 1 of 20]...[DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 0][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]...[DEBUG] DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 0...[DEBUG] MainClientExec - Executing request POST /xxx HTTP/1.1...[DEBUG] MainClientExec - Target auth state: UNCHALLENGED...[DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED...[DEBUG] headers - http-outgoing-0 >> POST /xxx HTTP/1.1...[DEBUG] headers - http-outgoing-0 >> Content-Length: 28...[DEBUG] headers - http-outgoing-0 >> Content-Type: application/x-www-form-urlencoded...[DEBUG] headers - http-outgoing-0 >> Host: localhost:8080...[DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive...[DEBUG] headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.9 (Java/1.8.0_181-1-redhat)...[DEBUG] headers - http-outgoing-0 >> Cookie: xxx=xxx...[DEBUG] headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate...[DEBUG] headers - http-outgoing-0 << HTTP/1.1 200 OK...[DEBUG] headers - http-outgoing-0 << Connection: keep-alive...[DEBUG] headers - http-outgoing-0 << Content-Type: text/html;charset=UTF-8...[DEBUG] headers - http-outgoing-0 << Content-Length: 8072...[DEBUG] headers - http-outgoing-0 << Date: Sun, 14 Jul 2019 13:46:08 GMT...[DEBUG] MainClientExec - Connection can be kept alive indefinitely...[DEBUG] PoolingHttpClientConnectionManager - Connection [id: 0][route: {}->http://localhost:8080] can be kept alive indefinitely...[DEBUG] DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 0...[DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: 0][route: {}->http://localhost:8080][total kept alive: 1; route allocated: 1 of 2; total allocated: 1 of 20]
出力例2：通信内容(ヘッダのみ)
- プロパティ設定：
-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.SimpleLog-Dorg.apache.commons.logging.simplelog.showdatetime=true-Dorg.apache.commons.logging.simplelog.log.org.apache.http.headers=DEBUG
- ログ出力例：12345678910111213...[DEBUG] headers - http-outgoing-0 >> POST /xxx HTTP/1.1...[DEBUG] headers - http-outgoing-0 >> Content-Length: 28...[DEBUG] headers - http-outgoing-0 >> Content-Type: application/x-www-form-urlencoded...[DEBUG] headers - http-outgoing-0 >> Host: localhost:8080...[DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive...[DEBUG] headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.9 (Java/1.8.0_181-1-redhat)...[DEBUG] headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate...[DEBUG] headers - http-outgoing-0 << HTTP/1.1 200 OK...[DEBUG] headers - http-outgoing-0 << Connection: keep-alive...[DEBUG] headers - http-outgoing-0 << Set-Cookie: xxx=xxx; path=/xxx...[DEBUG] headers - http-outgoing-0 << Content-Type: text/html;charset=UTF-8...[DEBUG] headers - http-outgoing-0 << Content-Length: 8734...[DEBUG] headers - http-outgoing-0 << Date: Sun, 14 Jul 2019 14:13:41 GMT
出力例3：通信内容(ヘッダ＋ボディ)
ヘッダとボディ内容を確認したい場合の例です。
org.apache.http.headersと併せて使用するとヘッダが重複して出てしまいます。
- プロパティ設定：
-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.SimpleLog-Dorg.apache.commons.logging.simplelog.showdatetime=true-Dorg.apache.commons.logging.simplelog.log.org.apache.http.wire=DEBUG
- ログ出力例：12345678910111213141516171819202122...[DEBUG] wire - http-outgoing-0 >> "POST /xxx HTTP/1.1[\r][\n]"...[DEBUG] wire - http-outgoing-0 >> "Content-Length: 28[\r][\n]"...[DEBUG] wire - http-outgoing-0 >> "Content-Type: application/x-www-form-urlencoded[\r][\n]"...[DEBUG] wire - http-outgoing-0 >> "Host: localhost:8080[\r][\n]"...[DEBUG] wire - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"...[DEBUG] wire - http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.9 (Java/1.8.0_181-1-redhat)[\r][\n]"...[DEBUG] wire - http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]"...[DEBUG] wire - http-outgoing-0 >> "[\r][\n]"...[DEBUG] wire - http-outgoing-0 >> "username=vip&password=secret"...[DEBUG] wire - http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]"...[DEBUG] wire - http-outgoing-0 << "Connection: keep-alive[\r][\n]"...[DEBUG] wire - http-outgoing-0 << "Set-Cookie: xxx=xxx; path=/xxx[\r][\n]"...[DEBUG] wire - http-outgoing-0 << "Content-Type: text/html;charset=UTF-8[\r][\n]"...[DEBUG] wire - http-outgoing-0 << "Content-Length: 8732[\r][\n]"...[DEBUG] wire - http-outgoing-0 << "Date: Sun, 14 Jul 2019 14:20:46 GMT[\r][\n]"...[DEBUG] wire - http-outgoing-0 << "[\r][\n]"...[DEBUG] wire - http-outgoing-0 << "<?xml version='1.0' encoding='UTF-8' ?>[\n]"...[DEBUG] wire - http-outgoing-0 << "<!DOCTYPE html>[\n]"...[DEBUG] wire - http-outgoing-0 << "<html lang="ja" xmlns="http://www.w3.org/1999/xhtml" xmlns:og="http://ogp.me/ns#">[\n]"...[DEBUG] wire - http-outgoing-0 << ...(応答内容)......[DEBUG] wire - http-outgoing-0 << "[0x9]</div></body>[\n]"...[DEBUG] wire - http-outgoing-0 << "</html>"
参考：サンプルプログラム
HttpClientを使ってHTTP POSTするサンプルプログラムです。
使用するHttpClientはmavenで取得する前提であるため、pom.xmlで宣言します。
実行する場合はソースコード上のURLを適宜修正してください。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 | package test; import java.io.IOException; import java.util.ArrayList; import java.util.List; import org.apache.http.HttpEntity; import org.apache.http.NameValuePair; import org.apache.http.client.entity.UrlEncodedFormEntity; import org.apache.http.client.methods.CloseableHttpResponse; import org.apache.http.client.methods.HttpGet; import org.apache.http.client.methods.HttpPost; import org.apache.http.impl.client.CloseableHttpClient; import org.apache.http.impl.client.HttpClients; import org.apache.http.message.BasicNameValuePair; import org.apache.http.util.EntityUtils; public class HttpClientTest { public static void main(String[] args) throws Exception { CloseableHttpClient httpclient = HttpClients.createDefault(); HttpPost httpPost = new HttpPost("http://localhost:8080/xxx"); List<NameValuePair> nvps = new ArrayList<NameValuePair>(); nvps.add(new BasicNameValuePair("username", "vip")); nvps.add(new BasicNameValuePair("password", "secret")); httpPost.setEntity(new UrlEncodedFormEntity(nvps)); try (CloseableHttpResponse response2 = httpclient.execute(httpPost);) { HttpEntity entity2 = response2.getEntity(); // do something useful with the response body // and ensure it is fully consumed EntityUtils.consume(entity2); } } } |
1 2 3 4 5 6 7 8 9 10 11 | <project ... ... <dependencies> <dependency> <groupId>org.apache.httpcomponents</groupId> <artifactId>httpclient</artifactId> <version>4.5.9</version> </dependency> </dependencies> ... </project> |