CakePHP4 でログ出力を標準出力(stdout, stderr) にする

本番環境をコンテナで実行する場合（例えば、AWSの ECS, Fargate で実行する場合）、ログ出力は標準出力にするのがベストな方法の1つです。

CakePHP4 プロジェクトでログを標準出力に出すようにしてみます。


# この記事でわかること

- CakePHP4 でログ出力を標準出力(stdout, strerr)にする設定方法。
- この記事内のソースは以下で公開しています。
    - https://github.com/katsuhiko/cakephp-vue-study


# 参考

- https://github.com/cakephp/cakephp/blob/4.0.4/src/Log/Engine/ConsoleLog.php#L32
- https://github.com/cakephp/cakephp/blob/4.0.4/src/Core/StaticConfigTrait.php#L213
- https://github.com/cakephp/cakephp/blob/4.0.4/src/Core/InstanceConfigTrait.php#L73


# 事前準備

- CakePHP4 プロジェクトは以下の記事で作成して、Docker で動くようにしています。
    - [CakePHP4 を docker-compose で動くようにする](https://qiita.com/katsuhiko/items/f18c488457af33abdf66)
- docker-compose を実行し、コンテナを立ち上げます。

```sh
docker-compose up -d
```

|  | バージョン |
|:-----------------|:------------------|
| docker           | Docker version 19.03.8, build afacb8b |
| docker-compose   | docker-compose version 1.25.4, build 8d51620a |
| CakePHP4         | 4.0.4 |


# ログ出力方法の変更

` ./config/app.php ` の Log の設定を変更します。

```php:config/app.php
use Cake\Console\ConsoleOutput;
use Cake\Log\Engine\ConsoleLog;

// ...

    'Log' => [
        'debug' => [
            'className' => ConsoleLog::class,
            'stream' => 'php://stdout',
            'outputAs' => ConsoleOutput::PLAIN,
            'url' => env('LOG_DEBUG_URL', null),
            'scopes' => false,
            'levels' => ['notice', 'info', 'debug'],
        ],
        'error' => [
            'className' => ConsoleLog::class,
            'stream' => 'php://stderr',
            'outputAs' => ConsoleOutput::PLAIN,
            'url' => env('LOG_ERROR_URL', null),
            'scopes' => false,
            'levels' => ['warning', 'error', 'critical', 'alert', 'emergency'],
        ],
        // To enable this dedicated query log, you need set your datasource's log flag to true
        'queries' => [
            'className' => ConsoleLog::class,
            'stream' => 'php://stdout',
            'outputAs' => ConsoleOutput::PLAIN,
            'url' => env('LOG_QUERIES_URL', null),
            'scopes' => ['queriesLog'],
        ],
    ],

// ...
```

` className ` で ` ConsoleLog::class ` を指定します。
` ConsoleLog::class ` 固有で指定できるパラメータは ` stream ` ` outputAs ` の2つです。
残りのパラメータ ` scopes ` ` levels ` は BaseLog から引き継いでいる情報なので、 ` FileLog::class ` を指定しているときから変更する必要はありません。
また、 ` url ` については後述します。

` stream ` は、標準出力( ` php://stdout ` )または、標準エラー( ` php://stderr ` )を指定します。
` outputAs ` は3つのモード（RAW, PLAIN, COLOR）があります。
COLOR にすると、コンソールが対応していればエラーだと赤文字で出力されますっというような制御の指定です。
たまにログによくわからない制御文字が入っている場合、大概、この COLOR での色情報が出てるんじゃないかなっと思います。
PLAIN が純粋で一番良いと思っています。


# 標準出力と言っても困ることもある

ログ出力を標準出力に変えてしまうと、テスト実行時に余計なログが出たり、開発時にログを追うのが難しいケースもあると思います。

そのときはやはりファイルに出力したくなります。

その場合、 ` ./config/.env ` で設定を上書きすることが可能です。そのときに使うのが ` url ` です。

```sh:config.env
export LOG_DEBUG_URL="file://logs/?file=debug&path=/var/www/html/logs/"
export LOG_ERROR_URL="file://logs/?file=error&path=/var/www/html/logs/"
export LOG_QUERIES_URL="file://logs/?file=queries&path=/var/www/html/logs/"
```

上記のように環境変数を用意することで、ファイルログ出力に切り替えることができます。
Docker 環境の場合、 ` path ` を固定で指定しても問題はありません（どの開発者でもマウントされている volume は同じなので）。

忘れないように ` ./config/.env.example ` にも同様の内容を追加しておきます。


# 補足) 本番環境を意識する

少し前までは、ログはローテーションさせつつ、どこかに待避させつつ、、、っと煩雑な作業の1つだったと思います。
でも、本番環境をコンテナで実行する場合、かなり簡単になりました。

AWS ECS / Fargate 環境の場合、標準出力・標準エラーで出しておけば、CloudWatch logs へ転送されます。
CloudWatch logs で失効期間を指定すれば、古いログを自動で削除できます。
また、 CloudWatch logs へ転送されれば、メトリクスフィルターでキーワード（「Exception」等）を指定して、フィルターにかけることでアラート通知を行うこともできます。

Fluentd 等を使いより柔軟なログ転送を行うこともできますが、まずは、気軽な上記の方法から試すのが良いのではないかなっと思っています。

AWS しか利用していないため、詳しくは把握していませんが、他クラウドサービスも似た機能はあると思います。

ログ出力は手軽に標準出力・標準エラーで解決するのが、手間のかからない良い方法だと思います。


# 補足) nginx のログはどうなっているか

nginx のコンテナを立ち上げた場合、 ` default.conf ` でファイル出力しているに見えますが、実は、シンボリックリンクで標準出力・標準エラーに変えられています。

```sh:ホスト-コンテナへ入る
docker exec -it web /bin/sh
```

```sh:コンテナ
ls -l /var/log/nginx/
total 0
lrwxrwxrwx    1 root     root            11 May 11  2019 access.log -> /dev/stdout
lrwxrwxrwx    1 root     root            11 May 11  2019 error.log -> /dev/stderr
```

そのため ` docker logs -f web ` をするとログを参照することができます。


# 補足) php-fpm のログはどうなっているか

` docker logs -f app ` するとプログラムでは出力していない

```
192.168.96.3 -  21/Mar/2020:06:01:15 +0000 "GET /index.php" 200
```

のようなログが出ていると思います。
これは、php-fpm コンテナ内の ` /usr/local/etc/php-fpm.d/docker.conf ` にて設定されている内容で出力されています。

```sh:ホスト-コンテナへ入る
docker exec -it app /bin/bash
```

```sh:コンテナ
cat /usr/local/etc/php-fpm.d/docker.conf
```

```ini:/usr/local/etc/php-fpm.d/docker.conf
[global]
error_log = /proc/self/fd/2

; https://github.com/docker-library/php/pull/725#issuecomment-443540114
log_limit = 8192

[www]
; if we send this to /proc/self/fd/1, it never appears
access.log = /proc/self/fd/2

clear_env = no

; Ensure worker stdout and stderr are sent to the main error log.
catch_workers_output = yes
decorate_workers_output = no
```

` /proc/self/fd/2 ` について、詳しくは把握していないですが、コメントにあるように 2 を 1　へ変えればでなくなるみたいです。