google-http-clientのHTTPヘッダをログに出力する

GCPクライアントライブラリが発行しているHTTPリクエストヘッダ/レスポンスヘッダをログに出したい、というニーズにお答えします。

(追記)
本家に記載があることに気が付きました。内容は今のところ当メモとだいたい同じですが、本家サイトを見ていただくのがいいと思います。
https://googleapis.github.io/google-http-java-client/http-transport.html

リクエストヘッダだけをログに出したい(ボディは出したくない)方は、当記事が参考になると思います。
(追記終わり)

---

下調べ

google-http-clientでは、JUL(java util logging)を使っているようです。

• ログ出力に使っているLoggerは com.google.api.client.http.HttpTransport クラスのLOGGER定数です。
  • クラスごとにLoggerを持つのではなく、HttpTransport定数を各クラスから参照するという指針のようです。
• ログレベルをCONFIGにすればログが出そうです。

このことから、HttpTransportのLoggerに対してログレベルをCONFIGに設定すれば、出力できそうだとアタリを付けました。

ログに出してみる

ログに出すアプローチは2種類です。

アプローチ1: logging.propertiesで出力する

JULはファイルで設定できるので、まずはそのアプローチを試してみます。

参考: https://docs.oracle.com/javase/jp/8/docs/api/java/util/logging/LogManager.html

設定ファイル logging.properties を作ります。

logging.properties

handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=CONFIG
com.google.api.client.http.HttpTransport.level=CONFIG

システムプロパティ java.util.logging.config.file へ logging.properties へのパス(ファイルシステム上のパス) を指定して、実行してみます。

実行するのはこんなコードです。(Cloud Storageのバケットを一覧取得します)

final GoogleCredentials credentials = createCredentials();
final StorageOptions storageOptions = StorageOptions.newBuilder().setCredentials(credentials).build();
final Storage storage = storageOptions.getService();
final Page<Bucket> buckets = storage.list();
for (final Bucket bucket : buckets.iterateAll()) {
    System.out.println("bucket: " + bucket);
}

出力結果

コンソールにリクエスト/レスポンスが出力されました。(下調べは当たっていたことが分かりました)

7月 12, 2020 12:14:09 午前 com.google.api.client.http.HttpRequest execute
構成: -------------- REQUEST  --------------
GET https://storage.googleapis.com/storage/v1/b?project=xxxx&projection=full
Accept-Encoding: gzip
Authorization: <Not Logged>
User-Agent: (略)


7月 12, 2020 12:14:09 午前 com.google.api.client.http.HttpRequest execute
構成: curl -v --compressed -H 'Accept-Encoding: gzip' -H 'Authorization: <Not Logged>' -H 'User-Agent: (略)
7月 12, 2020 12:14:10 午前 com.google.api.client.http.HttpResponse <init>
構成: -------------- RESPONSE --------------
HTTP/1.1 200 OK
Alt-Svc: (略)
Server: UploadServer
Cache-Control: private, max-age=0, must-revalidate, no-transform
X-GUploader-UploadID: (略)
Vary: X-Origin
Vary: Origin
Expires: Sat, 11 Jul 2020 15:14:10 GMT
Content-Length: 3228
Date: Sat, 11 Jul 2020 15:14:10 GMT
Content-Type: application/json; charset=UTF-8


