プログラマー探偵の事件簿：エラーを隠蔽するrecover

プログラム言語にはエラーを無かったことにしてくれる魔法の呪文が存在する。try / catch、rescureといったものである。GO言語の場合はrecoverである。今回は私自身がrecoverを使ってTWSNMPのエラーの証拠を隠蔽することに悩んだ話である。助手の猫は「ベッドやトイレを汚した時は隠さず正直に知らせろ！」と言っている。

事件の始まり

Raspberry PiでNetflowに対応する実験をしていた時である。

この記事の最後にバグ発見として書いた問題である。Netflow(ipfix形式）のデータを受けている途中でTWSNMPが異常終了した。

異常終了の原因

GO言語で異常終了する時にはpanicというメッセージを表示する。今回は、

panic: interface conversion: interface {} is nil, not uint１６

である。メッセージにはソースコード上場所も記録されている。

SrcPort: int(record["sourceTransportPort"].(uint16)),

送信元ポート番号がないNetflowのデータを処理する時に発生していることまでわかった。このデータはGO言語のNetflow処理パッケージから送られているものでブラックボックスである。

安易な解決策

送信元ポート番号がないNetflowのデータを処理する時に発生しているのだから、送信元ポート番号がないNetflowのデータは無視するようにすればよい！

if _,ok := record["sourceTransportPort"];ok {
   あれば処理する
} 

のようにする。
ここで、処理するデータは他にもあり、それらが存在しないことも考えなければと心配になる。安易に全部のデータの存在をチェックする処理を組み込んだ。とりあえず問題は起きないが、はたしてそれで良いのだろうか？
助手の猫は無言でこっちを見ている。「もう少し考えろ！」という意味か？

隠蔽する解決策

GO言語のpanicを回避する方法をGoogleに聞いてみた。

Defer, Panic, and Recover - The Go Blog

を見つけた。panicが起こっても無かったことにしてくれる方法である。これはよい呪文を見つけた。さっきの対策をやめて、さっそく試してみる。

defer func() {
    if r := recover(); r != nil {
        astiLogger.Errorf("logIPFIX err=%v", r)
	}
}()
問題の処理

問題の処理のところで発生したエラーはdeferの中のrecoverが隠蔽してくれる。うまくいったように思えるがログを見るとlogIPFIX err=の行が頻繁に出ている。まるで、猫が「ベッドを汚した」、「トイレを汚した」と文句を言っているような感じである。はたしてそれで良いのだろうか？

正直な解決策

悩んだすえ、やっぱり正直に直すことにした。
問題の原点に戻って、送信元ポート番号がないNetflowのデータがどういうものか調べることにした。問題が発生した時にデータをログに記録してみた。

defer func() {
    if r := recover(); r != nil {
		astiLogger.Errorf("logIPFIX err=%v", r)
        //データをログに出力
		for k, v := range record {
			astiLogger.Errorf("%v=%v", k, v)
		}
	}
}()

調べてみるとICMPのデータの場合にエラーになっている。ICMPにはポート番号はないので当然である。

Internet Control Message Protocol - Wikipedia

ICMPの場合はポート番号の代わりにコードとタイプを利用する処理を追加した。recoverの処理はそのままに組み込んだ状態である。エラーのログも記録されなくなった。

いつか、recoverの魔法で異常終了を免れることがあるかもしれない。

助手の猫はトイレもベッドも、かみさんのおかげでキレイなので、すやすや寝ている。