プログラマー探偵の事件簿：ダイイングメッセージを追え！

長い間、平穏に動作していたプログラムが忘れたころに突然止まることがある。今回は長期間稼働していたTWSNMPが異常終了した原因を調べた時の話である。一気に寒くなってきたので、助手の猫は体温を保つために沢山カリカリを食べてエネルギー補給している。仕事の手伝いのために膝の上に乗った猫は夏よりずっしりしてきた。

事件の始まり

ふと気がつくとTWSNMPのアイコンが私のMacの画面から消えている。テスト用に動かしているのでデバック用のログを出力していた。ログを確認すると、

panic: runtime error: index out of range [-1]

goroutine 796354 [running]:
math/rand.(*rngSource).Uint64(...)
/usr/local/Cellar/go/1.14.5/libexec/src/math/rand/rng.go:249
math/rand.(*rngSource).Int63(0xc000448000, 0x30)
/usr/local/Cellar/go/1.14.5/libexec/src/math/rand/rng.go:234 +0x93
math/rand.(*Rand).Int63(...)
/usr/local/Cellar/go/1.14.5/libexec/src/math/rand/rand.go:85
math/rand.(*Rand).Int31(...)
/usr/local/Cellar/go/1.14.5/libexec/src/math/rand/rand.go:99
math/rand.(*Rand).Int31n(0xc000446f00, 0x7fff, 0x0)
/usr/local/Cellar/go/1.14.5/libexec/src/math/rand/rand.go:134 +0x5f
math/rand.(*Rand).Intn(0xc000446f00, 0x7fff, 0xc0030426c8)
/usr/local/Cellar/go/1.14.5/libexec/src/math/rand/rand.go:172 +0x45
main.doPing(0xc000769133, 0xd, 0x2, 0x1, 0x40, 0xc0144d8e01)
/Users/ymimacmini/go/src/github.com/twsnmp/twsnmp/src/ping.go:71 +0x3a
main.doPollingPing(0xc000775080)
/Users/ymimacmini/go/src/github.com/twsnmp/twsnmp/src/polling.go:200 +0xb5
main.doPolling(0xc000775080, 0x163dd2f548587208)
/Users/ymimacmini/go/src/github.com/twsnmp/twsnmp/src/polling.go:132 +0x318
created by main.pollingBackend
/Users/ymimacmini/go/src/github.com/twsnmp/twsnmp/src/polling.go:79 +0x363`

のようにpanicで異常終了していた。そういえば、何ヶ月か前にも同じエラーを見た気がした。二度あることは三度ある。真面目に調べたほうが良さそうだ。

プログラムのダイイングメッセージ

GO言語のようなモダンなプログラム言語は異常終了した時にダイイングメッセージのように最後に実行したソースコードの場所をログに残してくれる。それが手がかりになる。このケースの場合、最後に実行したコードは

/usr/local/Cellar/go/1.14.5/libexec/src/math/rand/rng.go:249

ということだ。この場所のソースコードを眺めてみる。

// Uint64 returns a non-negative pseudo-random 64-bit integer as an uint64.
func (rng *rngSource) Uint64() uint64 {
	rng.tap--
	if rng.tap < 0 {
		rng.tap += rngLen
	}

	rng.feed--
	if rng.feed < 0 {
		rng.feed += rngLen
	}

	x := rng.vec[rng.feed] + rng.vec[rng.tap]　＜ーこの行
	rng.vec[rng.feed] = x
	return uint64(x)
}

たしかに配列を使っている。rng.feedかrng.tapが−１になれば

panic: runtime error: index out of range [-1]

のパニックが発生する。しかし、その前の行で

rng.tap--
if rng.tap < 0 {
	rng.tap += rngLen
}

という処理がある。−１になりそうならrngLenを足している。不思議だ。

世界がパニックに陥る危機

問題のプログラムは私が作ったコードではない。GO言語が提供するプログラムでみんなが使っているものだ。こんな場所で問題がおきると世界中の人がパニックに陥る。大変なことだ！

ここで助手の猫が登場して「あんたの作ったコードの問題に決まっている！」と言って膝の上で調査を助けてくれた。私が作った部分で問題に関係しているコードをダイイングメッセージから順番に調べる。

/Users/ymimacmini/go/src/github.com/twsnmp/twsnmp/src/ping.go:71 

の行だ。

	var p = &pingEnt{
		Target:   ip,
		Timeout:  timeout,
		Retry:    retry,
		Size:     size,
		sequence: 0,
		id:       randGen.Intn(math.MaxInt16), <-この行
		Tracker:  randGen.Int63n(math.MaxInt64),
		done:     make(chan bool),
	}

単に乱数でIDに使う数値を作っているだけだ。GO言語のパッケージの関数を使っている。はたして何が悪いのだろう。ソースコードを見るだけではわからない。

並列は災いを呼ぶ

自分の作ったコードを見ても何もうかばないので、もう一度GO言語のパッケージの Uint64()関数を見直すと、ちょっと閃いた。

rng.tap--

の行と

x := rng.vec[rng.feed] + rng.vec[rng.tap]

の行を同時に実行したらrng.tapが−１になるかもしれない。そして、問題の処理（PING)は並列で動くように作ってあるので２つの行が同時に実行される可能性はある。

そこでいつものようにGoogleさんに聞いてみた。”golang rand thread safe”のキーワード。いくつか見つけた。

math/rand: document that math.Rand is not safe for concurrent use 揃 Issue #3611 揃 golang/go

日本語だと

Go の疑似乱数生成器は Goroutine-Safe ではないらしい（追記あり）

とか。
まさに、これが原因だった。問題の処理が同時に実行されないように、Mutex

A Tour of Go

を使って対策した。

var randGen = rand.New(rand.NewSource(time.Now().UnixNano()))
var pingMutex sync.Mutex

func newPingEnt(ip string, timeout, retry, size int) *pingEnt {
	pingMutex.Lock()
	defer pingMutex.Unlock()
	return &pingEnt{
		Target:   ip,
		Timeout:  timeout,
		Retry:    retry,
		Size:     size,
		sequence: 0,
		id:       randGen.Intn(math.MaxInt16),
		Tracker:  randGen.Int63n(math.MaxInt64),
		done:     make(chan bool),
	}
}

隠蔽の誘惑

並列処理の問題というアイデアがうかぶ前に途方にくれていた時、

で書いた。recoverを使ってエラーを隠蔽しようかと考えた。解決策を見つけた今思うと危うく間違った方向にいくところだった。

助手の猫は、いつのまにか寒さに耐えかねて布団にもぐって寝ていた。