Docker SDK for Goでコンテナのログをtailしてみる

こんにちわ

最近DockerのTUI Clientを作っていて、SDKでハマっていたところがあるので、
自分の備忘録として記事に残します。

2019/03/02 追記
HTTP/2の多重化ストリームと書きましたが、
Dockerは独自のフレームを定義してるのでHTTP/2ではなかったです。すいません。

Docker SDKとは

普段Dockerを使っている方なら知っていると思いますが、
Dockerコマンドは実はDocker Engine APIを叩いているだけです。
そのAPIを叩く部分をラッピングして使いやすくしたのでSDKです。

公式SDKはGoとPythonしかない様ですが、REST APIなのである程度自作はできると思います。
https://docs.docker.com/develop/sdk/

本日は、GoのDocker SDKを使ったコンテナログをtailする時に躓くポイントについて話していきます。

コマンドでコンテナログをtailする

普通にコマンドを実行するとこんな感じになります。

$ docker container logs -f mysql
Initializing database
2019-02-07T03:53:08.512874Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-02-07T03:53:09.514164Z 0 [Warning] InnoDB: New log files created, LSN=45790
2019-02-07T03:53:09.647195Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2019-02-07T03:53:09.716490Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: e24f13bf-2a8b-11e9-897a-0242ac180003.
2019-02-07T03:53:09.718579Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2019-02-07T03:53:09.719975Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2019-02-07T03:53:12.975444Z 1 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2019-02-07T03:53:12.975490Z 1 [Warning] 'user' entry 'mysql.session@localhost' ignored in --skip-name-resolve mode.
2019-02-07T03:53:12.975499Z 1 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2019-02-07T03:53:12.976376Z 1 [Warning] 'db' entry 'performance_schema mysql.session@localhost' ignored in --skip-name-resolve mode.
2019-02-07T03:53:12.976406Z 1 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2019-02-07T03:53:12.976691Z 1 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2019-02-07T03:53:12.977023Z 1 [Warning] 'tables_priv' entry 'user mysql.session@localhost' ignored in --skip-name-resolve mode.
2019-02-07T03:53:12.977056Z 1 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
Database initialized
Initializing certificates
Generating a RSA private key
...

これをSDKを使って同じ事をします。

SDKを使った場合

SDKではContainersLogsって関数が用意されていて、
それにcontext、コンテナID、オプションを渡すと、レスポンスが返ってきます。
そのレスポンスはdocker側が用意しているdocker/docker/pkg/stdcopy.StdCopyを使用して、標準・エラーに出力します。

package main

import (
	"context"
	"log"
	"os"

	"github.com/docker/docker/api/types"
	"github.com/docker/docker/client"
	"github.com/docker/docker/pkg/stdcopy"
)

func run() int {
	c, err := client.NewClientWithOpts(client.WithVersion("1.39"))
	if err != nil {
		return 1
	}

	r, err := c.ContainerLogs(context.Background(), "657814ba450f", types.ContainerLogsOptions{
		ShowStdout: true,
		ShowStderr: true,
		Follow:     true,
	})
	if err != nil {
		log.Println(err)
		return 1
	}

	_, err = stdcopy.StdCopy(os.Stdout, os.Stderr, r)
	if err != nil {
		log.Println(err)
		return 1
	}

	return 0
}

func main() {
	os.Exit(run())
}

ソースはこれだけですが、ちょっとストリーム多重化も関連してくるため、
その知識がないとつまずく方もいるかと思いますので、つまずきポイントについて解説していきます。

躓きポイント

ContainerLogsを使用すると多重化ストリームのレスポンスが返ってきます。
コンテナへのアタッチもこの原理で動いています。

多重化ストリームとは一つのコネクション上で、
複数のHTTPリクエスト＆レスポンスのやり取りを行うことができる仕組みとしてHTTP/2で導入されたものです。
詳しくはこちらの資料にわかりやすくまとめてあるので、興味ある方は読んでみてください。

すいません、間違えました。
Dockerでは自前で多重化ストリームを定義していました。
したがってHTTP/2は関係ないです。
ただ、多重化ストリームの考え方同じなはずなので、図のイメージで問題ないと思います。

Docker側で定められたフレーム定義に従って、
レスポンスを適切に処理して標準・エラー出力しないと、
正しい文字列を得られなくて、先頭に変な文字がついてたりします。

Y2019-03-01T07:14:51.672442Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
Z2019-03-01T07:14:51.673425Z 0 [Note] InnoDB: 5.7.24 started; log sequence number 12440262
E2019-03-01T07:14:51.673943Z 0 [Note] Plugin 'FEDERATED' is disabled.
g2019-03-01T07:14:51.674929Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-03-01T07:14:51.717753Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
N2019-03-01T07:14:51.728152Z 0 [Warning] CA certificate ca.pem is self signed.
U2019-03-01T07:14:51.730623Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
82019-03-01T07:14:51.730701Z 0 [Note] IPv6 is available.
@2019-03-01T07:14:51.730720Z 0 [Note]   - '::' resolves to '::';
H2019-03-01T07:14:51.730740Z 0 [Note] Server socket created on IP: '::'.

Docker側が定めたフレーム定義はこちらになります。

header := [8]byte{STREAM_TYPE, 0, 0, 0, SIZE1, SIZE2, SIZE3, SIZE4}

STREAM_TYPEは

• 0:stdin
• 1:stdout
• 2:stderr

となっています。
1なら、os.Stdoutに出力すると言った制御が必要です。

続いて、SIZE1, SIZE2, SIZE3, SIZE4はビッグエンディアン¹としてコンコードされた4バイトデータです。
こちらは、ストリームのフレーム（データの部分）の長さになります。

公式SDKでは以下のロジックで正しくデータを取得できると書いてあります。

1. Read 8 bytes.
2. Choose stdout or stderr depending on the first byte.
3. Extract the frame size from the last four bytes.
4. Read the extracted size and output it on the correct output.
5. Goto 1.

上記のロジックに従って、自前で制御するとこんな感じになります。

hdr := make([]byte, 8)
for {
    _, err := r.Read(hdr)
    if err != nil {
        log.Fatal(err)
    }
    var w io.Writer
    switch hdr[0] {
    case 1:
        w = os.Stdout
    case 2:
        w = os.Stderr
    default:
        // error handling
    }
    count := binary.BigEndian.Uint32(hdr[4:])
    dat := make([]byte, count)
    _, err = r.Read(dat)
    fmt.Fprint(w, string(dat))
}

ただ、自前で実装しなくてもDockerが用意している
github.com/docker/docker/pkg/stdcopy.StdCopy(dstout, dsterr io.Writer, src io.Reader)
を使えば簡単に標準・エラー出力できます。

まとめ

今回のようなストリーム型レスポンスを扱う上で、
HTTPの多重化ストリームの仕組みとエンディアンについて知識が必要になってきます。
これらの知識がなかったので、ちんぷんかんぷんでした。

やっとのこと理解できたので、忘れないうちに記事にしました。
今後DockerのSDKを使って何かつくおうと思っている方にとって、何か役に立てればと思います。

1. エンディアンはCPUによってデータをメモリ上に格納する方法が異なるります。推測になってしまうが、おそらくDocker側はビッグエンディアンに統一させているようです。 ↩