GAE Flexible Environmentでアプリケーションのログを出力するためにやったこと。

GoogleAppengine Flexible Environmentでのログ出力

皆さん、アプリケーションを作るときにはログはアプリケーションサーバ上のストレージに吐き出してますか〜？？

GAE/go (Standard Environment）ではgoogle.golang.org/appengine/logを利用すればよしなにログビューアーに出力してくれ、ログのフィルタなどもかんたんに行なえ、「なんて素晴らしいんだ！！」と感動したことだと思います。

しかし、GAE/FEでは何もせずともログビューアに出力してくれるというわけではありませんでした。

色々苦労して期待通りに出力するところまでできたので、いろいろ調査したことを含め、いつか誰かの役に立つかもしれないので細かく書いてみようと思います。

ログ出力作戦（第一世代）

最初に考えたログ出力方法としてはStackDriverLoggingAPI(v2)を自前で叩くという手法。→こちら

こちらの手法を利用した場合、ローカルの開発環境で叩く場合、ステージング環境で叩く場合、本番環境で叩く場合の出力先(API接続先)の振り分けをしなくてはならないことや、1回のリクエストで複数回APIを叩くのはよろしくないため、リクエストスコープで書き込みをバッファしてLoggingAPIを実行する仕組みを作る必要がありそうです。

そんなところ、FE環境ではfluentdが動いており、適切なフォーマットで吐き出したファイルは適切な形でログビューアに出力されるという情報を得て、早速ログ出力作戦は第二世代へ

ログ出力作戦（第二世代）

FE環境にはエージェントがインストールされ、ログ出力する仕組みが用意されている

使用する App Engine のフレキシブル環境アプリケーションを Stackdriver Error Reporting に接続するには、構造化データをカスタム ログファイルに送信します。

App Engine のフレキシブル環境アプリのデフォルト設定により、Stackdriver Logging エージェントがインストールされ、設定されます。

なるほど、これはありがたい。
情報通り、決められたファイルに決められた形式で出力する事で、よしなに集めますよ。と。

決められたファイルと決められた形式とは・・・？

出力する仕組みがある、ということは分かったが、出力先と出力するJSONの形がわからない・・・

Using Cloud logging in App Engine apps などのドキュメントを参考に進めたが、微妙にうまく動かない。

この辺からドキュメントは諦めて、ソースコードやら環境を地道に調査したほうが速いのでは？という気がしたのでその手法に切り換え。

まずは、Managed VM Sidecar ContainersというFE環境のコンテナ周りの設定のリポジトリを眺めつつ、環境を把握する。

FE環境のインスタンスはssh接続できる。

ssh接続できることに気づくまでは、コードを書く→デプロイする→死ぬほど待つ。という苦行でしたが接続できてしまえばこっちのもの。いろいろ調べてみます。

appengineの「インスタンス」をクリックし、インスタンスの「SSH」をクリックするとブラウザ上でターミナルが起動します。

ターミナルで接続した先はFE環境のインスタンスになります。（多分GCEインスタンスなのかな？）
以下コマンドで動いているコンテナを調べてみます。

$ sudo docker ps
CONTAINER ID        IMAGE                                                                                                                         COMMAND                  CREATED             STATUS              PORTS                                        NAMES
61096f77d1a5        gcr.io/google_appengine/nginx-proxy                                                                                           "/var/lib/nginx/bin/s"   About an hour ago   Up About an hour    8080/tcp, 8090/tcp, 0.0.0.0:8443->8443/tcp   thirsty_brattain
3e176f20673a        us.gcr.io/fe-stud/appengine/default.20161206t152342@sha256:330d6b553033c80ad0313fe3c2fd713bdaec873197d00193b6f8a32beda0ca73   "/docker-entrypoint.b"   About an hour ago   Up About an hour    8080/tcp                                     gaeapp
73675d907c83        gcr.io/google_appengine/api-proxy                                                                                             "/proxy"                 About an hour ago   Up About an hour                                                 api
5430f456d28c        gcr.io/google_appengine/fluentd-logger                                                                                        "/opt/google-fluentd/"   About an hour ago   Up About an hour                                                 stupefied_heisenberg

FE環境のインスタンスはDocker上で4つのコンテナが起動しており、共有しているホストインスタンスのディレクトリにgaeapp(アプリケーション）からログを吐き出すとfluentdのコンテナが拾ってログを送るという構成のようです。

fluentdなので収集するログファイルは Github内のファイル に定義されており、

/fluentd_logger/managed_vms.conf

以下のようになっています。

ファイルパターン
/var/log/app_engine/app/app*.log
/var/log/app_engine/app/app*.json
/var/log/app_engine/app/request*.log
/var/log/app_engine/app/STDOUT*.log
/var/log/app_engine/app/STDERR*.log
/var/log/app_engine/app/custom_logs/*.log
/var/log/app_engine/app/custom_logs/*.json
/var/log/app_engine/monitoring/*.log
/var/log/syslog

標準で対象になっているのはこのあたりかと。
注意点としてはfluentdのコンテナ内のパスであること！（私はgaeappコンテナ内でも同一のパスになるのではという思い込みのせいで少しハマってました。。。）

どうハマったのか下記します。
ディレクトリパスの対応表

gaeappコンテナがマウントしているパス	host instance内のログディレクトリ	fluentdコンテナがマウントしているパス
/var/log/app_engine	/var/log/app_engine/app	/var/log/app_engine/app

気づきましたか？
そうです、ホストインスタンスとfluentdのコンテナのログディレクトリのパスは一致してるのですが、何故かgaeappのログディレクトリのパスが異なっています。。。

なので、fluentdの設定ファイルを見て、そのディレクトリに対してgaeapp内でログファイルを出力してもfluentdが拾ってくれません・・・（涙。

この辺はfluentdのコンテナに入ってログをtailしながら試してみると良い気がします。

fluentdコンテナに入るにはホストインスタンス上で

$ sudo docker exec -it stupefied_heisenberg bash

でコンテナに入り、

# tail -f /var/log/google-fluentd/google-fluentd.log

で眺めることができます。
ちなみにログが正しくfluentdに拾われている場合には

2016-12-06 07:47:25 +0000 [info]: following tail of /var/log/app_engine/app/app.json
2016-12-06 07:54:25 +0000 [info]: following tail of /var/log/app_engine/app/app.log.json

のようなログが出力されます。（ファイルを見つけた最初にのみ出力されるのでそれも注意。）

出力する際に必要なJSON形式とは？？

まずはJSON形式じゃないログはどのようにログビューアでどのように出力されるか。

テキストのログは*.logという拡張子のファイルに出力するとテキストとして出力されます。
JSON形式のログと異なるところは、ログレベルなどの情報の付与が行えないという点でしょうか。

app.logを出力した例

細長い画像ですみません。。
テキストで出力した場合には（例は中身がJSON形式ですが、）ログレベル（左側のアイコン）もつかず出力されます。

アプリケーションから出力する場合にはやはりログレベルは欲しいです。
その為、出力に必要なJSON形式を下記します。

JSONフォーマットのログを出力し、ログビューアにきれいに出力するには。（完結編?）

JSONのフォーマットには appengine-java-vm-runtime 内の JsonFormatter.java と LogContext.java を利用します。

他の言語で利用する場合にも JsonFormatter.java 内のformatメソッドはそれほど難しい処理をしていないので、そちらを参考にして実装しても良いと思います。

で、結論となるJSON形式のサンプルですが以下のようになります。

{
  "timestamp":{"seconds":1481005920,"nanos":927000000},
  "severity":"ERROR",
  "thread":"qtp1347137144-13",
  "message":"TestLogger: === TEST LOG ==="
}

ちなみに先程のJsonFormatterを利用する場合にはjava.util.logging.LogRecordを利用することになりますが、注意点としてLogRecord#setLoggerNameを利用してロガー名を入れる必要があります。
入れなくてもエラーにはならないのですが、JSONのmessageが"null: === TEST LOG ==="のようになってしまいカッコ悪いので。

ざっくりとしたサンプルコード

Level level = Level.SEVERE; // ログレベル、Error相当
LogRecord record = new LogRecord(level, "=== TEST LOG ===");
record.setLoggerName("TestLogger");
JsonFormatter formatter = new JsonFormatter();
String logString = formatter.format(record); // このStringをjsonファイルの行として出力すれば良い。

ここまで準備できればJSONをファイルに吐き出してきれいにログビューアーに出力することができるようになります。

例はエラーレベルで出力してますので、ただ事じゃなさそうなアイコンがついてますね[！！]

Javaでの出力方法 (Appendix)

Scala(Java)で利用する場合にはslf4j/logbackなどを利用して出力したいと思いますが、以下のような方法で出力ができました。

プロジェクトの pom.xml に appengine-java-logging と appengine-managed-runtime を追加する

pom.xml

<!-- https://mvnrepository.com/artifact/com.google.appengine/appengine-java-logging -->
<dependency>
    <groupId>com.google.appengine</groupId>
    <artifactId>appengine-java-logging</artifactId>
    <version>1.9.31</version>
</dependency>
<!-- https://mvnrepository.com/artifact/com.google.appengine/appengine-managed-runtime -->
<dependency>
    <groupId>com.google.appengine</groupId>
    <artifactId>appengine-managed-runtime</artifactId>
    <version>1.9.31</version>
</dependency>

アプリケーションの何処かで VmRuntimeFileLogHandler#init を呼ぶ。

これは内部的にログ出力設定を指定しています。

VmRuntimeFileLogHandler.java

// ~~ snip ~~
    private static String fileLogPattern() {
        String pattern = System.getenv("APP_ENGINE_LOG_CONFIG_PATTERN");
        if(pattern != null) {
            return pattern;
        } else {
            String directory = System.getProperty("com.google.apphosting.logs", "/var/log/app_engine");
            pattern = System.getProperty("com.google.apphosting.vmruntime.VmRuntimeFileLogHandler.pattern");
            return pattern != null?(pattern.startsWith("/")?pattern:directory + "/" + pattern):directory + "/" + "app.%g.log.json";
        }
    }
// ~~ snip ~~

指定内容はこのクラスを参考にして、logback.xml などに転記してもいいと思います。その場合には VmRuntimeFileLogHandler#init は呼ばなくて良いです。

ロガーを生成して、ログを出力する

LogSample.java

Logger logger = Logger.getLogger("com");  // ロガー生成

logger.warning("= WARNING TEST ="); // ログ出力

必要に応じて logging.properties を設定します

.level=ALL

com.level=SEVERE

謝辞

FE環境でのログ出力周りに関して、いろいろと情報を頂いたりご相談させていただいた @soundTricker さんに感謝いたします。