Goで開発して3年のプラクティスまとめ(4/4): HTTP Server/logger編

Goで開発して3年のプラクティスまとめ(4/4): HTTP Server/logger編

yet another入門記事です。

• part1 プロジェクトを始めるまで編
• part2 cliアプリをつくれるところまで編
• part3 concurrent GO編
• part4 HTTP Server/logger編: これ
• part5以降・・・未定(unlikely)

ご質問やご指摘がございましたらこの記事のコメントでお願いします。
(ほかの媒体やリンク先に書かれた場合、筆者は気付きません)

Overview

Goはhttp serverを実装できる強力なライブラリであるnet/httpを備えています。
httpで通信を行うソフトウェアを作る機会は多いというか、ほとんどのアプリが何かしらの通信を行うと思います。

• net/httpのClient / Serverの書き方を紹介します
  • client
    • サンプルとしてmultipart/form-dataを送信します
      • non-stream版とstream版を紹介し、副次的にio.Pipeの使い方を述べます
    • Clientをカスタマイズする方法に触れます
      • X-Request-Idを自動的にセットするhttp.RoundTripper
      • http.TransportのDialContextを差し替えて名前解決部分を変更する
  • server
    • stdのみでhttp serverを実装してみます
    • github.com/labstack/echoを使ってstdのみバージョンを書きなおします
  • oapi-codegenを使ってOpenAPI specからecho server interfaceを生成して、validatorを提供したサーバーを実装します。
• ロギングライブラリについて紹介します。
  • structured loggingのみに絞ります

この記事では読者はHTTPサーバーアプリの実装経験があるという前提で組まれています。プロトコルそのものや、例えばmultipart/form-dataとはなんなのか、みたいなことは説明されません。

2種の想定読者

記事中では仮想的な「対象読者」と「ベテランとして取り扱われるその他の読者」が想定されています。

対象読者

記事中で「対象読者」と呼ばれる人々は以下のことを指します。

• 会社の同僚
• いままでGoを使ってこなかった人
• ある程度コンピュータとネットワークとプログラムを理解している人
• pythonとかNode.jsで開発したことある
• gitは使える。
• 高校生レベルの英語能力
  • 作ってるところがアメリカ企業なので英語のリンクが全般的に多い

part1以降はA Tour of Goを完了していることと、
ポインター、メモリアロケーション、POSIX(もしくはLinux) syscallなどの基礎的概念がわかっていることが前提条件になっています。

そのほかの読者

特に断りがない時、他の読者も聴衆として想定されます。

• 筆者と同程度かそれ以上にGoに長じており
• POSIX APIや通信プロトコル、他のプログラミング言語でよくやられる方法を知っている

というベテラン的な人々です。

記事中に他にいい方法があったら教えてくださいとか書いてますが、大概はこのベテランな人たちに向けて書いているのであって、対象読者は当面気にしないでください(もちろんあったら教えてください)。

対象環境

• 下層の仕組みに言及するとき、特に述べない限りlinux/amd64を想定します。
• OS/archに依存するコードは書きません。

version

検証はgo 1.22.0、リンクとして貼るドキュメントは1.22.3のものになります。

## go version
go version go1.22.0 linux/amd64

最近追加されたAPIをちょいちょい使うので1.22.0以降でないと動かないコードがたくさんあります。

直近の3～4 minor versionのみサポートするライブラリが多いとして、Go 1.18でできなくてそれ以降できるようになったことは、○○以降となるだけ書くようにします。

サンプルコードのrepository

サンプルコードの一部は下記にアップロードされます。

https://github.com/ngicks/go-basics-example

HTTP client / server

現実的なソフトウェアを作るうえでHTTPを通じて通信を行うことは非常に多いと思います。

最近ではgRPCを使うことも多いかもしれません(と言いつつ筆者は製品で使ったことはありませんが)

HTTPで通信を行うclient / serverともにnet/httpで実装されます。下記でそれぞれポイントを紹介していきます。

HTTP client

https://pkg.go.dev/net/http@go1.22.3#pkg-overview

上記のoverviewにさっそく書いてありますが、http requestを送るためには

• Get
• Head
• Post
• PostForm

のいずれかを使うことができます。

ソースを見れば一発で分かりますが、これらはhttp.DefaultClientの同名メソッド呼び出しのショートハンドです。
簡単なcliアプリなら上記を使うのが簡単でいいですが、実際にはいろいろ困るケースがあります。

実際にある困ったケースを先に上げます

• cookieの保存が必要なった
• ctxにセットされているRequest-idをリクエストに引き渡す機能を付け足したくなった(後述)

そのため、なにかのclientを作る(e.g. ダウンローダーなど)ときはなるだけ*http.Clientを引数にとるようにしたほうが良いといえるでしょう。

cookieの保存はClientのJarフィールドに*(net/http/cookiejar).Jarインスタンスを渡せば大体のケースでokです。JarフィールドはCookieJarというinterfaceなので挙動を変えたい場合は上記net/http/cookiejar実装をラップするなりします。

*http.Clientを引数として受け取る

*http.Clientをfieldに持つようなstructは引数で*http.Clientを受けとれるようにしたほうがよいでしょう。

例えばその構造体が以下であるとして

type Downloader struct {
	// ... fields ...
}

// Download downloads anything from given url into specified storage.
// If the target server url points to accepts Range requests
// Downloader tries to ...(and anything like that)...
func (d *Downloader) Download(ctx context.Context, url *urlpkg.URL) error {
	// ...implementation...
}

おそらくフィールドを隠したいのでNew関数を作ると思います

func New() *Downloader {
	return &Downloader{
		// ... initialization ...
	}
}

ここで*http.Clientを受けとっておくとよいという話です。

func New(client *http.Client) *Downloader {
	return &Downloader{
		client: client,
		// ... rest of initialization ...
	}
}

実際にはFunctional options patternを使うほうが良いかもしれません。
http.DefaultClientで十分っていうケースもありうるので、デフォルト値を持たせるためです。

type option interface {
	apply(*Downloader)
}

type funcOpt func(*Downloader)

func(o funcOpt) apply(d *Downloader) {
	o(d)
}

func WithClient(client *http.Client) option {
	return funcOpt(func(d *Downloader) {
		d.client = client
	})
}

func New(opts ...option) *Downloader {
	d := &Downloader{
		client: http.DefaultClient,
		// ... rest of initialization ...
	}
	for _, o := range opts {
		o(d)
	}
	return d
}

*http.ClientのDoメソッド以外を呼び出すつもりもないので、HTTPRequestDoerを定義してそれを受けとるほうが良いかもしれません。

(筆者はacronymも頭文字以外は小文字にしたほうがいいよ派ですが、この記事中では全部大文字にしています)

type HTTPRequestDoer interface {
	Do(req *http.Request) (*http.Response, error)
}

func WithHTTPRequestDoer(doer HTTPRequestDoer) option {
	return funcOpt(func(d *Downloader) {
		d.doer = doer
	})
}

c := &http.Client{/*...*/}
New(WithHTTPRequestDoer(c))

一般にdata raceを避けるために引数に受け取った*http.Clientのフィールドに対してwriteを行うのはお勧めできない行為なので型の詳細はいりませんし、Doerのほうがtest doubleを用意しやすいのでこちらのほうが良いケースもたくさんあるでしょう。

Requestを送る(multipart/form-data)

普通のrequestの送り方はドキュメントを見ていたらすぐわかると思うので、基本から少し飛び出してmultipart/form-dataの送信のexampleを示します。

multipartのhttp requestを送るにはmime/multipartを使います。

コード例を先に示し、説明を後に乗せます。

non-stream版

snippet

import (
	"bytes"
	"context"
	"fmt"
	"io"
	"mime/multipart"
	"net/http"
	"strings"
)

func sendMultipart(ctx context.Context, url string, client *http.Client) error {
	randomMsg1 := strings.NewReader("foobarbaz")
	randomMgs2 := strings.NewReader("quxquuxcorge")

	/*
		1.
		multipart.NewWriter(w)でio.Writerをラップした*multipart.Writerを得る。
		各種メソッドの呼び出しの結果はwに逐次書き込まれる。
	*/
	var buf bytes.Buffer
	mw := multipart.NewWriter(&buf)

	/*
		2.
		CreateFormField, CreateFormFile, CreateFormFieldなど各種メソッドを呼び出すと
		--<<boundary>>
		content-disposition: form-data; name="foo"

		のようなヘッダーを書いたうえで、そのセクションの内容を書き込むためのio.Writerを返す。
	*/
	w, err := mw.CreateFormField("foo")
	if err != nil {
		return err
	}
	_, err = io.Copy(w, randomMsg1)
	if err != nil {
		return err
	}

	w, err = mw.CreateFormFile("bar", "bar.tar.gz")
	if err != nil {
		return err
	}
	_, err = io.Copy(w, randomMgs2)
	if err != nil {
		return err
	}

	/*
		3．
		*multipart.Writerは必ず閉じる。
		閉じなければ最後の--<<boundary>>--が書かれない。
	*/
	err = mw.Close()
	if err != nil {
		return err
	}

	/*
		4.
		http.NewRequestWithContextにデータを受けたbytes.Bufferを渡す。
		(*Writer).FormDataContentType()でboundary込みの"Content-Type"を得られるのせセットする。
	*/
	req, err := http.NewRequestWithContext(ctx, http.MethodPost, url, &buf)
	if err != nil {
		return err
	}
	req.Header.Add("Content-Type", mw.FormDataContentType())
	resp, err := client.Do(req)
	if err != nil {
		return err
	}
	_ = resp.Body.Close()
	if resp.StatusCode != http.StatusOK {
		return fmt.Errorf("not 200: code =%d, status = %s", resp.StatusCode, resp.Status)
	}
	return nil
}
/*
	header: User-Agent = Go-http-client/1.1
	header: Content-Length = 374
	header: Content-Type = multipart/form-data; boundary=3f297ee5803297f68c78b73c870aa54e7e083628eef2d2fb42560336909b
	header: Accept-Encoding = gzip
	bytes read: 374
	body=
	--3f297ee5803297f68c78b73c870aa54e7e083628eef2d2fb42560336909b
	Content-Disposition: form-data; name="foo"

	foobarbaz
	--3f297ee5803297f68c78b73c870aa54e7e083628eef2d2fb42560336909b
	Content-Disposition: form-data; name="bar"; filename="bar.tar.gz"
	Content-Type: application/octet-stream

	quxquuxcorge
	--3f297ee5803297f68c78b73c870aa54e7e083628eef2d2fb42560336909b--

*/

• 1. multipart.NewWriter(w)でio.Writerをラップした*multipart.Writerを得ます。*multipart.Writerから得られるio.Writerへの書き込みはこのwに書き込まれます。
• 2. (*Writer).CreateFormField、(*Writer).CreateFormFile、(*Writer).CreatePartなどでセクションのヘッダーを書き込んだうえで、セクション内容を書き込むためのio.Writerをえます。
  • 入力データソースがファイルなどの場合はio.Copyで書き込むとよいです。
  • io.Copyはsrcがio.WriterToあるいはdstがio.ReaderFromを実装しているときはそれらの実装を使いますが、それ以外は中間バッファをallocateしてしまいます。io.CopyBufferは中間バッファを渡せるので、前述のbuf poolと組み合わせてこちらを使うほうが良いかなと思います。今回に限っては*strings.Readerはio.WriterToを実装しているので、io.Copyで問題ありません。
• 3. *multipart.Writerは必ず閉じます。閉じなければ最後の--<<boundary>>--が書かれません。
• 4. (*Writer).FormDataContentTypeでboundary込みのContent-Typeを得られます。これは手動でセットする必要があります。

