【ダメゼッタイ】aws-sdk-go s3.GetObject のBody Close忘れ

この記事はWano Group Advent Calendar2021 11日目の記事です。

何をやらかしたか

S3にキャッシュファイルを期限付きで保存しておき、取得時に期限が切れていなければ使用、切れていれば再度作成をするような処理がありました。

結論から言うと、S3からのファイルGet後にBodyのCloseをし忘れるケースがあったことで、プロセスが開けるファイルディスクリプタの上限に達してしまい、 Too many open files を吐きまくり、実質プロセスが何もできなくなってしまいました。

S3に限った話ではなく、結構簡単に起こせてしまう？問題なので戒めとして

原因のコード

以下のような処理を書いてしまい、問題は静かに発生しました。

Put は、Expires付きでS3にファイルを保存し、 GetStream はS3からファイルを取得後、Expiresを見て、bodyを返す返さないを判断します。

import (
	"errors"
	"io"
	"time"

	"github.com/aws/aws-sdk-go/aws"
	"github.com/aws/aws-sdk-go/service/s3"
)

var ErrExpired = errors.New("expiration file")

type S3Handler struct {
	s3     *s3.S3
	bucket string
}

func (hdl *S3Handler) Put(body io.ReadSeeker, key string, ex time.Duration) error {
	obj := &s3.PutObjectInput{
		Body:   body,
		Bucket: aws.String(hdl.bucket),
		Key:    aws.String(key),
	}
	if ex > 0 {
		obj.Expires = aws.Time(time.Now().Add(ex))
	}

	_, err := hdl.s3.PutObject(obj)
	if err != nil {
		return err
	}
	return nil
}

func (hdl *S3Handler) GetStream(key string) (io.ReadCloser, error) {
	obj, err := hdl.s3.GetObject(&s3.GetObjectInput{
		Bucket: aws.String(hdl.bucket),
		Key:    aws.String(key),
	})
	if err != nil {
		return nil, err
	}
	if obj.Expires != nil {
		expire, err := time.Parse(time.RFC1123, *obj.Expires)
		if err != nil {
			return nil, err
		}
		
		if time.Now().After(expire) {
			return nil, ErrExpired
		}
	}
	return obj.Body, nil
}

問題箇所

• 期限が切れている場合にnilを返すようにしていた
• nilを返す前にBodyのCloseをし忘れてしまった
• 呼び出し側でもCloseができず、CLOSE_WAITステータスのままのTCPコネクションが増殖
• 結果プロセスのFD上限到達

func (hdl *S3Handler) GetStream(key string) (io.ReadCloser, error) {
	obj, err := hdl.s3.GetObject(&s3.GetObjectInput{
		Bucket: aws.String(hdl.bucket),
		Key:    aws.String(key),
	})
	if err != nil {
		return nil, err
	}
	if obj.Expires != nil {
		expire, err := time.Parse(time.RFC1123, *obj.Expires)
		if err != nil {
			// Close忘れ
			return nil, err
		}

		if time.Now().After(expire) {
			// Close忘れ
			return nil, ErrExpired
		}
	}
	return obj.Body, nil
}

デプロイから時間が経つと増えていくような形になっていたので、デプロイ時には気付けず

$ lsof -i:xxxx | awk '{print $9$10}'
NAME
localhost:xxxx->localhost:dx-instrument (CLOSE_WAIT)
localhost:xxxx->localhost:dx-instrument (CLOSE_WAIT)
localhost:xxxx->localhost:dx-instrument (CLOSE_WAIT)
localhost:xxxx->localhost:dx-instrument (CLOSE_WAIT)
localhost:xxxx->localhost:dx-instrument (CLOSE_WAIT)
localhost:xxxx->localhost:dx-instrument (CLOSE_WAIT)
...

解決策

nilを返す前にClose

		if err != nil {
+			obj.Body.Close()
			return nil, err
		}

		if time.Now().After(expire) {
+			obj.Body.Close()
			return nil, ErrExpired
		}
}

合わせて、aws sdkの各種メソッドには xxxxWithContext が提供されていることが多いので、こちらに差し替えてtimeoutの設定をしておくと良さそう

	ctx := context.Background()
	ctx, cancel := context.WithTimeout(ctx, 10*time.Second)
	defer cancel()
	obj, err := self.s3.GetObjectWithContext(ctx, &s3.GetObjectInput{
		Bucket: aws.String(self.defaultBucket),
		Key:    aws.String(s3key),
	})

終わり

Bodyの生存期間が長いとCloseのし忘れをしてしまいがちだったりすると思うので、以後気をつけます