Goコンテナでdocker-compose logsが取れない
やりたかったこと
docker-compose logsでGoコンテナのアクセスログやエラーログを取得しようとしていましたが、コンテナにアクセスしてサーバーを立ち上げた後のログは取得できませんでした。
本来、docker-compose logsはコンテナの標準出力をキャッチして出力してくれます。
コンテナにアクセスしてサーバー立ち上げてログ出力を標準出力に流せばdocker-compose logsにキャッチされると思っていたんですが、キャッチされなかったので、その原因を調べていきます。
結論
取れない原因は、コンテナ起動プロセスで実行したプログラムの標準出力をdockerは対象にしているようで、コンテナ起動プロセスとコンテナアクセス後のプロセスは違うのでそりゃログ取れないよね。という話でした。
書いてみると当然だろって感じなんですが、ログが取れなかった時は？だったのでログを取るまでの流れをここに忘備録として残しておきます。
やったこと
- Goコンテナはttyがtrueではないとコンテナが正常終了してしまうのでttyをtrueに変更してコンテナを継続させた。
- GoコンテナにアクセスしてEchoフレームワークを使用してサーバーを立てた（アクセスログやエラーログは標準出力に出るように設定）
- ポストマンでnginxコンテナ経由でgoコンテナにアクセス
- ホスト側に戻り、docker-compose logsを実行
- ログが出力されない
プロジェクト構成
logキャッチできない構成
（キャッチできる構成はGithubに載せておきます。）
.
├── docker
│ ├── go
│ │ └── Dockerfile
│ └── nginx
│ ├── Dockerfile
│ └── go-app.conf
├── docker-compose.yml
└── src
└── go-app
├── cmd
│ └── main.go
├── go.mod
├── go.sum
├── internal
├── pkg
version: "3.8"
services:
go-app:
build:
context: .
dockerfile: ./docker/go/Dockerfile
volumes:
- ./src/go-app:/go/src
ports:
- 10881:8080
working_dir: /go/src
tty: true
web-server:
depends_on:
- go-app
build:
context: .
dockerfile: ./docker/nginx/Dockerfile
volumes:
- ./docker/nginx/go-app.conf:/etc/nginx/conf.d/go-app.conf
ports:
- 10880:81
コンテナ内の標準出力先を見てみる
docker-compose logsがコンテナの標準出力を監視しているのなら、コンテナの標準出力はdocker側が何かしらの形式でキャッチしているだろうと思い、ymlを以下のように編集してコンテナを起動してみました。
※ttyやptsの詳細はこちら
まずはコンテナ起動プロセスを追ってみます。
version: "3.8"
services:
go-app:
build:
context: .
dockerfile: ./docker/go/Dockerfile
volumes:
- ./src/sample-go-fluentd:/go/src
ports:
- 10881:8080
working_dir: /go/src
# ここがtrueだと説明が面倒なので、falseに設定しておきます。
tty: false
# このコマンドを追記
command: >
sh -c '
ls -la /dev/
ls -la /proc/self/fd
'
$ docker-compose up -d && docker-compose logs
go-app_1 | /dev/:
go-app_1 | lrwxrwxrwx 1 root root 15 May 4 06:15 stderr -> /proc/self/fd/2
go-app_1 | lrwxrwxrwx 1 root root 15 May 4 06:15 stdin -> /proc/self/fd/0
go-app_1 | lrwxrwxrwx 1 root root 15 May 4 06:15 stdout -> /proc/self/fd/1
go-app_1 | /proc/self/fd:
go-app_1 | lrwx------ 1 root root 64 May 4 06:15 0 -> /dev/null
go-app_1 | l-wx------ 1 root root 64 May 4 06:15 1 -> pipe:[98685]
go-app_1 | l-wx------ 1 root root 64 May 4 06:15 2 -> pipe:[98686]
go-app_1 | lr-x------ 1 root root 64 May 4 06:15 3
コンテナ起動プロセスで中身を確認してみたところ、pipe[ポート番号？]のような形式になっていました。
標準出力がDocker側と繋がっている？ように見えますね。
Goコンテナ以外でも同じかどうか確認するため、nginxコンテナでも起動時標準出力はどうなっているのか、docker-compose logsで確認してみました。
web-server_1 | /dev/:
web-server_1 | lrwxrwxrwx 1 root root 15 May 4 07:19 stderr -> /proc/self/fd/2
web-server_1 | lrwxrwxrwx 1 root root 15 May 4 07:19 stdin -> /proc/self/fd/0
web-server_1 | lrwxrwxrwx 1 root root 15 May 4 07:19 stdout -> /proc/self/fd/1
web-server_1 | /proc/self/fd:
web-server_1 | total 0
web-server_1 | lrwx------ 1 root root 64 May 4 07:19 0 -> /dev/null
web-server_1 | l-wx------ 1 root root 64 May 4 07:19 1 -> pipe:[103592]
web-server_1 | l-wx------ 1 root root 64 May 4 07:19 2 -> pipe:[103593]
web-server_1 | l-wx------ 1 root root 64 May 4 07:19 3 -> pipe:[103592]
こちらも同じpipeという記述でした。こういう記述を見るとDocker側と繋がっているようですね。
次はttyをtrueにしてコンテナ内部に入って中身を確認してみます。
go-app:
build:
context: .
dockerfile: ./docker/go/Dockerfile
volumes:
- ./src/sample-go-fluentd:/go/src
ports:
- 10881:8080
working_dir: /go/src
tty: true
$ docker-compose up -d
# ...省略
$ docker-compose exec go-app sh
/go/src # ls -la /dev
lrwxrwxrwx 1 root root 15 May 16 03:22 stderr -> /proc/self/fd/2
lrwxrwxrwx 1 root root 15 May 16 03:22 stdin -> /proc/self/fd/0
lrwxrwxrwx 1 root root 15 May 16 03:22 stdout -> /proc/self/fd/1
/go/src # ls -la /proc/self/fd
lrwx------ 1 root root 64 May 16 03:24 0 -> /dev/pts/1
lrwx------ 1 root root 64 May 16 03:24 1 -> /dev/pts/1
lrwx------ 1 root root 64 May 16 03:24 2 -> /dev/pts/1
当然ながら、コンテナにアクセスしたので仮想端末に標準出力されていますね。ここで叩いたコマンドは全てdocker-compose logsに記録されていませんでした。
一応、全てのプロセスを確認してみましたがdocker側と連携してそうなものはありませんでした。
/go/src # ps a
PID USER TIME COMMAND
1 root 0:00 /bin/sh # 多分tty:trueで配置された
7 root 0:00 sh # コンテナに入った時のプロセス
37 root 0:00 ps a
/go/src # ls -la /proc/1/fd
lrwx------ 1 root root 64 May 16 03:32 0 -> /dev/pts/0
lrwx------ 1 root root 64 May 16 03:32 1 -> /dev/pts/0
lrwx------ 1 root root 64 May 16 03:32 2 -> /dev/pts/0
とりあえず、docker-compose logsと繋がっているのかもしれない、コンテナ起動の際に立ち上がったプロセスであろう/bin/shの標準出力先である、/dev/pts/0にechoコマンドを実行
/go/src # echo "Hello" > /dev/pts/0
コンテナ起動プロセスで実行しているプログラムが何もないのでDocker側はログを取得しなかったのか、ttyで起動したであろうプロセスに対して/go/src # echo "Hello" > /dev/pts/0を実行してもdocker-compose logsに"Hello"とは出力されませんでした。
ttyは多分コンテナ起動プロセスとは別に実行されているのか、とにかくコンテナアクセス後の標準出力はdocker-compose logsに記録されることはありませんでした。
では他のコンテナである、Nginxコンテナの方はどうなんだろうかとやってみたところ、
$ docker-compose exec web-server sh
/ # ps aux
PID USER TIME COMMAND
1 root 0:00 nginx: master process nginx -g daemon off;
33 nginx 0:00 nginx: worker process
34 nginx 0:00 nginx: worker process
35 nginx 0:00 nginx: worker process
36 nginx 0:00 nginx: worker process
37 root 0:00 sh
48 root 0:00 ps aux
コンテナ起動プロセスで実行されたNginxコンテナのImageに入っているnginx: master process nginx -g daemon off;がありました。
※nginx: master process nginx -g daemon off;は、通常バックグラウンドでNginxを起動してしまうところをフォアグラウンドで実行するためのコマンドです。
そのプロセスIDを追ってみると
/ # ls -la /proc/1/fd
total 0
dr-x------ 2 root root 0 May 16 04:24 .
dr-xr-xr-x 9 root root 0 May 16 04:24 ..
lrwx------ 1 root root 64 May 16 04:24 0 -> /dev/null
l-wx------ 1 root root 64 May 16 04:24 1 -> pipe:[454550]
lrwx------ 1 root root 64 May 16 04:24 10 -> socket:[457837]
lrwx------ 1 root root 64 May 16 04:24 11 -> socket:[457838]
lrwx------ 1 root root 64 May 16 04:24 12 -> socket:[457839]
lrwx------ 1 root root 64 May 16 04:24 13 -> socket:[457840]
lrwx------ 1 root root 64 May 16 04:24 14 -> socket:[457841]
lrwx------ 1 root root 64 May 16 04:24 15 -> socket:[457842]
lrwx------ 1 root root 64 May 16 05:00 16 -> socket:[457843]
l-wx------ 1 root root 64 May 16 04:24 2 -> pipe:[454551]
l-wx------ 1 root root 64 May 16 04:24 3 -> pipe:[454550]
lrwx------ 1 root root 64 May 16 04:24 4 -> socket:[457836]
l-wx------ 1 root root 64 May 16 04:24 5 -> pipe:[454551]
l-wx------ 1 root root 64 May 16 04:24 6 -> pipe:[454550]
lrwx------ 1 root root 64 May 16 04:24 7 -> socket:[457833]
lrwx------ 1 root root 64 May 16 04:24 8 -> socket:[457834]
lrwx------ 1 root root 64 May 16 04:24 9 -> socket:[457835]
普通にdocker側と繋がっていそうだったので、以下を実行してdocker-compose logsをみると、
/ # echo "Hello" > /proc/1/fd/1
$ docker-compose logs
web-server_1 | 2021/05/16 04:24:30 [notice] 1#1: start worker process 34
web-server_1 | 2021/05/16 04:24:30 [notice] 1#1: start worker process 35
web-server_1 | 2021/05/16 04:24:30 [notice] 1#1: start worker process 36
web-server_1 | Hello
なんと、出力されていました！
やっぱりDocker側とpipe:[ポート番号？]で繋がっているようですね。
以上のことをまとめると、
- コンテナ起動プロセスで実行したプログラムは、docker側とpipe:[ポート番号？]で繋がっている
- コンテナ起動プロセスで実行した常駐するようなプログラムは、コンテナ起動後もdocker側とpipe:[ポート番号？]で繋がっている（Nginxコンテナなど）
- コンテナにアクセスして対象のプロセスを見つけてそこに標準出力を向ければ、logに記録される
- コンテナにアクセスした後の標準出力はプロセスが違うのでlogに記録されない
- TTYはコンテナを持続させることはできるが、コンテナ起動プロセスで実行した常駐するようなプログラム、ではないため、標準出力はdocker側と繋がっていない
公式ドキュメントにはそういうこと書いてなかったので普通にコンテナアクセス後もログ出力されているのかと思ってしまった。
それにGoコンテナを持続させる方法にttyがよく使用されるので、Goコンテナではコンテナアクセスしてサーバー立てるのが基本、というかローカル開発ではそういうもんだよな、と無意識のうちに思ってしまっていました。
それも合わさって余計わかりにくかったですね。
じゃあGoコンテナをdocker-compose logsに記録するにはどうするの？
Goコンテナをdocker-compose logsに載せる場合、常駐プログラムとしてコンテナ起動プロセスでフォアグラウンド実行する必要があります。
1. コンテナ起動プロセスで常駐プログラムとしてサーバーを立ててしまう
ymlにcommandを追加して、ビルドしてサーバー立ち上げを行ってしまう。
こうすればGoコンテナは起動し続けます。
ただし、ローカル開発であればソースコードの変更が必ずあるのでなんらかの方法でソースコードの更新を反映させる仕組みが必要になってきます。
2. コンテナ起動プロセスで常駐プログラムとしてなんか適当に動かして、そのプロセスの標準出力先を指定して実行する
これは愚策だと思うのでやりません。
3. そんなにログが取りたいなら公式で書かれているようにstraceで追う
こちらが参考になる。
色々と方法は考えられますが、今回は自然でかつ開発作業的にもあったら嬉しいツール「Air」を使用して1の方法で行きたいと思います。
Airはホットリロードツールと言われるもので、ソースコードの変更を検知して自動で反映してくれます。
Goには有名なものにRealizeというものがありますが、更新が止まっているようなのでこちらを使っていきます。
それではAirの使用法から〜ログ取得までの一連の流れを書いていきます。
GoコンテナでAirのinstallとサーバー実行方法
1. プロジェクト構成
一番最初に書いてある通りです。
2. Goで動くプログラムを作成する
まずGo側で実際に動くプログラムを作成します。
こちらの説明は省きますが、Echoフレームワークを使用してサーバーを立てています。
package main
import (
"net/http"
"os"
"github.com/labstack/echo"
"github.com/labstack/echo/middleware"
)
func main() {
e := echo.New()
e.GET("/", func(c echo.Context) error {
return c.String(http.StatusOK, "Hello, World!")
})
e.Use(middleware.LoggerWithConfig(
middleware.LoggerConfig{
Format: "bytes_in=${bytes_in},bytes_out=${bytes_out},method=${method}, uri=${uri}, status=${status}, error=${error}\n",
Output: os.Stdout,
},
))
e.Logger.Fatal(e.Start(":8080"))
}
こちらを書いてgo-app/cmd/main.goにおきます。
3. Airを試す
AirのgithubのReadmeを見てみると、
# binary will be $(go env GOPATH)/bin/air
curl -sSfL https://raw.githubusercontent.com/cosmtrek/air/master/install.sh | sh -s -- -b $(go env GOPATH)/bin
# or install it into ./bin/
curl -sSfL https://raw.githubusercontent.com/cosmtrek/air/master/install.sh | sh -s
air -v
と書かれているので、ttyをtrueにした状態でGoコンテナを起動して、コンテナにアクセスします。
アクセス後、インストールして問題なくバージョン情報が表示できるか確認します。
/project_dir $ docker-compose up -d && docker-compose exec go-app sh
/go/src # curl -sSfL https://raw.githubusercontent.com/cosmtrek/air/master/install.sh | sh -s -- -b $(go env GOPATH)/bin
/go/src # air -v
__ _ ___
/ /\ | | | |_)
/_/--\ |_| |_| \_ 1.27.3, built with Go 1.16.3
次はAirの初期設定をします。
air initを実行して、tomlファイルを作成し、そこにホットリロードの詳細を残していきます。
/go/src # air init
__ _ ___
/ /\ | | | |_)
/_/--\ |_| |_| \_ 1.27.3, built with Go 1.16.3
.air.toml file created to the current directory with the default settings
.air.tomlファイルが作成されたと思います。
↓中身の説明はReadMeに貼られているサンプルを参考にするといいと思います。
一応、自動生成されたtomlファイルの解説します。（ReadMeの方にはより詳しい情報が乗っています。）
root = "."
# airのログなどを管理する一時ディレクトリ。
tmp_dir = "tmp"
[build]
# 実行バイナリ
bin = "./tmp/main"
# アプリをコンパイルするコマンド
cmd = "go build -o ./tmp/main ./cmd/main.go"
# cmdの実行タイミングを遅らせることができます。
# コードをいじってすぐcmd+sを押すような場合、コンパイルがすぐに走ってしまいますが、こちらを設定しておけばコンパイル回数を減らせるでしょう
delay = 1000
# airの監視から外しておくもの。assetsやtmpやvendorの変更がデフォルトでは監視対象外のようですね。
exclude_dir = ["assets", "tmp", "vendor"]
# airの監視から外しておくもの。exclude_dirと違って、こちらはファイル単位で対象外にできるようです。
exclude_file = []
# airの監視から外しておくもの。正規表現も使えるみたいですね。
exclude_regex = []
#
exclude_unchanged = false
# ディレクトリのシンボリックリンクをたどる設定のようです。
# 今回の用途には必要ないと思います。（ReadMeではtrue）
follow_symlink = false
# 実行時に引数とか設定できるやつ。マイグレーションとかに使えそう。今回これは使いませんのでコメントアウト
full_bin = "tmp/main up"
# 監視対象のホワイトリスト
include_dir = []
# 監視対象のホワイトリスト。拡張子の指定ができるみたい。
include_ext = ["go", "tpl", "tmpl", "html"]
# 割り込み信号送信後の遅延時間（秒）
kill_delay = "0s"
# 名前の通り、ビルドエラーのログファイルみたいです。tmp_dirにファイルが置かれるようです。
log = "build-errors.log"
# プロセスを強制終了する前に割り込み信号を送信する。windowsではサポートされていないらしい
send_interrupt = false
# ビルドエラーが発生したら古いバイナリの実行を停止する。
stop_on_error = true
# これはカラー設定なので深くはみません
[color]
app = ""
build = "yellow"
main = "magenta"
runner = "green"
watcher = "cyan"
# ログの時間を表示するかどうか
[log]
time = false
# 終了時にtmp_dirが存在したら削除するかどうか。いらないので削除するためtrueに変更しています
[misc]
clean_on_exit = true
上の情報をみながら適切に決めていくといいと思います。
今回は一部修正した上の状態でいきます。編集が終わったら以下コマンドを叩く
/go/src # air
__ _ ___
/ /\ | | | |_)
/_/--\ |_| |_| \_ 1.27.3, built with Go 1.16.3
mkdir /go/src/tmp
watching .
watching cmd
watching cmd/bin
watching internal
watching pkg
!exclude tmp
building...
go: downloading github.com/labstack/echo v3.3.10+incompatible
go: downloading github.com/labstack/gommon v0.3.0
go: downloading golang.org/x/crypto v0.0.0-20200820211705-5c72a883971a
go: downloading github.com/dgrijalva/jwt-go v3.2.0+incompatible
go: downloading github.com/valyala/fasttemplate v1.2.1
go: downloading github.com/mattn/go-colorable v0.1.7
go: downloading github.com/mattn/go-isatty v0.0.12
go: downloading golang.org/x/sys v0.0.0-20200826173525-f9321e4c35a6
go: downloading github.com/valyala/bytebufferpool v1.0.0
go: downloading golang.org/x/net v0.0.0-20200822124328-c89045814202
go: downloading golang.org/x/text v0.3.3
running...
____ __
/ __/___/ / ___
/ _// __/ _ \/ _ \
/___/\__/_//_/\___/ v3.3.10-dev
High performance, minimalist Go web framework
https://echo.labstack.com
____________________________________O/_______
O\
⇨ http server started on [::]:8080
すると、こんな感じでサーバーが立ち上がると思います。
こうなっていれば完璧です。
適当にmain.goを変更してみてください、自動でリビルドされているはずです。
4. コンテナ起動プロセスに上の手順を載せる
airの挙動は大体わかったので、これをDockerの起動プロセスに載せます。これが終わればlogが取れるはずです。
以下のDockerfileとdocker-compose.ymlを編集します。
.
├── docker
│ ├── go
│ │ └── Dockerfile
├── docker-compose.yml
FROM golang:1.16.3
RUN curl -sSfL https://raw.githubusercontent.com/cosmtrek/air/master/install.sh | sh -s -- -b $(go env GOPATH)/bin && \
air -v
version: "3.8"
services:
go-app:
build:
context: .
dockerfile: ./docker/go/Dockerfile
volumes:
- ./src/go-app:/go/src
ports:
- 10881:8080
working_dir: /go/src
# もういらないので削除
# tty: true
# これを追加
command: air
web-server:
depends_on:
- go-app
build:
context: .
dockerfile: ./docker/nginx/Dockerfile
volumes:
- ./docker/nginx/go-app.conf:/etc/nginx/conf.d/go-app.conf
ports:
- 10880:81
最後にコンテナを一旦潰してビルドして立ち上げてログを取ってみましょう
$ docker-compose down
# ...省略
$ docker-compose build --no-cache go-app
# ...省略
$ docker-compose up -d
# ...省略
$ docker-compose logs
go-app_1 |
go-app_1 | __ _ ___
go-app_1 | / /\ | | | |_)
go-app_1 | /_/--\ |_| |_| \_ 1.27.3, built with Go 1.16.3
go-app_1 |
go-app_1 | mkdir /go/src/tmp
go-app_1 | watching .
go-app_1 | watching cmd
go-app_1 | watching cmd/bin
go-app_1 | watching internal
go-app_1 | watching pkg
go-app_1 | !exclude tmp
go-app_1 | building...
go-app_1 | go: downloading github.com/labstack/echo v3.3.10+incompatible
go-app_1 | go: downloading github.com/labstack/gommon v0.3.0
go-app_1 | go: downloading golang.org/x/crypto v0.0.0-20200820211705-5c72a883971a
go-app_1 | go: downloading github.com/dgrijalva/jwt-go v3.2.0+incompatible
go-app_1 | go: downloading github.com/valyala/fasttemplate v1.2.1
go-app_1 | go: downloading github.com/mattn/go-colorable v0.1.7
go-app_1 | go: downloading github.com/mattn/go-isatty v0.0.12
go-app_1 | go: downloading github.com/valyala/bytebufferpool v1.0.0
go-app_1 | go: downloading golang.org/x/sys v0.0.0-20200826173525-f9321e4c35a6
go-app_1 | go: downloading golang.org/x/net v0.0.0-20200822124328-c89045814202
go-app_1 | go: downloading golang.org/x/text v0.3.3
go-app_1 | running...
go-app_1 |
go-app_1 | ____ __
go-app_1 | / __/___/ / ___
go-app_1 | / _// __/ _ \/ _ \
go-app_1 | /___/\__/_//_/\___/ v3.3.10-dev
go-app_1 | High performance, minimalist Go web framework
go-app_1 | https://echo.labstack.com
go-app_1 | ____________________________________O/_______
go-app_1 | O\
go-app_1 | ⇨ http server started on [::]:8080
できました。
まあ当たり前ですが、嬉しいですね。
airが動作しているかも確認してみましょう。
main.goファイルの中身を適当にいじってみます。
func main() {
fmt.Println("air動いてるよね？")
e := echo.New()
e.GET("/", func(c echo.Context) error {
return c.String(http.StatusOK, "Hello, World!")
})
e.Use(middleware.LoggerWithConfig(
middleware.LoggerConfig{
Format: "bytes_in=${bytes_in},bytes_out=${bytes_out},method=${method}, uri=${uri}, status=${status}, error=${error}\n",
Output: os.Stdout,
},
))
e.Logger.Fatal(e.Start(":8080"))
}
$ docker-compose logs
go-app_1 | cmd/main.go has changed
go-app_1 | building...
go-app_1 | running...
go-app_1 | air動いてるよね？
go-app_1 |
go-app_1 | ____ __
go-app_1 | / __/___/ / ___
go-app_1 | / _// __/ _ \/ _ \
go-app_1 | /___/\__/_//_/\___/ v3.3.10-dev
go-app_1 | High performance, minimalist Go web framework
go-app_1 | https://echo.labstack.com
go-app_1 | ____________________________________O/_______
go-app_1 | O\
go-app_1 | ⇨ http server started on [::]:8080
こんな感じで出ていれば完了です！
長くなりましたが、docker-compose logsでログが追えるようになりコンテナアクセスの必要はなくなりました。
今回ファイルをいくつも編集したりどこで実行したのかわかりづらかったりしたかもしれないので、完成形をGithubに載せておきました。
よかったら参考にしてください。
Discussion