ただこの方法だと一旦bytes.Bufferなどにすべてのデータを受けてしまうことになり、各セクションのデータが大きい場合メモリ的負荷が高くなってしまいます。そこで、io.Pipeを使ってストリーム化します。

stream版

多分以下の方法がidiomaticだと思います。ご意見などお待ちしてます。

func sendMultipartStream(ctx context.Context, url string, client *http.Client) error {
	randomMsg1 := strings.NewReader("foobarbaz")
	randomMgs2 := strings.NewReader("quxquuxcorge")

	writeMultipart := func(mw *multipart.Writer, buf []byte, content1, content2 io.Reader) error {
		var (
			w   io.Writer
			err error
		)

		w, err = mw.CreateFormField("foo")
		if err != nil {
			return err
		}

		_, err = io.CopyBuffer(w, content1, buf)
		if err != nil {
			return err
		}

		w, err = mw.CreateFormFile("bar", "bar.tar.gz")
		if err != nil {
			return err
		}

		_, err = io.CopyBuffer(w, content2, buf)
		if err != nil {
			return err
		}

		err = mw.Close()
		if err != nil {
			return err
		}

		return err
	}

	/*
		1.
		一旦でセクション内容以外を書き出してデータサイズをえる。
		各セクションの内容がファイルなどであれば、
		サイズは既知であるのでこれでContent-Lengthを適切に設定できる。
	*/
	metaData := bytes.Buffer{}
	err := writeMultipart(multipart.NewWriter(&metaData), nil, bytes.NewBuffer(nil), bytes.NewBuffer(nil))
	if err != nil {
		return err
	}
	fmt.Printf("meta data size = %d\n\n", metaData.Len())

	/*
		2.
		io.Pipeでin-memory pipeを取得し、
		別goroutineの中でpw(*io.PipeWriter)にストリーム書き込みする。
		pwに書かれた内容はpr(*io.PipeReader)から読み出せるので、
		これをhttp.NewRequestWithContextに渡す。
	*/
	pr, pw := io.Pipe()
	mw := multipart.NewWriter(pw)
	defer pr.Close()
	go func() {
		/*
			3.
			goroutineの中で書き込む処理そのものは
			non-stream版とさほど変わらない
		*/
		var err error
		defer func() {
			_ = pw.CloseWithError(err)
		}()
		err = writeMultipart(mw, nil, randomMsg1, randomMgs2)
	}()

	ctx, cancel := context.WithCancel(context.Background())
	defer cancel()
	req, err := http.NewRequestWithContext(ctx, http.MethodPost, url, pr)
	if err != nil {
		return err
	}
	req.Header.Add("Content-Type", mw.FormDataContentType())
	/*
		4.
		ContentLengthを設定する。
		req.Header.Set("Content-Length", num)は無視されるので、必ずこちらを設定する。
	*/
	req.ContentLength = int64(metaData.Len()) + randomMsg1.Size() + randomMgs2.Size()

	// Doして終わり。
	resp, err := client.Do(req)
	if err != nil {
		return err
	}
	_ = resp.Body.Close()
	if resp.StatusCode != http.StatusOK {
		return fmt.Errorf("not 200: code =%d, status = %s", resp.StatusCode, resp.Status)
	}
	return nil
}
/*
	meta data size = 353

	header: User-Agent = Go-http-client/1.1
	header: Content-Length = 374
	header: Content-Type = multipart/form-data; boundary=83964749f5fbc8d761fef1243f6b8cdf2a55269c70b33cea5c838c1da7b3
	header: Accept-Encoding = gzip
	bytes read: 374
	body=
	--83964749f5fbc8d761fef1243f6b8cdf2a55269c70b33cea5c838c1da7b3
	Content-Disposition: form-data; name="foo"

	foobarbaz
	--83964749f5fbc8d761fef1243f6b8cdf2a55269c70b33cea5c838c1da7b3
	Content-Disposition: form-data; name="bar"; filename="bar.tar.gz"
	Content-Type: application/octet-stream

	quxquuxcorge
	--83964749f5fbc8d761fef1243f6b8cdf2a55269c70b33cea5c838c1da7b3--

*/

• 1. まず、bytes.Bufferにセクション内容以外のヘッダーデータを書きだしてサイズを得ておきます。
  • もちろんサイズはバウンダリのサイズから計算可能ですが、こうすれば間違えようがないのでこういうやり方をします。
  • Content-Lengthを適切に設定しないとリクエストを拒絶するサーバーが存在するため、事前にサイズを計算する必要があります。
• 2. 次にio.Pipeでin-memory pipeを作り、別goroutineの中でstream書き込みを行います。
  • io.Pipeはio.Writerをio.Readerに変換するようなもので、pw(*io.PipeWriter)に書かれた内容はpr(*io.PipeReader)から読み込めます。
  • 中間バッファを持たないので、別のgoroutineで動作させないとdeadlockを起こします。
  • pipe(2)に似ていますが、こちらはin-memoryです。pipe(2)に対応するのはos.Pipeです。
• 3. 書き込みの処理自体はnon-stream版と大して変わりません。
• 4. http.NewRequestWithContextにこのio.PipeReaderを渡し、req.ContentLengthに各セクションのヘッダーとトレイラーのサイズ+各セクションのサイズ(既知であるとする)をセットします。
  • 前述のnon-stream版ではこれを設定していませんでした。
  • これは特定のreaderの場合自動的にContentLengthが設定されるからです。
  • ちなみに、req.Header.Set("Content-Length", size)としても意味がなく、req.ContentLengthのみが尊重されます([1], [2], [3])。

とりあえずこのようにしておけば、筆者が体験する限りrequestがはじかれるようなことはありませんでした。
おそらくこれで行けてると思うんですが、ダメなケースがあるなどの場合コメントで教えていただけると幸いです。

*http.Clientを色々差し替える

Goのstdは全般的にいい感じの粒度でinterfaceに切り分けられているため、内部の挙動を実装をラップする形で差し替えたり変更するのが容易です。

http.Clientはドキュメントのとおり、redirectやcookieの挙動を制御するハイレベルなclientであり、1つのrequest-responseのトランザクションはhttp.RoundTripperで取り扱います。

これがinterfaceであるので、これの実装であるhttp.Transportをラップしたり、全く別な実装を与えることで挙動を変更することができます。

Example: Request-idをつける

HeaderにX-Request-Idがない場合付け足すRoundTripper実装です。

https://pkg.go.dev/net/http@go1.22.3#RoundTripper

// RoundTrip should not modify the request, except for
// consuming and closing the Request's Body.

と書かれています。以下実装ではmutationを防ぐためにreq.Cloneを呼んでdata raceを避けています。
ただし、これを行うとredirectのたびにCloneが呼ばれることになるので効率は悪いです。

context.Context経由でrequest-idが渡されるケースも想定してあります。

snippet

type keyTy string

const (
	RequestIdKey keyTy = "request-id"
)

type RequestIdTrapper struct {
	RoundTripper http.RoundTripper
}

func (t *RequestIdTrapper) RoundTrip(req *http.Request) (*http.Response, error) {
	req, err := addRequestID(req)
	if err != nil {
		return nil, err
	}
	return t.RoundTripper.RoundTrip(req)
}

func addRequestID(req *http.Request) (*http.Request, error) {
	if reqId := req.Header.Get("X-Request-Id"); reqId != "" {
		return req, nil
	}

	// Clone req to avoid data race.
	req = req.Clone(req.Context())

	reqId, _ := req.Context().Value(RequestIdKey).(string)

	if reqId == "" {
		var buf [16]byte
		_, err := io.ReadFull(rand.Reader, buf[:])
		if err != nil {
			return nil, fmt.Errorf("generating random X-Request-Id: %w", err)
		}
		reqId = fmt.Sprintf("%x", buf)
	}

	req.Header.Set("X-Request-Id", reqId)

	return req, nil
}

client := &http.Client{
	Transport: &RequestIdTrapper{RoundTripper: http.DefaultTransport},
}

これをechoなどのmiddlewareとlog/slogを組み合わせると一貫したロギングができるので調査がしやすくなります(後述)。

RoundTripperでやるのは邪道な感はあるので、できれば*http.Clientを呼び出す前の段階でaddReuqestIDを使ったほうがいいですね。

Example: 名前解決をgithub.com/miekg/dnsに差し替える

※例示であってセキュリティー的に安全なのかいまいちわかっていません。

http.RoundTripperの実装にはデフォルトでhttp.Transportが使われます。
Transportも内部の挙動を関数を差し替えるなりすることである程度手を入れさせてくれます。ここで、TransportのDialContextを差し替えることで名前解決の実装を変更できることを示します。

Goのstdで実装されるDNS Client部分はglibcなどのそれよりもforgivingな実装になっていないのか、github.com/miekg/dnsでは解決できるけどstdではできないということがあります。github.com/glang/goのissueを軽くさらったくらいじゃこの話題は出てこないので、多分ものすごく珍しい環境だとは思います。

そこで以下のようにDNS部分をpaepcke.de/dnsresolver経由でgithub.com/miekg/dns実装のDNSクライアントに差し替えます。

import (
	"context"
	"fmt"
	"net"
	"net/http"
	"net/netip"
	"os"
	"strings"
	"sync"
	"time"

	"github.com/miekg/dns"
	"paepcke.de/dnsresolver"
)

var (
	resolverOnce = sync.OnceValue(func() *dnsresolver.Resolver {
		// ResolverAutoが`/etc/resolve.conf`をLstatして存在チェックする。
		// wslやdockerなど一部環境はこれがsymlinkなので、その環境ではうまく動かない
		// そのため手動であらかじめStatしておいて、存在していれば明示的にそこを読み込ませる。
		if _, err := os.Stat("/etc/resolv.conf"); err == nil {
			return dnsresolver.ResolverResolvConf()
		}
		return dnsresolver.ResolverAuto()
	})
)

func dialer(fallbackOnly bool) func(ctx context.Context, network, addr string) (net.Conn, error) {
	d := &net.Dialer{
		Timeout:   30 * time.Second,
		KeepAlive: 30 * time.Second,
	}
	return func(ctx context.Context, network, addr string) (net.Conn, error) {
		var (
			host = addr
			port = ""
			err  error
		)
		if strings.Contains(addr, ":") {
			host, port, err = net.SplitHostPort(addr)
			if err != nil {
				return nil, err
			}
		}

		raw, _ := strings.CutPrefix(host, "[")
		raw, _ = strings.CutSuffix(raw, "]")
		_, err = netip.ParseAddr(raw)
		if err == nil {
			// turns out it is already a raw IP addr.
			return d.DialContext(ctx, network, addr)
		}

		if fallbackOnly {
			_, err := net.LookupHost(host)
			if err == nil {
				return d.DialContext(ctx, network, addr)
			}
		}

		r := resolverOnce()
		resolved, err := r.LookupAddrs(host, []uint16{dns.TypeA, dns.TypeAAAA})
		if err != nil {
			return nil, err
		}
		if resolved[0].Is4() {
			addr = resolved[0].String()
		} else {
			addr = "[" + resolved[0].String() + "]"
		}
		if port != "" {
			addr += ":" + port
		}
		return d.DialContext(ctx, network, addr)
	}
}

