プログラマ探偵の事件簿：精度の低い時計がログを消す

助手の猫の予感があたった事件である。

事件のはじまり

GitHUBに届いた１件のTWSNMP　FCに関する問い合わせから始まった。

お世話になっております。
複数のノードにて同時に障害を検知した場合、障害リストの件数と復旧リストの件数に差異が発生しております。

①障害リストには載っているが復旧が来ていないノード
②障害リストには載っていないが復旧のみが来たノード

上記ノード共にノード毎のポーリングログには障害がログが記載されておりますが、イベントログ、通知メールには記載されておりませんでした。
原因や対処についてお分かりになれば教えて頂けませんでしょうか。

GitHUn Issues

不思議なこともあるものだと思ったが、私は使っている人の勘違いだろうと思っていた。しかし助手の猫は「プログラマー探偵の出番では？」と言っていた。

証拠を集める

話だけでは調べようがないので証拠のなるログを送ってもらった。
なんと、使っている人の勘違いではなさそうである。
たしかに、

①障害リストには載っているが復旧が来ていないノード
②障害リストには載っていないが復旧のみが来たノード

が発生している。
通知のリストに載っていないものはログにも記録されてないメール通知をする仕組みの問題ではなさそうである。障害が発生したことをログに記録できないことが原因のようである。この時点で少し真相に近づいていた。
助手の猫もやる気がでてきたようだ。

私を混乱させた情報

問い合わせをした人から、

本日も障害21件、復旧25件と差異が発生しております。
毎日、00:00から監視サーバの再起動を実施しています。
監視をスタートし監視てからすべてではありませんが、継続しております。

と

監視を実施しているPCの時刻が3分進んでいました。
原因の一つとして考えられますでしょうか。

という情報があった。
またまた、私は使っている人の勘違いではと思い始めた。TWSNMP FCが動作する監視サーバーを再起動しているのかと思ったからだ。再起動している間のログが記録されていない。そのことを問い合わせをしてきた人に聞いて調べるのは待とうと思った。しかし、助手の猫は「プログラマー探偵の出番では？」と言い続けている。
週末の休みになった。

イベントログが消える原因

週が開けてから

監視サーバとは監視側のサーバの再起動になります。
TWSNMP FCを稼働させているサーバは再起動しておりません。

という回答があった。私の勘違いであった。助手の猫が「そらみろ、プログラマー探偵の出番だろ。ちゃんと、もう一度、ソースコードを調べろ！」と言った。

一つの仮説

助手の猫に言われるまま、ソースコードを見直した。最初は多数のログを保存した時に溢れて一部抜けるのかと思ったが、その可能性低い。
深くまでソースコードを見ていると「ログを保存するキーのところが怪しい」と助手の猫が言った。なるほど、一つの仮説が浮かんだ。
ログをデータベースに保存する時に、ログを識別するキーを時刻から作っている。もし、同時刻のキーが連続するとログは失われる。簡単に言うと
００：０３：００.00000000001のログは１件だだけしか保存できない仕組みなのである。プログラム上は10億分の1秒単位の時刻でキーを作成している、これが重なることなどありえないように思える。

時計の精度を現場検証

10億分の1秒単位の時刻が重なる可能性をテストプログラムを作って現場検証してみた。

package main
import (
	"log"
	"time"
)
func main() {
	i := 0
	st := time.Now()
	for st.UnixNano() == time.Now().UnixNano() {
		i++
	}
	log.Printf("%d %v", i, time.Since(st))
}

プログラムが動作するコンピュータの時計を読んで10億分の1秒単位の時刻が同じであった回数をカウントしている。カウントが１０だったら、１０回見る間、針は動かなかったということである。
コンピュータの時計の精度（解像度）が低いか、コンピュータのCPUが後続ならカウントが大きくなる。カウントが大きくなるコンピュータ上で今回の問題のログのためのキーを作成すると同じ値になる（重複する）可能性が高いということである。
安いPCで動かしているLinuxでは常に０である。
開発用にMacでは、大きくて７ぐらいである。０の時もある。
Windows環境では、なんと１００００以上になる。WIndowsの時計の精度は他より良くないのであろう。

解決

高速なCPUのWindows環境だとログのキーが同じになる確率が高く、これが原因でログが消えていたのである。キーが同じ値にならないように値をずらして保存するように対策して解決した。
プログラム上で10億分の1秒単位と書いても実際には違っていたのである。
助手の猫から一言
「プログラム上に見えているものは、真実ではない！」
まったく、その通りである。自分の勘違いも反省しなければ。