dockerでデタッチモードでコンテナを起動し、サービスが起動するまで標準出力にログを出す

## やりたいこと

Dockerでコンテナを起動する際、`-d`をつけてdetachモードで（バックグラウンドで）実行することはよく行われると思う。
その際に、コンテナ上のサービスが起動するのに時間がかかる場合、`docker compose logs -f`で出力を監視し、起動するまで待つこともよく行われるだろう。

この記事では、この一連の処理を一つのスクリプトにまとめて

- スクリプトの中で`docker compose up -d`を実行後、
- ログを監視しサービスが起動するまで標準出力にログを出力し
- サービスが起動し終わったら終了する

というスクリプトを書く方法についてまとめる。

## 準備

ここではサンプルとしてmysqlのイメージを起動することにする。
公式のmysqlのイメージ https://hub.docker.com/_/mysql を利用する。
こちらのページにあるように以下のようなdocker-compose.ymlを用意する。（readmeに書いてあるものをそのまま利用しているだけである）

```yml:docker-compose.yml
# Use root/example as user/password credentials
version: '3.1'

services:

  db:
    image: mysql
    command: --default-authentication-plugin=mysql_native_password
    restart: always
    environment:
      MYSQL_ROOT_PASSWORD: example

  adminer:
    image: adminer
    restart: always
    ports:
      - 8080:8080
```

このymlファイルを用いて、`docker compose up`で起動するとmysqlとadminerの二つのサービスが起動する。その際に標準出力には以下のように出力される。

```txt
compose_mysql-adminer-1  | [Tue Mar 15 07:33:03 2022] PHP 7.4.28 Development Server (http://[::]:8080) started
compose_mysql-db-1       | 2022-03-15 07:33:03+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.28-1debian10 started.
compose_mysql-db-1       | 2022-03-15 07:33:03+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
compose_mysql-db-1       | 2022-03-15 07:33:03+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.28-1debian10 started.
compose_mysql-db-1       | 2022-03-15 07:33:03+00:00 [Note] [Entrypoint]: Initializing database files
....

compose_mysql-db-1       | 2022-03-15T07:33:12.166847Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
compose_mysql-db-1       | 2022-03-15T07:33:12.180978Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
compose_mysql-db-1       | 2022-03-15T07:33:12.181061Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.28'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
```

mysqlが立ち上がるまでに１０秒くらいの時間を要し、mysqlが起動し終わると"ready for connections"というログが出力される。
（mysqlの場合は10秒くらいで済むが、起動にもっと長い時間を要する場合、これが終わるまで待っているのは面倒なので一括処理したい、というのが本記事の趣旨である）

## うまくいかない方法

単純に次のようなスクリプトを使うとうまくいかない。

```bash
docker compose up -d
docker logs -f
```

ログは出力されるが、サービス立ち上げが完了しても`docker logs -f`は起動したままである。"ready for connections"という文字列が現れたら`docker logs`を終了するようにしたい。

## うまくいく方法

`docker logs -f`の出力をgrepして、"ready for connections"が現れたら`docker logs`をシグナルを送ってプロセスを修了するようにする。
簡単なように思えるが、これを行うのは一筋縄ではいかない。最終的に下のようなスクリプトに行き着いた。

```bash:up_and_logs.sh
#!/bin/bash

docker compose up -d

if [ -e temp.pipe ]; then
  rm temp.pipe
fi
mkfifo temp.pipe
docker compose logs -f --since 0s > >(tee temp.pipe) 2> /dev/null &

trap "kill -9 $!" 1 2 3 15
# in case we receive the signal, we kill `docker compose logs`

grep --line-buffered -m 1 "ready for connections" > /dev/null < temp.pipe

# to stop `docker compose logs -f`, multiple signals are needed
# probably due to a bug in this command
while kill -0 $! 2> /dev/null; do
  kill -2 $!
  sleep 0.1
done
rm temp.pipe
```

## 解説

まず`docker compose up -d`でデタッチして起動する。

続いて、`docker compose logs -f --since 0s > >(tee temp.pipe) 2> /dev/null &`という行に注目して欲しい。
`docker compose log -f`で実行中のコンテナのログが出力されるが、その出力は名前付きパイプ`tee temp.pipe`に送る。
見慣れないbash文法の`>(tee temp.pipe)`というものがあるが、これはコマンド置換と呼ばれるものである。
単純にpipeで送ると、`docker compose logs -f`コマンドのプロセスIDが取得できないのでコマンド置換を用いた。
コマンド置換についてはこちらの記事も参照のこと : https://qiita.com/yohm/items/8f2d5dda7c58db1ef9f9

`docker compose logs`コマンドに`--since 0s`オプションをつけているのは、再実行した時に過去のログ出力の中にある"ready for connections"という文字列を見つけて、誤判定してしまうのを防ぐためである。

teeコマンドに送られたログ出力は、標準出力に出力されつつ名前付きパイプ`temp.pipe`に送られる。（事前に`mkfifo temp.pipe`で名前付きパイプを作っている。）
この名前付きパイプでおくられたログは`grep --line-buffered -m 1 "ready for connections" > /dev/null < temp.pipe` にて処理され、grepで文字列が見つかるまでこのコマンドは待ち続ける。
`--line-buffered`オプションは入力をバッファしないための処理で、これがないと延々とプログラムが終了しないことが起こりうる。

その後、"ready for connections"の文字列が発見されたら、$!のプロセスIDにkillでシグナルを送ってログ出力を終了する。
ここでも一つ罠があって、なぜかkillを１回行うだけでは`docker compose logs -f`が終わらない。公式ドキュメントによるとこのシグナルを受信したらプロセスが終了するはずなのだが、dockerのバグなのか終了しない。
なぜか複数回送ると適切に終了するようになるので、`while ....`の箇所でプロセスが生きている間、`kill -2 $!`を繰り返し行うことにしている。

中間あたりにある`trap ...`コマンドは、Ctrl-Cなどで中断した時に`docker compose logs -f`を終了するためのもの。

これで、「コンテナを起動して、起動が完了するまで標準出力にログを出力する」という処理が実現できる。