func main() {
	t := &http.Transport{
		Proxy:                 http.ProxyFromEnvironment,
		ForceAttemptHTTP2:     true,
		MaxIdleConns:          100,
		IdleConnTimeout:       90 * time.Second,
		TLSHandshakeTimeout:   10 * time.Second,
		ExpectContinueTimeout: 1 * time.Second,
	}
	t.DialContext = dialer(false)

	client := &http.Client{
		Transport: t,
	}
	var err error
	_, err = client.Get("https://www.google.com")
	// err = <nil>
	fmt.Printf("err = %v\n", err)
	_, err = client.Get("https://142.250.206.228:443")
	// err = Get "https://142.250.206.228:443": tls: failed to verify certificate: x509: cannot validate certificate for 142.250.206.228 because it doesn't contain any IP SANs
	fmt.Printf("err = %v\n", err)
	_, err = http.DefaultClient.Get("https://142.250.206.228:443")
	// err = Get "https://142.250.206.228:443": tls: failed to verify certificate: x509: cannot validate certificate for 142.250.206.228 because it doesn't contain any IP SANs
	fmt.Printf("err = %v\n", err)
	_, err = client.Get("https://[2404:6800:400a:804::2004]:443")
	// err = Get "https://[2404:6800:400a:804::2004]:443": dial tcp [2404:6800:400a:804::2004]:443: connect: cannot assign requested address
	fmt.Printf("err = %v\n", err)
}

とりあえず動いている。
実際上はfunc DialContext(ctx context.Context, network, addr string) (net.Conn, error)をラップするように実装したほうがいいと思いますし、stdをもうちょい掘ったら賢いaddrのハンドリング方法もある気がしますね。exampleとしてはこんなものかと思います。
SANがないのでIP直指定だとうまいこと動かないですが、それはそれとしてIPv4 addrを渡されたときのパターンとしては動いていますね。
IPv6 addrが直接渡された時も(おそらく)筆者の環境がIPv6契約していないからうまくいかないですがそれはそれとしてうまいこと下層のDialerに渡せているようですね。

paepcke.de/dnsresolverのソースは一通り読みましたが問題ないと判断して使っています。やはり結構面倒な都合がたくさん転がってるので、それをうまく処理してくれているように見えます。windowsで動くのかがよくわからないです。

DNS clientって何があるんですかね？こんな困りかたするの稀な気しますし、DNS server実装はいっぱいあってもclientはあんまりないように見えます。
筆者はDNSのメッセージフォーマットそのものをしっかり理解してgithub.com/miekg/dnsを直接使う方向に進もうかと思っています。
お勧めのDNS Clientあったら教えてください。

HTTP server

Goのhttp serverはstdの時点で非常に強力で、std以外を一切使わないで開発するというのも十分可能です。

stdのnet/httpだけでサーバーを実装するときにかかわる概念をざっくり切り分けると以下のようになります。

        +---------------+
        | addr / socket |
        +---------------+
               | socket
        +--------------+
        | net.Listener |
        +--------------+
               | conn (connection)
        +--------------+
        | *http.Server | for { conn := lis.Accept(); go server.Serve(conn) }
        +--------------+
               |
       +----------------+
       | *http.ServeMux | multiplexes http.Handler-s
       +----------------+
         | | | | | | | |  ...
+--------------+ +--------------+
| http.Handler | | http.Handler | ... Handle each request
+--------------+ +--------------+
      |
+-----------------------+
| worker struct, etc... | ... running in separate goroutines, etc...
+-----------------------+

addr / socket - net.Listener - *http.Serverまでの関係はPOSIXで言うところのsocket(2)してbind(2)してlisten(2)してfor-loopの中でaccept(2)するのと一致します。典型的なPOSIXプログラムはpthreadでハンドラを実行することになると思いますが、Goは代わりにgoroutineでハンドラを実行します

https://github.com/golang/go/blob/go1.22.3/src/net/http/server.go#L3254-L3286

*http.Serverは(net.Listener).Acceptした後さらにcontext.Contextをあれこれマネージしたり新しいgoroutineでconnからヘッダーを読んで*http.Request, http.ResponseWriterを用意したりしてHnadlerを呼び出します。

*http.ServeMuxはRouterのことです。
それ自体がhttp.Handlerで、他のhttp.Handlerをpath patternとともに登録しておくことで、http requestのPathに応じてroutingを行うmux(Multiplexer)であるということです。

ここで重要なのは、*http.Serverから上下に依存するnet.Listenerと*http.ServeMux・・・ではなくhttp.Handlerはどちらもinterfaceであり、これらの実装は差し替え可能なので、

• テストダブルへの差し替え
• net.Listenerに偽のnet.Connを返させることで、例えばstdin/stdoutごしにgRPCをさせる(できることまでは確認しています)

みたいなことができるということです。

muxという言い回し

筆者は初見の時muxという言い回しにピンとこずに困りました。muxはmultiplexerのことで、この略し方は別段Goに限らずされるときはされるみたいです。(e.g. tmux)

multiplexerという語自体ははデジタル回路を勉強したことがある対象読者は聞いたことがあることでしょう(アナログマルチプレクサも存在します)。回路などで言うmultiplexerは複数の情報ストリームを１つの信号線で流す多重化の仕組みことです。ソフトウェアの文脈で言えばHTTP/2/QUICが１つのTCP/UDPコネクションの上でstreamを複数流すことをmultiplexと言いますね。

stdのみ

skeleton

シンプルな構成は以下のようになります。

前述の構成図を逆順に初期化していく様に以下のように書けます。

下記の状態では、どのパスにアクセスされてもhandlerに到達するようになっています。

package main

import (
	"fmt"
	"net"
	"net/http"
)


func main() {
	// ... initialization of application ...

	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.WriteHeader(http.StatusOK)
		_, _ = w.Write([]byte(`{"result":"foobarbaz"}` + "\n"))
	})

	mux := http.NewServeMux()

	mux.Handle("/", handler)

	server := &http.Server{
		Handler: mux,
	}

	listener, err := net.Listen("tcp", "127.0.0.1:8080")
	if err != nil {
		panic(err)
	}

	fmt.Printf("listening = %s\n", listener.Addr())
	fmt.Printf("server closed = %#v\n", server.Serve(listener))
}

このサンプルではオミットされていますが実際にはhttp.Handlerから呼び出されるアプリケーションがあって、これらの初期化やリクエスト可能になるまでの準備を先に行うことになるでしょう。

Routing

mux.Handleはpath pattern, http.Handlerを登録しておくことができ、incoming requestのPathがもっとも一致するpath patternに登録されるhttp.Handlerにルーティングします。

http.HandlerFuncは関数func(w http.ResponseWriter, r *http.Request)をhttp.Handlerに変換するための型です。Goを書いているとこういう感じで関数や単なる変数がinterfaceを満たすことができるような型を作ることがよくあると思うので覚えておくほうが良いと思います。

// 他にマッチしないときここに必ずルートされる。
mux.Handle("/", handler)
mux.Handle("/foo", handler)
mux.Handle("/bar", handler)
mux.Handle("/baz/{id}", handler)

Go 1.22よりmux.Handleのpath patternの扱いに変更がいろいろはいりHTTP Methodをパターンに持つことができるようになりました。

// GETはGET/HEADでマッチ
mux.Handle("GET /foo", handler)
// {name}でpath paramを設定できる。muxを通過した後にハンドラ内でr.PathValue("name")でこのパスを取得できる。
mux.Handle("POST /foo/{parma}", handler)
// 上記のmethod付きにマッチしないときこっちにルーティングされるので、http.StatusMethodNotAllowedを返したいならこういうルートを作る。
mux.Handle("/foo", handler)
// 他にマッチしないときここに必ずルートされる。
mux.Handle("/", handler)

前述通り、各http.Handlerにはhttp.ResponseWriterと*http.Requestが渡されます。

handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	w.WriteHeader(http.StatusOK)
	_, _ = w.Write([]byte(`{"result":"foobarbaz"}` + "\n"))
})

rはclient側の実装で取り扱った*http.Requestと全く同じものなのでURLフィールドやHeaderフィールドを持っています。それらを判定に使うことができます。
wはio.Writerを実装するのでioパッケージの各種関数群やWriteメソッドを呼び出すことでresponseを書くことができます。

w.WriteHeaderでstatus codeとheaderを書き込んで、その後bodyを書き込むのは他の言語のフレームワークと同様です。

client側としてrequestを送る際はContent-Lengthヘッダーは無視されていましたが、serverがResponseを送る際はheaderの値が使われます。セットしなくても、1度きりのWriteしかしなかったりなどする場合は自動的につけられたりしますが、サイズが既知の場合はなるだけつけたほうがいいでしょうね。
コードを見る限りContent-Typeもsniffingによって自動的にセットされる挙動があるようですが、以下のコードのようなjsonはsniffingでは判別不可能なようです。手動でw.Header().Set("Content-Type", "application/json")しなければなりません。

snippet

mux.Handle("/", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	w.Header().Set("Content-Type", "application/json")
	if r.URL.Path != "" && r.URL.Path != "/" {
		w.WriteHeader(http.StatusNotFound)
		_, _ = w.Write([]byte(`{"err":"path not found"}` + "\n"))
		return
	}
	if r.Method != http.MethodHead && r.Method != http.MethodGet {
		w.WriteHeader(http.StatusMethodNotAllowed)
		_, _ = w.Write([]byte(`{"err":"method not allowed"}` + "\n"))
		return
	}
	if !strings.HasPrefix(r.Header.Get("Content-Type"), "application/json") {
		w.WriteHeader(http.StatusBadRequest)
		_, _ = w.Write([]byte(`{"err":"non json content type"}` + "\n"))
		return
	}
	w.WriteHeader(http.StatusOK)
	_, _ = w.Write([]byte(`{"result":"ok"}` + "\n"))
}))

example: JSON store

適当な例としてsync.Mapにtype Sample struct { Foo string; Bar int }なJSONを収めて取得できるハンドラを書いてみます。

type Sample struct {
	Foo string
	Bar int
}

func (s Sample) Validate() error {
	var builder strings.Builder
	if s.Foo == "" {
		builder.WriteString("missing Foo")
	}
	switch n := s.Bar; {
	case n == 0:
		if builder.Len() > 0 {
			builder.WriteString(", ")
		}
		builder.WriteString("missing Bar")
	case n < 0:
		if builder.Len() > 0 {
			builder.WriteString(", ")
		}
		builder.WriteString("negative Bar")
	case n > 250:
		if builder.Len() > 0 {
			builder.WriteString(", ")
		}
		builder.WriteString("too large > 250 Bar")
	}
	if builder.Len() > 0 {
		return fmt.Errorf("validation error: %s", builder.String())
	}
	return nil
}

type getResult struct {
	Key   string
	Value any    `json:",omitempty"`
	Err   string `json:",omitempty"`
}

type postResult struct {
	Key     string
	Prev    any    `json:",omitempty"`
	Swapped bool   `json:",omitempty"`
	Result  string `json:",omitempty"`
	Err     string `json:",omitempty"`
}

func main() {
	mux := http.NewServeMux()
	var store sync.Map
	mux.Handle("POST /pp/{key}", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "application/json")

		key := r.PathValue("key")

		enc := json.NewEncoder(w)
		enc.SetEscapeHTML(false)

		if !strings.HasPrefix(r.Header.Get("Content-Type"), "application/json") {
			w.WriteHeader(http.StatusBadRequest)
			_ = enc.Encode(postResult{Key: key, Err: "non json content type"})
			return
		}
		dec := json.NewDecoder(io.LimitReader(r.Body, 64<<20)) // hard limit on 64MiB
		dec.DisallowUnknownFields()
		var s Sample
		if err := dec.Decode(&s); err != nil {
			w.WriteHeader(http.StatusBadRequest)
			_ = enc.Encode(postResult{Key: key, Err: "bad request shape"})
			return
		}
		if dec.More() {
			w.WriteHeader(http.StatusBadRequest)
			_ = enc.Encode(postResult{Key: key, Err: "junk data after json value"})
			return
		}
		if err := s.Validate(); err != nil {
			w.WriteHeader(http.StatusBadRequest)
			_ = enc.Encode(postResult{Key: key, Err: err.Error()})
			return
		}

		prev, loaded := store.Swap(key, s)
		w.WriteHeader(http.StatusOK)
		_ = enc.Encode(postResult{Key: key, Prev: prev, Swapped: loaded, Result: "ok"})
	}))
	mux.Handle("GET /pp/{key}", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "application/json")

		key := r.PathValue("key")
		val, loaded := store.Load(key)
		if !loaded {
			w.WriteHeader(http.StatusNotFound)
			enc := json.NewEncoder(w)
			_ = enc.Encode(getResult{
				Key: key,
				Err: "not found",
			})
			return
		}
		w.WriteHeader(http.StatusOK)
		enc := json.NewEncoder(w)
		enc.SetEscapeHTML(false)
		_ = enc.Encode(getResult{
			Key:   key,
			Value: val,
		})
	}))
	mux.Handle("/pp/{key}", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "application/json")
		w.WriteHeader(http.StatusMethodNotAllowed)
		_, _ = w.Write([]byte(`{"err":"method not allowed"}` + "\n"))
	}))
	// ... listen and serve ...
}

