「Goのtime.Formatによるミリ秒切り捨て」と「MySQLのINSERTによるミリ秒四捨五入」で1秒の誤差が生まれた話

背景

2022年春頃にZOZOTOWNでログイン通知機能とログイン履歴機能をリリースしました。QAのフェーズにおいて、「ログイン通知で表示されるログイン時刻」と「ログイン履歴で表示されるログイン時刻」で最大1秒の誤差が生まれるケースがあることが判明しました。どちらの時刻もミリ秒までは表示しない仕様です。1秒とはいえ、これらの値が不一致なのは問題なので原因調査と対策をしました。

原因

ログイン通知で表示されるログイン時刻

ログイン通知で表示されるログイン時刻は、サーバがログインリクエストを受け付けた時の日時です。つまり、Goのアプリケーション上でのみ処理するデータです。アプリケーションでは、その日時を下のようにFormatし、ミリ秒を切り捨てます。

package main

import (
	"fmt"
	"time"
)

func main() {
	t, _ := time.Parse("2006/01/02 15:04:05", "2022/04/05 10:00:00.500")
	fmt.Println(t.Format("2006/01/02 15:04:05"))
}

2022/04/05 10:00:00

ログイン履歴で表示されるログイン時刻

ログイン履歴で表示されるログイン時刻は、一度MySQLのDBにINSERTされたデータをSELECTで取得したデータです。

カラムの型はDATETIMEで、ミリ秒は扱いません。もし、ミリ秒のデータをINSERTするとミリ秒が四捨五入されます。

mysql> INSERT INTO test VALUES (CAST('2022/04/05 10:00:00.500' as datetime));
Query OK, 1 row affected (0.00 sec)

mysql> SELECT * FROM test;
+---------------------+
| t                   |
+---------------------+
| 2022-04-05 10:00:01 |
+---------------------+
1 row in set (0.00 sec)

原因まとめ

上記の通り、「ログイン通知で表示されるログイン時刻」はGoのtimeパッケージのFormatでミリ秒以下が切り捨てられるのに対して、「ログイン履歴で表示されるログイン時刻」はMySQLのINSERTによりミリ秒以下が四捨五入されることが原因でした。

対策

ログイン履歴情報をDBにINSERTする前に、時刻情報のミリ秒を切り捨てるように改修しました。