Envoy の gRPC-JSON transcoder を使っているときにアクセスログでハマったのでメモっておきます。
gRPC-JSON transcoder というのは、簡単にいうとRESTful な JSON API としてリクエストすると gRPC の形式に変換した上で upstream のサーバーにプロキシしてくれて、レスポンスについても gRPC の形式から JSON に戻してくれるという機能です。
例えばこのような protobuf を定義して Envoy に取り込むと GET /shoes/{item_id} という JSON API のエンドポイントが有効になりリクエストを送れるようになります。
syntax = "proto3"; package shoes; import "google/api/annotations.proto"; service Shoes { rpc GetShoeInfo(GetShoeInfoRequest) returns (ShoeInfo) { option (google.api.http) = { get : "/shoes/{item_id}" }; } } message GetShoeInfoRequest { string item_id = 1; } message ShoeInfo { string item_id = 1; string name = 2; string type = 3; repeated string size_labels = 4; }
で、実際にリクエストを送ってみると以下のようなアクセスログが出力されました。パスが正しいので見落としていたのですがよく見ると GET でリクエストしたにも関わらず POST と出力されているのに気付き、調べてみることにしました。
$ curl -v http://localhost:8080/shoes/123456 > GET /shoes/123456 HTTP/1.1 --- [2021-02-20T06:56:41.536Z] "POST /shoes/123456 HTTP/1.1" 200 - 0 120 19 15 "-" "curl/7.64.1" "7f86f233-e658-400d-bb8f-999dea810924" "localhost:8080" "172.19.0.2:50051"
ログに利用される情報
まず私が気になったのはどの時点のリクエスト/レスポンス情報がログに出力されるのかということでした。ソースコードを探すのが中々大変だったのですが以下の部分に行き着きました。C++のソースコードなので私は詳しく追えないのですが、コメントには "@param request_headers supplies the incoming request headers after filtering." とあってフィルタリングされた後のリクエストヘッダーが渡されるということが書いてあります。gRPC-JSON transcoder もフィルターの一種なので gRPC に変換した後のリクエストヘッダーが適用されそうと分かりました。
/** * Abstract access logger for requests and connections. */ class Instance { public: virtual ~Instance() = default; /** * Log a completed request. * @param request_headers supplies the incoming request headers after filtering. * @param response_headers supplies response headers. * @param response_trailers supplies response trailers. * @param stream_info supplies additional information about the request not * contained in the request headers. */ virtual void log(const Http::RequestHeaderMap* request_headers, const Http::ResponseHeaderMap* response_headers, const Http::ResponseTrailerMap* response_trailers, const StreamInfo::StreamInfo& stream_info) PURE; };
https://github.com/envoyproxy/envoy/blob/v1.17.0/include/envoy/access_log/access_log.h#L75-L94
パスが元リクエストの値になっている理由
次にログの形式を確認すると default のフォーマットは以下のように定義されています。 https://www.envoyproxy.io/docs/envoy/latest/configuration/observability/access_log/usage#default-format-string
[%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"\n
まずパスの部分に注目すると %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% という定義になっていて、これはリクエストヘッダーの中に X-ENVOY-ORIGINAL-PATH があればその値になり、なければ :PATH ヘッダーの値になるという指定です。一方 HTTP method の部分に注目すると %REQ(:METHOD)% という定義でリクエストの :METHOD ヘッダーの値が出力される指定となっています。
gRPC のリクエストは POST でパスが /{package}.{service}/{rpc} のような形式になるのでパスについては X-ENVOY-ORIGINAL-PATH に元のパス(ex. /shoes/{id})がセットされてると考えられます。実際はどうなのかというところでまたもやソースコードを探索したところ、transcoder の処理中でヘッダーの値をセットしている部分を発見しました。そしてここでは EnvoyOriginalMethod (これは x-envoy-original-method というヘッダーのキーを表す)に元の HTTP method の値をセットしているようです。
Http::FilterHeadersStatus JsonTranscoderFilter::decodeHeaders(Http::RequestHeaderMap& headers,
bool end_stream) {
//...
headers.setEnvoyOriginalPath(headers.getPathValue());
headers.addReferenceKey(Http::Headers::get().EnvoyOriginalMethod, headers.getMethodValue());
headers.setPath("/" + method_->descriptor_->service()->full_name() + "/" +
method_->descriptor_->name());
headers.setReferenceMethod(Http::Headers::get().MethodValues.Post);
//...
}
const LowerCaseString EnvoyOriginalMethod{absl::StrCat(prefix(), "-original-method")};
https://github.com/envoyproxy/envoy/blob/v1.17.0/source/common/http/headers.h#L158
アクセスログの設定
ということで x-envoy-original-method ヘッダーの値をログに出力できれば良さそうですね。ということで %REQ(X-ENVOY-ORIGINAL-METHOD?:METHOD) とすることでパスと同じような扱いで出力できます。Envoy の yaml 設定ファイルの例は以下となります。
access_log: - name: envoy.access_loggers.file typed_config: "@type": type.googleapis.com/envoy.extensions.access_loggers.file.v3.FileAccessLog path: /dev/stdout log_format: text_format_source: inline_string: | [%START_TIME%] "%REQ(X-ENVOY-ORIGINAL-METHOD?:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"
この設定で Envoy を起動しリクエストを行ったところ無事に GET でログが出力されました。
$ curl -v http://localhost:8080/shoes/123456 > GET /shoes/123456 HTTP/1.1 --- [2021-02-20T06:59:07.580Z] "GET /shoes/123456 HTTP/1.1" 200 - 0 120 12 4 "-" "curl/7.64.1" "a6e3602c-d935-47d8-884a-b3c5e34296fd" "localhost:8080" "172.19.0.3:50051"
おわりに
ということで無事に解決して良かったです。