snippetで実行して試せるようにしています。気になる場合は実行してみて試してみてください。

middlewareが欲しいし、結構ボイラープレートな処理がすでに発生していますね。
後述のgithub.com/labstack/echoを使う版ではこれを解決したいと思います。

context.Contextハンドリング

*http.ServerのBaseContextおよびConnContextフィールドにコールバック関数を渡すことで、サーバー全体/コネクション(=request)レベルでcontext.Contextをトラップして変更できます。
これらのcontext.Contextは(*http.Request).Contextで取得できますので、http.Handler内で呼ばれる関数にはこれが渡されることが多いでしょう。

ただし、(*http.Server).Closeを呼べば、このcontext.Contextはcancelされるので、context cancellationのために絶対にセットしないといけないということはありません。

package main

import (
	"context"
	"fmt"
	"log/slog"
	"net"
	"net/http"
	"os"
)

func main() {
	logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
	mux := http.NewServeMux()

	type keyTy string
	var (
		baseKey keyTy = "base-key"
		connKey keyTy = "conn-key"
	)
	server := &http.Server{
		Handler: mux,
		ConnContext: func(ctx context.Context, c net.Conn) context.Context {
			return context.WithValue(ctx, connKey, "conn")
		},
		BaseContext: func(l net.Listener) context.Context {
			return context.WithValue(context.Background(), baseKey, "base")
		},
	}

	mux.Handle("/", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		logger.Info(
			"context",
			slog.Any(string(baseKey), r.Context().Value(baseKey)),
			slog.Any(string(connKey), r.Context().Value(connKey)),
		)
	}))

	listener, err := net.Listen("tcp", "127.0.0.1:8080")
	if err != nil {
		panic(err)
	}

	logger.Info(fmt.Sprintf("listening = %s", listener.Addr()))
	logger.Info(fmt.Sprintf("server closed = %v", server.Serve(listener)))
}
// time=2024-06-24T12:03:57.577Z level=INFO msg=context base-key=base conn-key=conn

Graceful shutdown

*http.Serverのgraceful shutdownには(*http.Server).Shutdown, 強制的な終了には(*http.Server).Closeを用います。

Shutdownは新規のリクエストの受付を止め、現在処理中のリクエストの処理完了を無限に待ち、すべて終わるとnilをリターンします。
そのため、Shutdownにはcontext.Contextを渡すことができ、処理完了待ち中にこれがcancelされるとそのctx.Err()が返されます。
渡すcontextはcontext.WithTimeoutなどを用いてタイムアウトできるようにしておくとよいでしょう。

(*http.Server).RegisterOnShutdownでシャットダウン時に呼ばれるコールバック関数を登録できます。これによってWebsocketなどのhttpをHijackするような通信をシャットダウンするようにシグナルするとよいとドキュメントに書かれています。

Closeが呼ばれると、(*http.Request).Context()で返されるcontextはcancelされます。
新しいrequestが来た時点で、connは別goroutineでRead待ちの状態になっており[1][2], Closeがこれらのconnを閉じる[3]ことでエラーが起きます,それによってrequestの親contextがcancelされます[4][5]

snippet

package main

import (
	"context"
	"errors"
	"fmt"
	"log/slog"
	"net"
	"net/http"
	"os"
	"os/signal"
	"sync"
	"syscall"
	"time"
)

func main() {
	logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
	mux := http.NewServeMux()

	mux.Handle("/", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		logger.Info("blocking on context")
		<-r.Context().Done()
		logger.Info("context canceled", slog.Any("err", r.Context().Err()), slog.Any("cause", context.Cause(r.Context())))
	}))

	server := &http.Server{
		Handler: mux,
	}

	server.RegisterOnShutdown(func() {
		logger.Info("on shutdown")
	})

	listener, err := net.Listen("tcp", "127.0.0.1:8080")
	if err != nil {
		panic(err)
	}

	var wg sync.WaitGroup
	wg.Add(1)
	go func() {
		defer wg.Done()
		logger.Info(fmt.Sprintf("listening = %s", listener.Addr()))
		// Serveでブロックしておく
		logger.Info(fmt.Sprintf("server closed = %v", server.Serve(listener)))
	}()

	// 別のgoroutineでsignal待ちに入る
	wg.Add(1)
	go func() {
		defer wg.Done()

		// signal.Notifyでsignalを待ち受ける。
		// とりあえずSIGINT, SIGTERMで事足りる。環境によって決める。
		sigChan := make(chan os.Signal, 10)
		signal.Notify(sigChan, os.Interrupt, syscall.SIGTERM)

		// signalされるまで待つ。このサーバーはsignalされる以外に終了する手段がない
		sig := <-sigChan
		// osによらないメッセージを得られるのでprintしてもよい
		logger.Warn(fmt.Sprintf("signaled with %q", sig))

		// Shutdownは新しいrequestの受付を止めたうえで、処理中のrequestのresponseが帰るまで待つ。
		// 上記Handler中ではブロックしたままなのでこのctxは必ずtimeoutする。
		ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
		defer cancel()
		logger.Info("requesting shutting down the server")
		err := server.Shutdown(ctx)
		logger.Error("server shutdown error", slog.Any("err", err))

		// 渡したcontext.Contextのキャンセルによるエラーなのかは下記のようにするとわかる。
		// ただし、内部的に作成されたcontext.Contextのtimeoutやcancellationは検知できない。
		// あくまで、このctxが返したエラーなのかどうかだけ。
		// errors.Is(err, context.DeadlineExceeded)あるいは
		// errors.Is(err ,context.Canceled)のほうが良い時もある。
		if err != nil && errors.Is(err, ctx.Err()) {
			logger.Error("closing server")
			err := server.Close()
			logger.Error("server close error", slog.Any("err", err))
		}
	}()

	wg.Wait()
}

以下でserverを起動し

# go run .

別のターミナルでリクエストします。

# curl localhost:8080/

以下のようなログが出ます。^CはCtrl+Cを押したたときにターミナルに表示されます。

time=2024-06-24T12:19:42.066Z level=INFO msg="listening = 127.0.0.1:8080"
# handlerがblock
time=2024-06-24T12:19:43.640Z level=INFO msg="blocking on context"
# ^Cでinterrupt
^Ctime=2024-06-24T12:19:45.409Z level=WARN msg="signaled with \"interrupt\""
time=2024-06-24T12:19:45.409Z level=INFO msg="requesting shutting down the server"
# Serveは即座にリターン
time=2024-06-24T12:19:45.409Z level=INFO msg="server closed = http: Server closed"
# RegisterOnShutdownで登録された関数が呼ばれている
time=2024-06-24T12:19:45.409Z level=INFO msg="on shutdown"
# 10秒たったのでtimeout
time=2024-06-24T12:19:55.410Z level=ERROR msg="server shutdown error" err="context deadline exceeded"
time=2024-06-24T12:19:55.410Z level=ERROR msg="closing server"
# handlerがunblock
time=2024-06-24T12:19:55.410Z level=INFO msg="context canceled" err="context canceled" cause="context canceled"
time=2024-06-24T12:19:55.410Z level=ERROR msg="server close error" err=<nil>

ちょっとわかりにくいですが、Closeを呼び出した後にhttp.HandlerでブロックしていたDone()がunblockされています。

github.com/labstack/echo

stdのnet/httpをラップする形でmiddlewareの追加などを提供するライブラリがあります。
net/httpを使わない別の方向に進んだライブラリももちろんあるんですがここではそれらは取り扱いません。

• gin
• chi
• echo

あたりが有名だと思います。

筆者はgithub.com/labstack/echoしか使ったことがないので他の詳細はわかりませんがおそらくおおむね似たような形になっていると思います。

以下で、stdのみでつくったAPIをechoを使って再実装してみます。

基本的には公式のドキュメントをあたってください: https://echo.labstack.com/

package main

import (
	"context"
	"fmt"
	"net"
	"net/http"
	"strings"
	"sync"

	"github.com/labstack/echo/v4"
)

func main() {
	e := echo.New()
	e.HideBanner = true
	e.HidePort = true

	var store sync.Map
	g := e.Group("/pp")
	g.POST("/:key", func(c echo.Context) error {
		c.Logger().Infof("request id associated with ctx: %s", c.Request().Context().Value(RequestIdKey))
		key := c.Param("key")

		if !strings.HasPrefix(c.Request().Header.Get("Content-Type"), "application/json") {
			return c.JSON(http.StatusBadRequest, postResult{Key: key, Err: "non json content type"})
		}

		var s Sample
		err := c.Bind(&s)
		if err != nil {
			return c.JSON(http.StatusBadRequest, postResult{Key: key, Err: "binding: " + err.Error()})
		}
		if err := s.Validate(); err != nil {
			return c.JSON(http.StatusBadRequest, postResult{Key: key, Err: err.Error()})
		}

		prev, loaded := store.Swap(key, s)
		return c.JSON(http.StatusOK, postResult{Key: key, Prev: prev, Swapped: loaded, Result: "ok"})
	})
	g.GET("/:key", func(c echo.Context) error {
		key := c.Param("key")
		val, loaded := store.Load(key)
		if !loaded {
			return c.JSON(http.StatusNotFound, getResult{Key: key, Err: "not found"})
		}
		return c.JSON(http.StatusOK, getResult{Key: key, Value: val})
	})

	// e.Start("127.0.0.1:8080") // You can use echo's Start to let it handle listener and server!

	server := &http.Server{
		Handler: e,
	}

	listener, err := net.Listen("tcp", "127.0.0.1:8080")
	if err != nil {
		panic(err)
	}
	fmt.Printf("listening = %s\n", listener.Addr())
	fmt.Printf("server closed = %v\n", server.Serve(listener))
}

ボイラープレートが減りましたね

• (*echo.Echo).Groupサブパス以下のrouter groupを作成できます。
• *echo.Echoあるいは*echo.GroupのGET, POST, DELETE, PUTなどのメソッドで、http methodを絞ったルーティングができます。
• echo.Context.Bindでパスパラメータやボディーのペイロードなどを構造体などに代入できます。
  • この場合、Content-Typeを見た判別が行われるのでrequestにContent-Typeが入っていないと、sには何も束縛されないままエラーしません。
  • json出ないといけないとかの場合、middlewareなどではじいておくほうが良いです。
• (echo.Context).JSONなどで、特定のデータフォーマットでresponseを書くことができます。
  • responseにContent-Typeも付きます。
• (*echo.Echo).Startでサーバーを開始できますが、listenerやserverの細かい制御がしたいので、http.Handlerとしてのみここでは使っています。

(*echo.Echo).Use,(*echo.Echo).Preあるいは(*echo.Group).Useでmiddlewareを追加できます。
Node.jsでの開発経験がある対象読者にはexpress.jsやkoaでなじみ深い概念だと思います。

例えばhandlerの処理前+後にそれぞれログを残すには