7月 12, 2020 12:14:10 午前 com.google.api.client.util.LoggingByteArrayOutputStream close
構成: Total: 3,228 bytes
7月 12, 2020 12:14:10 午前 com.google.api.client.util.LoggingByteArrayOutputStream close
構成: {
  "kind": "storage#buckets",
  "items": (略)

このように試してみると、狙い通りだったことと、想定していなかったことの両面に気が付きます。

意図したとおりだったこと

無事にリクエストとレスポンスのヘッダが出力されました。

意図していなかったこと

• ヘッダだけでなくボディも出力されました。
  • LoggingByteArrayOutputStream クラスからボディが出力されています。
  • ヘッダは、 HttpRequest と HttpResponse クラスから出力されています。
• Authorizationヘッダの値が Authorization: <Not Logged> と省略されています。
  • ログレベルをCONFIG → ALLに変えると、値が表示されます。
• curlコマンドで同じリクエストを発行するための文字列が出力されています。
• (JULデフォルトのログを久しぶりに目にしましたが、読みづらいですね。 logging.properties へformatterを指定したいところです)

ボディを出さないようにしたいのですが、設定ファイルでは表現できないように思います。

アプローチ2: プログラムで出力する

次はプログラムで設定するアプローチを試してみます。

JULのLoggerへ、先程の設定ファイルと同じような指示をします。

import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogRecord;
import java.util.logging.Logger;

import com.google.api.client.http.HttpRequest;
import com.google.api.client.http.HttpResponse;
import com.google.api.client.http.HttpTransport;

(略)

final Logger logger = Logger.getLogger(HttpTransport.class.getName());
logger.setLevel(Level.CONFIG);
// TODO addしたHanderを戻す(remove)ようにする
logger.addHandler(new Handler() {
    @Override public void publish(final LogRecord record) {
        // 今回はヘッダだけを出したい(ボディは出したくない)ので、HttpRequestとHttpResponseだけにします。
        final String sourceClassName = record.getSourceClassName();
        if (HttpRequest.class.getName().equals(sourceClassName) || HttpResponse.class.getName().equals(sourceClassName)) {
            final String date = DateTimeFormatter.ISO_INSTANT.format(Instant.ofEpochMilli(record.getMillis()));
            final String msg = "[" + logger.getLevel() + "] " + date + " " + record.getMessage();
            // TODO 自身のロガーへどうぞ
            System.out.println(msg);
        }
    }

    @Override public void flush() {
    }

    @Override public void close() throws SecurityException {
    }
});

出力結果

先ほどと同じ(Cloud Storageのバケットを取得する)コードを実行してみると、
今度はボディが出力されなくなりました。(curl用の文字列は出力されるままですけれど)

[CONFIG] 2020-07-11T13:37:42.844Z -------------- REQUEST  --------------
GET https://storage.googleapis.com/storage/v1/b?project=xxxx&projection=full
Accept-Encoding: gzip
Authorization: <Not Logged>
User-Agent: (略)


[CONFIG] 2020-07-11T13:37:42.844Z curl -v --compressed -H 'Accept-Encoding: gzip' -H 'Authorization: <Not Logged>' -H 'User-Agent: (略)
[CONFIG] 2020-07-11T13:37:43.536Z -------------- RESPONSE --------------
HTTP/1.1 200 OK
Alt-Svc: (略)
Server: UploadServer
Cache-Control: private, max-age=0, must-revalidate, no-transform
X-GUploader-UploadID: (略)
Vary: X-Origin
Vary: Origin
Expires: Sat, 11 Jul 2020 13:37:43 GMT
Content-Length: 3228
Date: Sat, 11 Jul 2020 13:37:43 GMT
Content-Type: application/json; charset=UTF-8

所感

2種類のアプローチを試しました。私のユースケースは

• ヘッダだけを出したいケース
• ヘッダとボディ両方を出したいケース

の2つがあるため、プログラムで出力するアプローチの方が良さそうです。
(記事中のコード例ではヘッダだけを出すようにしましたが、ヘッダとボディの両方を出力できるように変えることは難しくありません。)

一方で、ヘッダとボディ両方を出したいというユースケースだけでしたら、設定ファイルアプローチで十分ですね。

環境

動作確認したバージョンです。

• Windows 10
• Java 8
• https://mvnrepository.com/artifact/com.google.http-client/google-http-client/1.36.0
  • https://mvnrepository.com/artifact/com.google.cloud/google-cloud-storage/1.111.2 に含まれているものです