tl;dr
キーワードは「monotonic clock」です。
あらすじ
Goで以下のようなコードを書いていた*1*2。あるAPIを叩くクライアントで、APIコールに必要なアクセストークンを4時間キャッシュしている。c.getToken() で得られたトークンを使ってAPIコールを行えばよい。
type Client struct { mu sync.RWMutex expiresAt time.Time token string } // トークンのキャッシュがあればキャッシュから返し、なければ更新してから返す func (c *Client) getToken() string { if cachedToken, ok := c.getTokenFromCache(); ok { return cachedToken } return c.refreshToken() } // トークンをキャッシュから返す // 有効なトークンがキャッシュされていたら (トークン, true) を返す // 無効だったら (空文字列, false) を返す func (c *Client) getTokenFromCache() (string, bool) { c.mu.RLock() defer c.mu.RUnlock() // time.Now() < c.expiresAt if c.token != "" && time.Now().Before(c.expiresAt) { return c.token, true } return "", false } // トークンを更新してキャッシュしてから返す func (c *Client) refreshToken() string { c.mu.Lock() defer c.mu.Unlock() // 更新したトークンが token 変数に入っているとする // トークンをキャッシュに格納する c.token = token // 4時間で期限切れになる (実際にはもうちょっと短いものとして管理している) c.expiresAt = time.Now().Add(4 * time.Hour) return c.token }
うまく動いていそうということでしばらく開発を続けていた。が、ある日、APIクライアントがうまく動いていないらしいという報告を受けた。手元の開発マシンでバックエンドのアプリケーションを立ち上げたまま終業し、始業してから作業を再開しようとすると、アプリケーションがエラーを返すようになる。アプリケーションを起動しなおすと直るらしい。
もらったログを見ると、どうやら無効なトークンを使いつづけているようだ。期限切れかどうかを判定するロジックがおかしいのか? 排他制御がうまくいっていないのか? と見直してみたけど一見よさそう。他のメンバーに動作確認してもらった範囲では、うまくトークンを更新できているようだった。
キャッシュの有効期限とキャッシュヒットしたかどうかをログに出力するようにしたら、現在時刻が有効期限を過ぎているのにキャッシュヒットしたという出力が得られた。なんなのか。分からないまま調査しているうちに、ふと見たらトークンが更新されてしまっていた……。
さて、一体何が起こっていたのだろうか?
解決編
何が起こっているのか分からないまま祝日を過ごしていたが、ふとGoのtimeパッケージはmonotonic clockに対応していることを思い出した。
Goのmonotonic clockについてはtimeパッケージのドキュメントに書いてある。ひとことで言うと、OSの時刻設定によらず経過時間を正確に計測できる仕組みということになる?
もうちょっと調べると、monotonic clockで少しハマったという記事がヒットした。
これと同じことが起こっているのではないか? つまり、マシンがスリープしている間にmonotonic clockが止まり、トークンの有効期限に達していないとみなされているのではないか。
monotonic clockによるものだとすると、調査の過程で分かったことの辻褄が合う。
- 始業時にエラーが出る
- マシンをスリープさせたときにmonotonic clockが止まっていた
- アプリケーションを再起動すると直る
- トークンの再取得が走るから
- これ自体はmonotonic clock関係ない
- 一見すると動いていそうに見える
- マシンをスリープさせなければmonotonic clockが動いている
- いつの間にかトークンが更新されてしまっていた
- 調査しているうちにmonotonic clockの時間がトークンの有効期限を過ぎたから
裏付けのために、time.Timeのmonotonic clock部分も含めてログ出力するようにしてみた。
fmt.Printf("now=%v; expiresAt=%v; now - expiresAt=%v\n", now, c.expiresAt, now.Sub(n.expiresAt))
初回のキャッシュヒット時のログはこう:
now=2023-02-24 09:27:24.615819 +0900 JST m=+179.006316501; expiresAt=2023-02-24 13:20:26.996021 +0900 JST m=+14287.096705501; now - expiresAt=-3h55m8.090388875s
このあと30分ほど開発マシンをスリープさせて、再度キャッシュヒットさせたときのログはこう:
now=2023-02-24 10:01:11.549191 +0900 JST m=+488.264479709; expiresAt=2023-02-24 13:20:26.996021 +0900 JST m=+14287.096705501; now - expiresAt=-3h49m58.83222575s
13:20:26 - 10:01:11 は実時間でだいたい3時間19分*3。だけど t.Sub(...) で計算した残り時間は3時間49分となっている。
全部わかった……。
修正
Goのtime.Time同士の計算を実時間として扱うには、time.Timeに対して Round(0) を呼んだ返り値を使えばよい。これはtimeパッケージのドキュメントにそう書いてある。
The canonical way to strip a monotonic clock reading is to use t = t.Round(0).
(中略)
If Times t and u both contain monotonic clock readings, the operations t.After(u), t.Before(u), t.Equal(u), t.Compare(u), and t.Sub(u) are carried out using the monotonic clock readings alone, ignoring the wall clock readings. If either t or u contains no monotonic clock reading, these operations fall back to using the wall clock readings.
手元では開発マシンがスリープしてmonotonic clockが止まりうる。一方で、サーバーにデプロイしたときはmonotonic clockが止まる想定はせず、むしろ時刻がずれても経過時間が正しく取れる恩恵のほうが大きいはず。
ということで、トークンをキャッシュする部分について、手元でだけ time.Now() の呼び出しを time.Now().Round(0) に置き換えられるようにした。
まとめ
Goのmonotonic clockと手元の開発環境の噛み合わせによっては、インメモリキャッシュの実装がうまく動かない場合もあるよ、という事例でした。Goじゃなくても、monotonic clockを採用している環境ではハマるかもしれません。
なぜか有効期限付きのインメモリキャッシュがうまく動かないときに思い出してもらえれば幸いです。