import (
	"context"
	"fmt"
	"net"
	"net/http"
+	"os"
	"strings"
	"sync"

	"github.com/labstack/echo/v4"
+	"github.com/labstack/gommon/log"
)

// ...

func main() {
	// ...
+	e.Logger.SetOutput(os.Stdout)
+	e.Logger.SetLevel(log.DEBUG)
+	e.Use(func(next echo.HandlerFunc) echo.HandlerFunc {
+		return func(c echo.Context) error {
+			c.Logger().Infof("received path = %s", c.Request().URL.Path)
+			err := next(c)
+			if err != nil {
+				c.Logger().Errorf("err: %#v", err)
+			} else {
+				c.Logger().Infof("no error")
+			}
+			return err
+		}
+	})
	// ...
}

例えば、requestのヘッダーについているX-Request-Idか、ない場合はランダム生成した文字列をresponseのX-Request-Idヘッダーに追加しながら、
(*http.Request).Context()にそのrequest-idをセットするには以下のようにします。

import (
	"context"
	"fmt"
	"net"
	"net/http"
	"os"
	"strings"
	"sync"

	"github.com/labstack/echo/v4"
+	"github.com/labstack/echo/v4/middleware"
	"github.com/labstack/gommon/log"
)

// ...

+type keyTy string
+
+const (
+	RequestIdKey keyTy = "request-id"
+)
+
+func modifyConfig[T any](base T, fn func(c T) T) T {
+	return fn(base)
+}

func main() {
	// ...
+	e.Pre(middleware.RequestIDWithConfig(modifyConfig(
+		middleware.DefaultRequestIDConfig,
+		func(conf middleware.RequestIDConfig) middleware.RequestIDConfig {
+			conf.RequestIDHandler = func(ctx echo.Context, s string) {
+				ctx.SetRequest(ctx.Request().WithContext(context.WithValue(ctx.Request().Context(), RequestIdKey, s)))
+			}
+			return conf
+		},
+	)))
	// ...
}

github.com/oapi-codegen/oapi-codegen: OpenAPI code generator

OpenAPIとは

https://github.com/OAI/OpenAPI-Specification

OpenAPIはHTTP APIの定義フォーマットです。プログラミング言語によらないフォーマットでAPIを定義することでプログラミング言語間で共有したり、これをもとにcode generationによってserver stubやclientを生成したりします。

gRPCが専用の中間言語とバイナリフォーマットを定義するのに対して、こちらはyaml形式などで記述し、実際にサーバー間でやり取りされるデータはapplication/jsonやapplication/xmlなどです。

Go向けのcode generatorは

• https://github.com/OpenAPITools/openapi-generator
• https://github.com/oapi-codegen/oapi-codegen
• https://github.com/ogen-go/ogen

あたりが有名です。
筆者はhttps://github.com/OpenAPITools/openapi-generatorとhttps://github.com/oapi-codegen/oapi-codegenを試したことがあります。
https://github.com/OpenAPITools/openapi-generatorは、複数のプログラミング言語向けのコードを出力できることを強みとしていますが、１年ほど前の時点では実装しやすいserver stubやclientなどをうまいことえられず、
断念して各プログラミング言語でそれぞれに実装されたものを用いるようにしています。現在はどうなっているのかわかりませんので対象読者はそれぞれよく検討していただくのがいいかと思います。

現在(2024/06時点)のOpenAPIの最新バージョンは3.1.0ですが、https://github.com/oapi-codegen/oapi-codegenが追従していないので3.0.3を使うことをお勧めします。

github.com/oapi-codegen/oapi-codegen

https://github.com/oapi-codegen/oapi-codegen/tree/v2.3.0

OpenAPI specを読み込んで、client, model, 各種ライブラリ(std, echo, chiなど)を用いたserver stubなどを作成してくれるcode generatorやライブラリです。
この実装はGoのコードのみを生成します。他の言語向けの実装は個別に探してください。

v.2.3.0現在、stdおよび数々のライブラリを用いるサーバーを生成でき、strict-serverオプションをつければrequest bodyからモデルをパーズして、ハンドラでresponseのモデルを返せる状態のserver interfaceが生成されるほか、oneOfおよびallOf(バグはある(後述))、さらにnullable-typeオプションでT | null | undefinedなJSONのフィールドもうまく扱えます。すごい！

以下でちょろっとサンプルを通じて使い方を説明します。
詳しいことはsnippetを見てください。

まずOpenAPIをyamlで記述したり、oapi-codegen向けのconfigを置いたりするディレクトリを作成します。
構成的には./apiディレクトリを作るのがお勧めですかね。./api以下にspecなどを置くのはgRPCでもよくやる慣習ですし、中見てprotoファイルがあるか.openapi.ymlがあるかでどっちのサーバーかよくわかります。(どっちも提供したい場合はちょっと悩ましいですが。)
この例では1つしかOpenAPI specを書かないので./api直下にファイルを並べていますが、複数ある場合などはさらにサブディレクトリを作ったほうが良いかもしれません。

.
|-- api
|   |-- api.openapi.yml
|   |-- gen.go
|   `-- option.yml
|-- go.mod
`-- go.sum

option.ymlを設定します。これはcode generatorに読ませるオプションファイルです。
筆者はechoしか使ったことないのでechoのサーバーにします。clientもついでに作っときます。go getでこのモジュールを取り込んだらclient実装が使えるようになって便利です。(snippetはgo getできないローカルオンリーモジュールですので単に例示です。)

option.yml

package: api
generate:
  echo-server: true
  strict-server: true
  client: true
  models: true
  embedded-spec: true
output: api.gen.go
output-options:
  nullable-type: true

gen.goはgo:generateでgithub.com/oapi-codegen/oapi-codegenを実行するだけのファイルです。ここに書くとばらけなくていいと思ってますが、別に好きな方法でgeneratorを呼び出せばいいと思います。

gen.go

package api

//go:generate go run github.com/oapi-codegen/oapi-codegen/v2/cmd/oapi-codegen@v2.3.0 -config option.yml ./api.openapi.yml

api.openapi.ymlはなんか適当なサンプルとして書いてるだけなので深い意味はないですが、OpenAPIフォーマットそのものの例示にはいいかもしれないです。
これそのものを深く解説するつもりはないので、これに詳しくない対象読者は前記のOpenAPI specificationのgithubページなどを読んでフォーマット詳細を調べてください。

ちなみにgitlabは拡張子openapi.yml|openapi.yaml|openapi.jsonなどのファイルをSwaggerEditorで描画してくれます。それが嫌なら別の名前にしましょう。

api.openapi.yml

openapi: "3.0.3"
info:
  version: 1.0.0
  title: Generate models
paths:
  /foo:
    get:
      responses:
        200:
          content:
            application/json:
              schema:
                $ref: "#/components/schemas/FooMap"
        500:
          content:
            application/json:
              schema:
                $ref: "#/components/schemas/FooError"
    post:
      requestBody:
        content:
          application/json:
            schema:
              $ref: "#/components/schemas/Foo"
      responses:
        200:
          content:
            application/json:
              schema:
                $ref: "#/components/schemas/Foo"
        400:
          content:
            application/json:
              schema:
                $ref: "#/components/schemas/FooError2"
components:
  schemas:
    Foo:
      type: object
      required:
        - name
        - rant
      properties:
        name:
          type: string
        rant:
          type: string
    FooMap:
      type: object
      additionalProperties:
        $ref: "#/components/schemas/Foo"
    FooError:
      oneOf:
        - $ref: "#/components/schemas/Error1"
        - $ref: "#/components/schemas/Error2"
        - $ref: "#/components/schemas/Error3"
    FooError2:
      allOf:
        - $ref: "#/components/schemas/Error1"
        - $ref: "#/components/schemas/Error2"
        - $ref: "#/components/schemas/Error3"
    Error1:
      type: object
      properties:
        foo:
          type: string
          nullable: true
    Error2:
      type: object
      properties:
        bar:
          type: string
          nullable: true
    Error3:
      type: object
      properties:
        baz:
          type: string
          nullable: true

go generateでgen.goの//go:generateコメントを呼び出します。

go generate ./...

詳しくはsnippetで確認してほしいのですが、strict-serverオプションが有効なので以下のようなinterfaceが出力されます。

// StrictServerInterface represents all server handlers.
type StrictServerInterface interface {

	// (GET /foo)
	GetFoo(ctx context.Context, request GetFooRequestObject) (GetFooResponseObject, error)

	// (POST /foo)
	PostFoo(ctx context.Context, request PostFooRequestObject) (PostFooResponseObject, error)
}

ではこのinterfaceを実装しましょう。この例では./serverに実装するものとして

.
|-- api
|   |-- api.openapi.yml
|   |-- gen.go
|   `-- option.yml
|-- go.mod
-`-- go.sum
+|-- go.sum
+`-- server
+    `-- server.go

server.go

package server

import (
	"context"
	"fmt"
	"http-server-oapi-codegen/api"
	"math/rand/v2"
	"sync"

	"github.com/oapi-codegen/nullable"
)

var _ api.StrictServerInterface = (*serverInterface)(nil)

type serverInterface struct {
	m *sync.Map
}

func New() api.StrictServerInterface {
	return &serverInterface{
		m: new(sync.Map),
	}
}

// (GET /foo)
func (s *serverInterface) GetFoo(ctx context.Context, request api.GetFooRequestObject) (api.GetFooResponseObject, error) {
	foos := make(map[string]api.Foo)
	s.m.Range(func(key, value any) bool {
		foos[key.(string)] = value.(api.Foo)
		return true
	})
	if len(foos) == 0 {
		var fooErr api.FooError
		err := fooErr.FromError1(api.Error1{Foo: nullable.NewNullableWithValue("yay")})
		if err != nil {
			fmt.Printf("err = %v\n", err)
			return nil, err
		}
		return api.GetFoo404JSONResponse(fooErr), nil
	}
	return api.GetFoo200JSONResponse(foos), nil
}

// (POST /foo)
func (s *serverInterface) PostFoo(ctx context.Context, request api.PostFooRequestObject) (api.PostFooResponseObject, error) {
	rand := rand.N(10)

	switch rand { //機嫌が悪いとエラー
	case 0:
		return api.PostFoo400JSONResponse(api.FooError2{
			Foo: nullable.NewNullableWithValue("yay"),
		}), nil
	case 1:
		return api.PostFoo400JSONResponse(api.FooError2{
			Bar: nullable.NewNullableWithValue("yay"),
		}), nil
	case 2:
		return api.PostFoo400JSONResponse(api.FooError2{
			Baz: nullable.NewNullableWithValue("yay"),
		}), nil
	default:
		s.m.Store(request.Body.Name, *request.Body)
		return api.PostFoo200JSONResponse(*request.Body), nil
	}
}

この例ではinterface以上のことをするつもりがないのでNewはapi.StrictServerInterface interfaceを返しています。
一般にinterfaceへのメソッドの追加は破壊的変更なので、それを避けるために関数は具体的な型を返したほうが良いことが多いです。
フィールドの追加や型へのメソッドの追加は破壊的変更ではないとみなされるからです。
今回の例ではこのサーバーはinterfaceで定義されるmethod set以外のメソッドを実装することは決してないので、interfaceで直接返しています。

エントリポイントを作ります。

