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

## GoogleAppengine Flexible Environmentでのログ出力

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

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

<img width="1062" alt="スクリーンショット_2016-12-06_17_44_49.png" src="https://qiita-image-store.s3.amazonaws.com/0/28681/6f5bb326-846e-cced-ad29-3f82b0736378.png">

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

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

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

最初に考えたログ出力方法としてはStackDriverLoggingAPI(v2)を自前で叩くという手法。→[こちら](http://qiita.com/mtoyoshi/items/d11bcfa6f7ed51e5a813)

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

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

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

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

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

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

https://cloud.google.com/error-reporting/docs/setup/app-engine-flexible-environment

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


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

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

[Using Cloud logging in App Engine apps](https://cloud.google.com/appengine/articles/logging#cloud_logging_and_the_flexible_environment) などのドキュメントを参考に進めたが、微妙にうまく動かない。

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

まずは、[Managed VM Sidecar Containers](https://github.com/GoogleCloudPlatform/appengine-sidecars-docker)というFE環境のコンテナ周りの設定のリポジトリを眺めつつ、環境を把握する。

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

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

appengineの「インスタンス」をクリックし、インスタンスの「SSH」をクリックするとブラウザ上でターミナルが起動します。
<img width="1029" alt="スクリーンショット_2016-12-06_18_23_01.png" src="https://qiita-image-store.s3.amazonaws.com/0/28681/771e2253-2ec7-7ab0-5ed2-ddd737af854d.png">

ターミナルで接続した先は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のコンテナが拾ってログを送るという構成のようです。
<img width="966" alt="スクリーンショット 2016-12-06 18.12.06.png" src="https://qiita-image-store.s3.amazonaws.com/0/28681/b3ad98ef-445d-c706-29ad-76b5fdb7caa8.png">

fluentdなので収集するログファイルは [Github内のファイル](https://github.com/GoogleCloudPlatform/appengine-sidecars-docker/blob/master/fluentd_logger/managed_vms.conf) に定義されており、

```
/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を出力した例
<img width="1205" alt="スクリーンショット 2016-12-06 18.46.25.png" src="https://qiita-image-store.s3.amazonaws.com/0/28681/dc299525-4c08-7eea-c3fd-675febfa72e9.png">
細長い画像ですみません。。
テキストで出力した場合には（例は中身がJSON形式ですが、）ログレベル（左側のアイコン）もつかず出力されます。

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

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

JSONのフォーマットには [appengine-java-vm-runtime](https://github.com/GoogleCloudPlatform/appengine-java-vm-runtime) 内の `JsonFormatter.java` と `LogContext.java` を利用します。

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

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

```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 ==="`のようになってしまいカッコ悪いので。

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

```java
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をファイルに吐き出してきれいにログビューアーに出力することができるようになります。
<img width="498" alt="スクリーンショット_2016-12-06_18_57_25.png" src="https://qiita-image-store.s3.amazonaws.com/0/28681/a86700f4-d0e1-094e-00fe-503c7deef129.png">
例はエラーレベルで出力してますので、ただ事じゃなさそうなアイコンがついてますね[！！]

## Javaでの出力方法 (Appendix)

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

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

```xml: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` を呼ぶ。

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

```java: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` は呼ばなくて良いです。

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

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

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

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

```yaml
.level=ALL

com.level=SEVERE
```

## 謝辞

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