.
|-- api
|   |-- api.gen.go
|   |-- api.openapi.yml
|   |-- gen.go
|   `-- option.yml
+|-- cmd
+|   `-- server
+|       `-- main.go
|-- go.mod
|-- go.sum
`-- server
    `-- server.go

github.com/oapi-codegen/echo-middlewareなど、それぞれのサーバー向けmiddlewareを利用するとOpenAPI specに基づいたvalidationがかかるとドキュメントされています。

main.go

package main

import (
	"fmt"
	"net"
	"net/http"

	"http-server-oapi-codegen/api"
	"http-server-oapi-codegen/server"

	"github.com/labstack/echo/v4"
	echomiddleware "github.com/oapi-codegen/echo-middleware"
)

func main() {
	e := echo.New()

	spec, err := api.GetSwagger()
	if err != nil {
		panic(err)
	}

	e.Use(echomiddleware.OapiRequestValidator(spec))

	api.RegisterHandlersWithBaseURL(e, api.NewStrictHandler(server.New(), nil), "")

	server := &http.Server{
		Handler: e,
	}

	listener, err := net.Listen("tcp", "127.0.0.1:8080")
	if err != nil {
		panic(err)
	}
	fmt.Printf("listening = %s\n", listener.Addr())
	fmt.Printf("server closed = %v\n", server.Serve(listener))
}

embedded-spec: trueなので、生成されたコードの中に圧縮されたOpenAPI specが埋め込まれています。
これをapi.GetSwaggerで取得すると、echomiddleware.OapiRequestValidatorに直接渡せます。

これでサーバーを立ててリクエストをすると

# curl http://127.0.0.1:8080/foo -X POST -H 'Content-Type:application/json' -d '{"name":"foo"}'
{"message":"request body has an error: doesn't match schema #/components/schemas/Foo: Error at \"/rant\": property \"rant\" is missing"}
# curl http://127.0.0.1:8080/foo -X POST -H 'Content-Type:application/json' -d '{"name":"foo","rant":"🤬"}'
{"name":"foo","rant":"🤬"}
# curl http://127.0.0.1:8080/foo
{"foo":{"name":"foo","rant":"🤬"}}

おお機能していますね。必要なキーがない時にvalidationエラーが起きています。

サーバーを起動しなおしてoneOfやallOfのエラーがうまく機能するか確認しましょう。

# curl http://127.0.0.1:8080/foo
{}

あれっ。うまく機能しないですね。

よくよく生成されたコードを見てみると

type GetFoo404JSONResponse FooError

func (response GetFoo404JSONResponse) VisitGetFooResponse(w http.ResponseWriter) error {
	w.Header().Set("Content-Type", "application/json")
	w.WriteHeader(404)

	return json.NewEncoder(w).Encode(response)
}

ここのせいですね。FooErrorはMarshalJSONを実装しますが、type A BとするとAはBのmethod setを継承しません。
MarshalJSONがないので、型の情報に基づいてmarshalされるわけですが、FooErrorは

// FooError defines model for FooError.
type FooError struct {
	union json.RawMessage
}

となっています。exportされないfieldはjson.Marshalに無視されるので、何もフィールドのないJSON Objectが出力されるわけです。

ですので

diff

type GetFoo404JSONResponse FooError

func (response GetFoo404JSONResponse) VisitGetFooResponse(w http.ResponseWriter) error {
	w.Header().Set("Content-Type", "application/json")
	w.WriteHeader(404)

	return json.NewEncoder(w).Encode(FooError(response))
}

とするとうまく機能しますね。おしいです。

#970ですでにissueになっています。MRもすでにいくつかありますので貢献も不要そうです。

筆者はv1.14.0(このexampleはv2.3.0)あたりで使っていましたが、そのころはoneOfのサポートがそもそもミリもなかったのでかなり進歩しています。かなり便利になって感動してます。

こういった問題はテキスト置換をするスクリプトをcode generatorの後に適用すればよいので、対象読者がこの問題に引っかかった場合はそのようにするなどして解決してください。
前述通り、versionが進めば直るでしょうから生成されるコードを注視しておいたほうが良いです。

(もしかしたら後日、astを置換して修正するタイプのcode generatorの記事のサンプルとしてこういったケースに対応するかも。)

log/slog: structured logging

ログはプログラムを作って運用する場合に重要なトピックとなります。

ログを書くことでプログラムの一連のイベントの発生を保存することができます。
大抵のソフトウェアが手元で動かないため、
このような手掛かりがなければ不審な動きや不具合が起きたときに原因を調べるのが非常に難しくなります。

Go 1.21よりstdでlog/slogというstructured logging(構造化ロギング)のためのライブラリを提供されるようになりました。

structured loggingとは

structured loggingと言えば対象読者的にはstructlogとかwinstonが想像されるでしょうか？
これらを使いこなしていた対象読者には下の説明は不要なので飛ばしてください。

structured loggingというのは言葉の通り構造化された情報をログとして出力することを指しています。
構造化とは言っていますが、スキーマが存在していることを指しているわけではないようです。

これは、ものすごい乱暴に言うとJSON(or yaml, xml,csv,MessagePack, etc etcのような任意のデータ構造を表現できるフォーマット)でログを出力できるということです。
JSONなので、処理に合わせて情報を付け足したり任意の構造に構築できます。

// 普通ログは出力時間、ログレベル、メッセージを含みますよね
{"time":"2024-06-13T15:20:39.178198009Z","level":"DEBUG","msg":"happening of some event"}
// JSONなので任意に情報を追加しても容易にパーズできます。
{"time":"2024-06-13T15:20:39.178198009Z","level":"DEBUG","msg":"happening of some event", "additional_info":"message for a","request":{"path":"/foo","method":"POST"}}

任意の情報を追加したいときは、一連のイベントをログエントリ上で追跡したかったり、特定の状態に落ちたことを検知したいときなどだと思います。

例えば、http serverで動くプログラムを作るとき、http requestをきっかけとして起きる一連のイベントを追跡したいことはよくあると思います。
この時、追跡のための情報としてX-Request-Idヘッダーから取り出したrequest-idや、リクエストを受けとった時間、clientが指定したパラメータなどをログに出力しようと考えることになるでしょう。
この時、それらの情報をログのコンテキスト(以後log contextと呼ばれる)として引きまわせば一連のログにそれらの情報が出力することができます。
出力されたログに対してgrepやjqを駆使すれば簡単に任意のコンテキストを追跡することができます。

上記より、structured loggingの重要な要素として以下があります。

• log contextをlogger objectに結び付けられること
  • 情報は任意に追加して累積できる
• log contextは任意の構造であること
  • winstonの例で行くとObject
  • structlogで言うとdict[str, Any]
  • Goのlog/slog場合は[]slog.Attr
• ログ出力時にはそれらの情報の構造を任意のフォーマットに変換して出力できること

一般に、ログ出力時間、ログレベル、ロガーメソッドを呼び出したソースコード上の短い名前などを出力したいという要求があるため、特に設定を行わなくてもロガーメソッドを呼ぶだけでこれらの情報がlog contextに追加されて出力されることが多いです。

上記の話を踏まえるとものすごくnaiveな実装は以下のようになります。

playground

仮想的なstructured_logger.go

type Logger struct {
	arbitraryLoggingContext map[string]any
}

func (l *Logger) Log(msg string) {
	lc := maps.Clone(l.arbitraryLoggingContext)

	// 出力時間は自動的に追加されることが多い
	lc["time"] = time.Now().String()

	// 呼び出し関数、ソースの名前と行番号は自動で追加さることが多い
	var pcs [1]uintptr
	runtime.Callers(2, pcs[:])
	fs := runtime.CallersFrames([]uintptr{pcs[0]})
	f, _ := fs.Next()
	lc["caller"] = fmt.Sprintf("%s:%d:%s", f.File, f.Line, f.Function)

	lc["msg"] = msg

	// log levelはこの例では出てこない

	bin, _ := json.Marshal(lc)
	bin = append(bin, []byte("\n")...)
	os.Stdout.Write(bin)
}

func main() {
	logger := Logger{arbitraryLoggingContext: make(map[string]any)}

	// loggerには情報が紐づく
	logger.arbitraryLoggingContext["request-id"] = r.Header.Get("X-Request-Id")
	logger.arbitraryLoggingContext["param"] = r.Header.Get("Parameter-A")
	logger.arbitraryLoggingContext["request-received-at"] = time.Now().String()

	logger.Log("foobar")
	// {"caller":"/tmp/sandbox4050927908/prog.go:53:main.main","msg":"foobar","param":"param-a","request-id":"1111111111","request-received-at":"2009-11-10 23:00:00 +0000 UTC m=+0.000000001","time":"2009-11-10 23:00:00 +0000 UTC m=+0.000000001"}

	// 情報は追加できる
	logger.arbitraryLoggingContext["added"] = "added massage"

	logger.Log("bazbazbaz")
	// {"added":"added massage","caller":"/tmp/sandbox4050927908/prog.go:58:main.main","msg":"bazbazbaz","param":"param-a","request-id":"1111111111","request-received-at":"2009-11-10 23:00:00 +0000 UTC m=+0.000000001","time":"2009-11-10 23:00:00 +0000 UTC m=+0.000000001"}
}

third partyのstructured loggerライブラリ

サードパーティにもstructured loggerのライブラリがたくさんあります。

• github.com/sirupsen/logrus(in maintainance mode)
• github.com/rs/zerolog
• go.uber.org/zap

log/slogのstd入りが最近(2023-08-08)なので、上記のどれかや似たようなサードパーティロギングライブラリを使っていることも多いのではないでしょうか。
パフォーマンスその他でこれらのライブラリを使うこともあると思いますが、stdに入っていて安定しているという点でlog/slogに強みがあり、おそらく大概のケースでlog/slogを使うほうが良いと思われます。

Basic API

playground

slog.SetDefault(slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelDebug})))

// Top level function = uses default logger
slog.Debug("foo", "a", "a", "b", 2, "c", map[string]any{"foo": "bar"})
// time=2009-11-10T23:00:00.000Z level=DEBUG msg=foo a=a b=2 c=map[foo:bar]

// Same as top level function
slog.Default().Debug("foo", "a", "a", "b", 2, "c", map[string]any{"foo": "bar"})
// time=2009-11-10T23:00:00.000Z level=DEBUG msg=foo a=a b=2 c=map[foo:bar]

// Newly allocated instance methods
logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelDebug}))
logger.Info("foo", "a", "a", "b", 2, "c", map[string]any{"foo": "bar"})
// {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"foo","a":"a","b":2,"c":{"foo":"bar"}}

// Add key-value pairs to logging context
logger = logger.With("foo", "bar")
logger.Error("baz", "a", "b", "c", 123)
// {"time":"2009-11-10T23:00:00Z","level":"ERROR","msg":"baz","foo":"bar","a":"b","c":123}

• slog.Debugのようなトップレベル関数はDefaultLoggerの同名メソッドへのショートハンドです
  • slog.SetDefaultでセットできます
  • slog.Defaultで、セットされたloggerを取り出せます。
• slog.Newで新しいインスタンスを作ることもできます。
• Debug, Infoの第二引数はvariadicで、緩い型付けのkey-value pairないしはslog.Attrを任意の数渡すことができます。
• Withでlog contextに情報を追加したloggerをえられます。

pythonはkeyword argumentがあったり、winstonではObjectをそのまま渡すことが多かったりします。
Goにはそういったものはないですし、Objectみたいにmap[string]anyを書くのは煩雑だったりするので、variadic argとWithのようなメソッドで解決する形になります。

log contextのストレージ

log contextを引きまわすことですべてのログにトレースIDを乗せることができますが、引き回す方法がそのままコードの複雑さに跳ね返ります。
すでに前述のとおり、*slog.Logger(というかslog.Handler)にlog contextを関連付けることができることは述べましたが、実はcontext.Contextによって引きまわすこともできます。

• *slog.Logger
  • というかslog.Handler
  • With, WithAttrs, WithGroupで任意の情報をlog contextに追加したlogger objectが作られる
• context.Context
  • *slog.LoggerにはInfoContext(ctx context.Context, msg string, args ...any)のようなメソッドがあり、これから情報を引き出してログに乗せることが想定されています。
  • 大抵の長く動作する関数は第一引数でこれを受け取ります。
    • WithValueによって任意の情報を任意のキーに関連付けた形で格納したcontext.Contextを得られることができる
    • Valueメソッドによって、キーに関連づいた情報を引き出せる
  • ただし、log/slogで提供されるslog.Handler(slog.TextHandler、slog.JSONHandler)はcontext.Contextから情報を引き出してログに乗せる機能を提供しない(Go1.22.4時点)。
    • なのでサンプルとしてcontext.Contextをとって格納された値をログに乗せるslog.Handlerのexampleを実装します(後述)

普通、マルチスレッドなプログラムはTLS(Thread Local Storage)にスレッド固有なデータを入れるものらしいです。
POSIX APIで言えばpthread_getspecific(3p)で取り出します。

と言いつつ、TLS自体対象読者にとってはあまりなじみない何かだと思います。
なぜなら通常pythonもNode.jsもasyncなコンテキストを追跡するAPIを提供し、通常そちらを使うことが多いからなはずだからです。

• Node.js: AsyncLocalStorage
• python: contextvars
  • structlogはcontextvarsをサポートする
• Rust(Tokio): tokio::task::LocalKey

これらはすべてasyncなコンテキストごとにデータを保存できるのでこれらをlog contextのストレージとして使うことができました。
言及しておいてなんですが、tokio::task::LocalKeyは触ったことがないのでどういう制約があるのかはさっぱりです。

Goはgoroutineを特定する方法が通常ないことからわかる通り、goroutineローカル的な考え自体がありません。
*slog.Loggerやcontext.Contextのような明確な方法でlog contextをやり取りします。

log contextを構築する

• (*log/slog.Logger).Withで情報をlog contextに追加した*slog.Loggerを得られます。
  • Node.jsのwistonで言うところのchild
• (*log/slog.Logger).WithGroupでlog contextを1段ネストします
  • 以後Withなどに渡された情報はこのgroup以下に追加していきます。
• context.Contextから情報を抜き出す方法に特にこれといった標準はありません。前述のとおり、log/slogに実装されるHandlerでこれから情報を取り出すものはありません。

WithGroupの動作は癖が強いですね。doc commentにも書かれていますが、以下二つは同じログを出力します。

logger.WithGroup("s").LogAttrs(ctx, level, msg, slog.Int("a", 1), slog.Int("b", 2))
logger.LogAttrs(ctx, level, msg, slog.Group("s", slog.Int("a", 1), slog.Int("b", 2)))

WithGroupは与えられた名前のgroupを作成し、以後Withなどで情報を渡された場合そのgroupに追加されます。
ものすごい乱暴に言うと、group名のフィールドをJSONに追加し、以後情報をそのフィールド以下にobjectとして追加していきます。

つまり以下のように動作します。

playground

// {/*ここにいる*/}
logger = logger.WithGroup("s")
// {"s":{/*ここにいる*/}}
logger = logger.With("a", 1)
// {"s":{"a":1/*ここにいる*/}}
logger = logger.With("b", 2)
// {"s":{"a":1,"b":2/*ここにいる*/}}
logger = logger.WithGroup("t")
// {"s":{"a":1,"t":{/*ここにいる*/}}}
logger.Info("foo", "b", 2, "c", 3)
// {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"foo","s":{"a":1,"b":2,"t":{"b":2,"c":3}}}

log/slogの関係図

もう少し踏み込んで関係性を説明します。

+--------------------+
| consumer of logger |
+--------------------+
          |  key-value(loosely typed pair), []slog.Attr
   +--------------+
   | *slog.Logger | convert variadic args into Attr or Record, add convenient methods(Info, Debug, etc)
   +--------------+
          |  slog.Record, []slog.Attr
   +--------------+
   | slog.Handler | manage logging context and structure, write log to output.
   +--------------+
          | `[]byte`, etc...
      +--------+
      | output | os.Stdout, remote logging service, etc...
      +--------+

*slog.Loggerはslog.Handlerを使いやすいinterfaceに整えるものです。

• interface間で変換を行います。
  • InfoContextやDebugContextなどのleveled method -> slog.Handler.Handle
  • (args ...any)のloosely typed pair -> []slog.Attr
    • string, anyのペアとslog.Attrの混在が許されます。

slog.Handlerはstructured logging contextを実際の出力フォーマットに変換して出力するものです。

• Handler実装は現状stdには
  • TextHandler
  • JSONHandler
  • の二つしかありません。現実的にはこの二つ以外を使うことはまれでしょう。
• *slog.HandlerOptionsでログ出力するレベルの制限やAttrの書き換えなどを行います。
• WithAttrs,WithGroupでstructured logging contextを構築できます。
  • WithAttrsメソッドは呼ばれた時点でログを部分的に書きだしてバッファーしておくなどの最適化のためにinterface上のメソッドになっているようです。
  • 実際これらを全く使わずに、渡すslog.Attrを工夫でも全く同じ構造のログを書きだせます。

loggerの引き回し方

// defaultを使う
logger := slog.Default()

// 引数で受け取る
func New(logger *slog.Logger) *Something {
	// ...
}
// 引数で受け取る2
func (*Something) someWork(ctx context.Context, logger *slog.Logger) error {
	// ...
}

// context.WithValueでctxに付与する
type keyTy string
const (
	SlogLoggerKey keyTy = "*slog.Logger"
)

logger, ok := ctx.Value(SlogLoggerKey).(*slog.Logger)
if !ok || logger == nil {
	logger = slog.Default()
}

筆者がぱっと思いつくのは上記三つくらいです。

• 1. defaultを使う方法はもっとも簡単です
  • slog.Defaultを使うので設定してくださいとドキュメントに書いても読まれない可能性があるのでやや堅くない印象を受けます。
  • ライブラリごとに出力先を変えたいなどの要求があるとき、呼び出し側にコントロールがないのでそこがいまいちに感じるときがあります。
• 2. 引数で受け取る方法はこの中で最も明示的です
  • functional options patternを併用すると、interface上気付きやすく、なおかつデフォルトも持たせられるのでバランスがいいかもしれません
  • 代わりにライブラリの使用者は個別にloggerの渡し方を考える必要があって手間ではあります。
  • unexport functionは引数でloggerを受けとることは多いかもしれません。
• 3. context.WithValueでctxに付与する
  • おそらく最も非明示的です
  • どのcontext keyに*slog.Loggerをつけるかの同意をとるのが最も難しいです
    • std内での使い方などを見ると、ctxにValueを持たせるのは公開interface上に情報を出さず、なおかつ特定の条件のみ与えられるoptionalな値など(=context-scopeの値)を引き渡すのに有用な手段という雰囲気を感じます。
    • http.ServerContextKeyみたいに公開された値としてctxに値を載せてくるstdライブラリももちろんあります。
  • その代わりに、httpのrequest-scopeのような狭い情報を付与したloggerを引き回せるのでログの取りやすさは圧倒的に楽だと思います。
  • test doubleをctxに値としてつけて引きまわすやり方をしている方も多いと思いますので、驚き自体は少ないと思います。

ライブラリを作るなら1.か2.。アプリ内なら3.もありという感じではないでしょうか。

筆者は2.,3.を併用してます。

example: context-handler: ctxからkey-valueを取り出すslog.Handler

前述の「ライブラリに引数として*slog.Loggerを渡すことで明示的コントロールを行う」と「request-scopeな情報を引き出せる」のいいとこどりをするためのslog.Handler実装を通して、このinterfaceの実装のコツというか癖みたいなのを述べたいと思います。

基本的かつ詳細な情報はこちらをご覧ください:https://golang.org/s/slog-handler-guide

(*log/slog.Logger).LogおよびfoobarContextのような名前のメソッドは第一引数にcontext.Contextを受けとることができ、これから情報を引き出してログに乗せることができます。

他の関数がcontext.Contextを第一引数で受けるときと違い、これはcancellationをとるためではなく、値を取り出すためだけに渡されます。
ただしlog/slogで現状(Go1.22.4時点)で実装されるslog.Handlerはcontext.Contextから情報を引き出す機能がありません。

ということで、context.Contextから事前に定義したkeyの情報取り出してログに乗せるslog.Handlerを作成してみます。

設計は適当に以下とします

• context.Contextから情報を引き出し、log contextに追加できる
• context.Contextから情報を引き出す際、
  • 特定のキー(SlogAttrsKey)に[]slog.Attrが関連づけられていることを想定する
  • 任意のキーを任意のlog context上のキーに関連付けられるようにする

なので、

• 任意キーとlog context上のキー名をマッピングできる
  • map[any]string
• 任意キーから取り出した任意の値を変換できる
  • []func(any) any
• 任意キーのlog context上での出現順序を定義できる
  • []string
• 任意キーのlog context上のgroup名を指定できる
  • ない場合はトップレベルに追加する

このぐらいやれば驚きのない挙動が作れますかね？

ポイントとしては

• WithGroupがslog.Handlerのもつ内部状態を変更してしまうので、単に内部slog.Handlerの同名メソッドを呼ぶだけでは足りない
• slogtest.Run, slogtest.TestHandlerで大まかな挙動のテストができる
  • ただしこのテストはslog.HandlerがWithGroupで作られた現在のgroupに情報を付け足すパターンを想定しないので、そういう実装にすると通過しなくなる。
• 各種メソッドはconcurrentに呼び出されることになるのでdata raceを避ける気づかいが必要になる

ぐらいですかね

snippet

package main

import (
	"bytes"
	"context"
	"crypto/rand"
	"encoding/hex"
	"encoding/json"
	"errors"
	"fmt"
	"io"
	"log/slog"
	"os"
	"slices"
	"sync"
	"testing/slogtest"
	"time"
)

type keyConverter struct {
	key     any
	convert func(v any) any
}

type groupAttr struct {
	name string
	attr []slog.Attr
}

type ctxHandler struct {
	inner        slog.Handler
	ctxGroupName string
	keyMapping   map[any]string
	keyOrder     []keyConverter
	groups       []groupAttr
}

var _ slog.Handler = (*ctxHandler)(nil)

func newCtxHandler(inner slog.Handler, ctxGroupName string, keyMapping map[any]string, keyOrder []keyConverter) (slog.Handler, error) {
	if len(keyMapping) != len(keyOrder) {
		return nil, errors.New("ctxHandler: mismatching len(keyMapping) and len(keyOrder)")
	}
	for _, k := range keyOrder {
		if k.key == SlogAttrsKey {
			return nil, fmt.Errorf("ctxHandler: keyOrder must not include %s", SlogAttrsKey)
		}
		_, ok := keyMapping[k.key]
		if !ok {
			return nil, errors.New("ctxHandler: keyOrder contains unknown key")
		}
	}
	return &ctxHandler{
		inner:        inner,
		ctxGroupName: ctxGroupName,
		keyMapping:   keyMapping,
		keyOrder:     keyOrder,
		groups:       []groupAttr{{name: "top"}},
	}, nil
}

func (h *ctxHandler) Enabled(ctx context.Context, level slog.Level) bool {
	return h.inner.Enabled(ctx, level)
}

func (h *ctxHandler) Handle(ctx context.Context, record slog.Record) error {
	ctxSlogAttrs, _ := ctx.Value(SlogAttrsKey).([]slog.Attr)

	var ctxAttrs []slog.Attr
	for _, k := range h.keyOrder {
		v := ctx.Value(k.key)
		if k.convert != nil {
			v = k.convert(v)
		}
		ctxAttrs = append(ctxAttrs, slog.Attr{Key: h.keyMapping[k.key], Value: slog.AnyValue(v)})
	}

	topGrAttrs := h.groups[0].attr
	if len(ctxSlogAttrs) > 0 {
		topGrAttrs = append(topGrAttrs, ctxSlogAttrs...)
	}
	if h.ctxGroupName == "" {
		topGrAttrs = append(ctxAttrs, slices.Clone(topGrAttrs)...)
	}

	// reordering attached attrs.
	//
	// ctx attrs alway come first.
	// Groups come latter.
	// Attrs attached to record will be added to last group if any,
	// otherwise will be attached back to the record.

	var attachedAttrs []slog.Attr
	record.Attrs(func(a slog.Attr) bool {
		attachedAttrs = append(attachedAttrs, a)
		return true
	})
	if len(attachedAttrs) > 0 {
		// dropping attrs
		record = slog.NewRecord(record.Time, record.Level, record.Message, record.PC)
	} else {
		// But you must call Clone anyway.

		// https://pkg.go.dev/log/slog#hdr-Working_with_Records
		//
		// > Before modifying a Record, use Record.Clone to create a copy that shares no state with the original,
		// > or create a new Record with NewRecord and build up its Attrs by traversing the old ones with Record.Attrs.
		record = record.Clone()
	}
	if h.ctxGroupName != "" {
		record.AddAttrs(slog.Attr{Key: h.ctxGroupName, Value: slog.GroupValue(ctxAttrs...)})
	}
	record.AddAttrs(topGrAttrs...)
	if len(h.groups) == 1 {
		record.AddAttrs(attachedAttrs...)
	}

	groups := h.groups[1:]
	if len(groups) > 0 {
		g := groups[len(groups)-1]
		groupAttr := slog.Attr{Key: g.name, Value: slog.GroupValue(append(attachedAttrs, g.attr...)...)}
		if len(groups) > 1 {
			groups = groups[:len(groups)-1]
			for i := len(groups) - 1; i >= 0; i-- {
				g := groups[i]
				groupAttr = slog.Attr{Key: g.name, Value: slog.GroupValue(append(slices.Clone(g.attr), groupAttr)...)}
			}
		}
		record.AddAttrs(groupAttr)
	}
	return h.inner.Handle(ctx, record)
}

func (h *ctxHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	if len(attrs) == 0 {
		return h
	}
	groups := slices.Clone(h.groups)
	g := groups[len(groups)-1]
	g.attr = append(slices.Clone(g.attr), attrs...)
	groups[len(groups)-1] = g
	return &ctxHandler{
		inner:        h.inner,
		ctxGroupName: h.ctxGroupName,
		keyMapping:   h.keyMapping,
		keyOrder:     h.keyOrder,
		groups:       groups,
	}
}

func (h *ctxHandler) WithGroup(name string) slog.Handler {
	if name == "" {
		return h
	}
	return &ctxHandler{
		inner:        h.inner,
		ctxGroupName: h.ctxGroupName,
		keyMapping:   h.keyMapping,
		keyOrder:     h.keyOrder,
		groups:       append(slices.Clone(h.groups), groupAttr{name: name}),
	}
}

type keyTy string

const (
	RequestIdKey keyTy = "request-id"
	SyncMapKey   keyTy = "sync-map"
	SlogAttrsKey keyTy = "[]slog.Attr"
)

func must[V any](v V, err error) V {
	if err != nil {
		panic(err)
	}
	return v
}

func main() {
	wrapHandler := func(h slog.Handler, ctxName string) (slog.Handler, error) {
		return newCtxHandler(
			h,
			ctxName,
			map[any]string{
				RequestIdKey: "request-key",
				SyncMapKey:   "values",
			},
			[]keyConverter{
				{key: RequestIdKey},
				{key: SyncMapKey, convert: func(v any) any {
					m, ok := v.(*sync.Map)
					if !ok {
						return nil
					}
					values := map[string]any{}
					m.Range(func(key, value any) bool {
						values[key.(string)] = value
						return true
					})
					return values
				}},
			},
		)
	}

	randomId := hex.EncodeToString(must(io.ReadAll(io.LimitReader(rand.Reader, 16))))
	store := &sync.Map{}
	store.Store("foo", "foo")
	store.Store("bar", 123)
	store.Store("baz", struct {
		Key   string
		Value string
	}{"baz", "bazbaz"})

	ctx := context.Background()
	ctx = context.WithValue(ctx, RequestIdKey, randomId)
	ctx = context.WithValue(ctx, SyncMapKey, store)
	ctx = context.WithValue(
		ctx,
		SlogAttrsKey,
		[]slog.Attr{
			slog.Group("g1", slog.Any("a", time.Monday)),
			slog.Group("g2", slog.String("foo", "bar")),
		},
	)

	for _, ctxGroupName := range []string{"", "ctx"} {
		logger := slog.New(
			must(
				wrapHandler(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelDebug}),
					ctxGroupName,
				),
			),
		)
		logger.DebugContext(ctx, "yay", slog.String("yay", "yayay"))
		logger.With("foo", "bar").WithGroup("nah").With("why", "why not").DebugContext(ctx, "nay")
	}
	/*
		{"time":"2024-06-16T15:24:07.981165471Z","level":"DEBUG","msg":"yay","request-key":"753572e4a2215c4226ea745baa4a8ab3","values":{"bar":123,"baz":{"Key":"baz","Value":"bazbaz"},"foo":"foo"},"g1":{"a":1},"g2":{"foo":"bar"},"yay":"yayay"}
		{"time":"2024-06-16T15:24:07.981226197Z","level":"DEBUG","msg":"nay","request-key":"753572e4a2215c4226ea745baa4a8ab3","values":{"bar":123,"baz":{"Key":"baz","Value":"bazbaz"},"foo":"foo"},"foo":"bar","g1":{"a":1},"g2":{"foo":"bar"},"nah":{"why":"why not"}}
		{"time":"2024-06-16T15:24:07.98123834Z","level":"DEBUG","msg":"yay","ctx":{"request-key":"753572e4a2215c4226ea745baa4a8ab3","values":{"bar":123,"baz":{"Key":"baz","Value":"bazbaz"},"foo":"foo"}},"g1":{"a":1},"g2":{"foo":"bar"},"yay":"yayay"}
		{"time":"2024-06-16T15:24:07.981248289Z","level":"DEBUG","msg":"nay","ctx":{"request-key":"753572e4a2215c4226ea745baa4a8ab3","values":{"bar":123,"baz":{"Key":"baz","Value":"bazbaz"},"foo":"foo"}},"foo":"bar","g1":{"a":1},"g2":{"foo":"bar"},"nah":{"why":"why not"}}
	*/
	var buf bytes.Buffer
	handler := must(wrapHandler(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}), ""))

	err := slogtest.TestHandler(
		handler,
		func() []map[string]any {
			// fmt.Println(buf.String())
			var ms []map[string]any
			for _, line := range bytes.Split(buf.Bytes(), []byte{'\n'}) {
				if len(line) == 0 {
					continue
				}
				var m map[string]any
				if err := json.Unmarshal(line, &m); err != nil {
					panic(err)
				}
				ms = append(ms, m)
			}
			return ms
		},
	)
	fmt.Printf("slogtest.TestHandler = %v\n", err)
	// slogtest.TestHandler = <nil>
}

snippetではHandleまで下層のslog.Handlerを触らないようにしています。これは前述のWithGroupとWithAttrsがlog contextにlogを部分的に書き込む挙動があるために、log contextトップレベルに情報を付け足す場合はこれらのメソッドを呼ぶことができないからです。

前述のとおり、以下の二つは同じログを出力し、

logger.WithGroup("s").LogAttrs(ctx, level, msg, slog.Int("a", 1), slog.Int("b", 2))
logger.LogAttrs(ctx, level, msg, slog.Group("s", slog.Int("a", 1), slog.Int("b", 2)))

なおかつ、WithGroupやWithAttrsはhandler内でlog contextをすべてクローンしたうえで部分的なlogを書き出してバッファしておく挙動があります。

トップレベルに情報を後付けしたい今回のユースケースではこれらのmethodのこの挙動が邪魔になってしまうので、Handleまでは呼び出すことができません。

思いのほか面倒ですね。パフォーマンスと使いやすさと間違いにくさの折り合いがつくのがこの辺だったのでしょう。

実際zapのパフォーマンステストを見ても、そこまでめちゃくちゃ遅い感じはしないです。already has 10 fields of contextのテスト(=WithAttrsをあらかじめ呼んである)では結構パフォーマンスがいいですから、この最適化は有効に機能しているということでしょう。

ここら辺がもうちょい簡単だったらXmlHandlerも例示してみようかなとか考えていたんですが、難しそうなのでやめておきました。(そもそもxmlとmap[string]anyの相互変換が難しいのでそのせいでslogtest.TestHandlerに通しにくいのもある)

example: echo middlewareでcontext.Contextに*slog.Loggerを持たせる

example request-idをつけるのところで述べた、*slog.LoggerとX-Request-Idとcontext.Contextの組み合わせの話です。

echoのmiddlewareで*http.Requestにぶら下がるcontext.Contextに*slog.Loggerを関連付け、関連付ける*slog.LoggerにWithでRequest-Idを渡します。

こうすることで、Handlerは*http.Requestのcontext.Contextからロガーを取り出せば、常にRequest-Idの付いたログを行うことができるため、サービス間串刺しでのログ追跡が容易になります。

context.Contextへの値の関連付けは簡単化のためにgithub.com/ngicks/go-common/contextkeyを作って筆者はそれを利用することにしています。

snippet

package main

import (
	"crypto/rand"
	"fmt"
	"io"
	"log/slog"
	"net"
	"net/http"
	"os"

	"github.com/labstack/echo/v4"
	"github.com/ngicks/go-common/contextkey"
)

func main() {
	e := echo.New()
	e.HideBanner = true
	e.HidePort = true

	baseLogger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{}))

	e.Use(func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			reqId := c.Request().Header.Get("X-Request-Id")
			if reqId == "" {
				var bytes [16]byte
				_, err := io.ReadFull(rand.Reader, bytes[:])
				if err != nil {
					return err
				}
				reqId = fmt.Sprintf("%x", bytes)
			}
			c.SetRequest(
				c.Request().WithContext(
					contextkey.WithSlogLogger(
						c.Request().Context(),
						baseLogger.With(slog.String("request-id", reqId)),
					),
				),
			)
			return next(c)
		}
	})

	// fallback先にio.Discardに書き込むloggerを用意しておくと、context.Contextにロガーがない時ログを出さないという決断ができます。
	nopLogger := slog.New(slog.NewTextHandler(io.Discard, nil))
	e.GET("/", func(c echo.Context) error {
		logger := contextkey.ValueSlogLoggerFallback(c.Request().Context(), nopLogger)
		logger.Info("request")
		return nil
	})

	server := &http.Server{
		Handler: e,
	}

	listener, err := net.Listen("tcp", "127.0.0.1:8080")
	if err != nil {
		panic(err)
	}
	fmt.Printf("listening = %s\n", listener.Addr())
	fmt.Printf("server closed = %v\n", server.Serve(listener))
}

# client
curl localhost:8080/
# server
{"time":"2024-06-24T16:56:42.005664845Z","level":"INFO","msg":"request","request-id":"237d0641b8fe95e3fbf9b874f3c9308e"}
# client
curl localhost:8080/ -H 'X-Request-Id:foobar'
# server
{"time":"2024-06-24T16:57:01.051332767Z","level":"INFO","msg":"request","request-id":"foobar"}

ちゃんとついていますね。

さいごに

軽い気持ちで社内向けに書いていたドキュメントを強化してやるかと思って始めたんですが、ファイルサイズが５倍以上に膨れ上がっても全くまだまだカバーすべき内容はカバーしきれていないと来ています。
さすがにそろそろ疲れたのでここまでにしておきます。

• part1 プロジェクトを始めるまで編
• part2 cliアプリをつくれるところまで編
• part3 concurrent GO / HTTP Server編
• part4 HTTP Server/logger編: これ