More than 5 years have passed since last update.

GoAdvent Calendar 2017

Goのpanicと向き合う。

Last updated at 2018-03-07Posted at 2017-12-24

Ho!Ho!Ho! Merry Panic!!

この記事はGo Advent Calendar 2017の25日目の記事です。
※本記事はOSX及びUNIXシステムなことを前提として向き合います。

package main

func main() {
    var p *interface{}
    *p = 0
}
/*
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x104f386]

goroutine 1 [running]:
main.main()
        /Users/nnao45/panic-test/panic01.go:5 +0x26
exit status 2
*/

上は何の変哲もないメモリアクセス違反ですね。
すごいクリスマステイストにしましたが、gopherとしては一番欲しくないクリスマスプレゼントそれはpanicかもしれません笑
しかし今日はこの標準パッケージさえ使わないたった６行のコードを中心¹にpanicと向き合いたいと思います。お付き合いください＞＜

「いっけね😓panic起きちゃったてへぺろ🌟」なんてスルーをしがちですが、
さてどうでしょう、しばらく眺めてみましょうか。
おやおや、hexがあちこちに点在しつつもgoroutineだかなんだかcodeだかなんだか吐き出しています。
如何ともし難い風貌しており、ミステリアスです。
しかし聖なる今日くらい、この子と向き合っていいのかなと思ってきたので筆をとりました。²

#そもそもGoのpanicとは何なのか。
そのミステリアスな風貌から「何かの黒魔術の類だろ？」と思いがちです。

ここの軸がブレると向き合った事にはならなそうですよね。
ここは参考書から引用させてください。

Goの型システムはコンパイル時に多くの誤りを検出しますが、境界線外への配列アクセス、nilポインタによる参照などの他の誤りは**実行時の検査を必要とします。**Goランタイムがそのような誤りを検出した場合、**パニック(panic)**となります。
典型的なパニックでは、通常の実行を停止し、そのゴルーチン内での全ての遅延関数の呼び出しが行われ、プログラミングログメッセージを表示してクラッシュします。
---プログラミング言語Go アラン＝ドノバン、ブライアン＝カーニハン著

エラーハンドリングをユーザに委ねるGoですが、
そのエラーハンドリングで掬えないバグからPCを守るという最後の砦です。
私としてはGoのpanicは他の言語の「例外」みたいなもの、と言ってもいいと思っています（多分）。
まぁあまり自由には取り扱えないわけですけどね。
注意点としては、「Goのランタイムが検知」するのであって「Goのランタイムで起こった異常」に限らない（＝当然シグナル起因も有り得る）わけです。

といった感じで、別に上記に書いてあることは複雑な事を言ってるわけではないですので、
しっかり頭に入れて進んでゆきたいと思います。

Goのぬるぽは何を言ってるのか追ってみる。³

ガッ！！

おそらくここの項目は、
ただ単純にその他言語のpanicやシグナルの話とさほど差はないので復習です。
まずはどう言った意味合いを示しているのかが気になりますよね。
では、この記事の最初のpanicが起きた時のコンソールメッセージをまずは見ていきましょう。

エラー1行目：エラーメッセージ

panic: runtime error: invalid memory address or nil pointer dereference

Javaなどの例外処理としても有名ないわゆる「ぬるぽ」、「null pointer exception」、「10億ドルの誤り」です。

ヌルポインタ（英語: null pointer）とは、何のオブジェクトも指していないことを表す特別なポインタである。
ヌルポインタの値や型がいかなるものかという詳細は言語によって異なる。実際的にはいかなるオブジェクトも参照しないという言語もあり、参照先を求めようとするとJava（NullPointerException）のように例外が発生するものもある。
----ヌルポインタ wikipedia https://ja.wikipedia.org/wiki/%E3%83%8C%E3%83%AB%E3%83%9D%E3%82%A4%E3%83%B3%E3%82%BF

というわけです。

##エラー２行目：SIGSEGV

[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x104f37f]

SIGSEGVはUNIXシグナルのひとつで、いわゆるセグメンテーションフォルトでしょう。

###せぐふぉ###

UNIXライクのオペレーティングシステム上では、不正なメモリにアクセスをするプロセスはSIGSEGVシグナルを受け取る。Microsoft Windows上では、不正なメモリにアクセスするプロセスはSTATUS_ACCESS_VIOLATION例外を受け取る。
----セグメンテーション違反 wikipedia https://ja.wikipedia.org/wiki/%E3%82%BB%E3%82%B0%E3%83%A1%E3%83%B3%E3%83%86%E3%83%BC%E3%82%B7%E3%83%A7%E3%83%B3%E9%81%95%E5%8F%8D

今回のコードでは、pのアドレスを直接指定して値を代入しようとしています。この行為自体は何も悪くないのですが、

一般に、0 番地からある番地までは OS が使用するため、ユーザーが勝手にアクセスすることはできません。近代的な OS の場合、メモリはシステムエリアとユーザーエリアに区別されていて、ユーザーのプログラムがシステムエリアにアクセスすることを禁止しています。もし、このメモリにアクセスすると OS で例外 (エラー) が発生します。
----お気楽 Go 言語プログラミング入門 http://www.geocities.jp/m_hiroi/golang/abcgo06.html

Goでも（というかほぼ殆どの処理系で）ぬるぽのように、何のオブジェクトも指していないメモリのアドレスは「0」です。

###シグナル###

シグナル（英: signal）とは、UNIXやUnix系などのPOSIX準拠OSにおける限定的なプロセス間通信の一形態。プロセス間あるいはスレッド間で非同期イベントの発生を伝える機構である。シグナルが送信された際、OSは宛先プロセスの正常な処理の流れに割り込む。どんな不可分でない処理の間でも割り込むことができる。受信プロセスが以前にシグナルハンドラを登録しておけば、シグナル受信時にそのルーチンが実行される。
----シグナル (ソフトウェア) wikipedia https://ja.wikipedia.org/wiki/%E3%82%B7%E3%82%B0%E3%83%8A%E3%83%AB_(%E3%82%BD%E3%83%95%E3%83%88%E3%82%A6%E3%82%A7%E3%82%A2)

Goでも事前にここに登録されており、しっかりとシグナルを受け取っています。

と言う事です。さて、、、、その後のcode=0x1 addr=0x0 pc=0x104f386も非常にアヤシイですね。これを追っていきましょう。

code=0x1

code=0x1はsiginfo.si_codeの値を表しています。
si、signal info、つまりこれはシグナル情報の中のコードです。
プロセスはシグナルをキャッチしたとき、そのシグナル情報をシステムに要求します。
その情報は、なぜシステムがそのシグナルを生成したかを示しています。

多くのUNIXシステムでは例外を識別するためにシグナル番号(si_signo)とシグナル・コード(si_code)が使用されます。

細々した情報はsiginfo.h自身に譲るとして、まぁ結論はここです。

siginfo.h

/*
 * SIGSEGV si_codes
 */
#define SEGV_MAPERR	1	/* address not mapped to object */

0x1、つまりこれはsiginfo.hで定義されたSEGV_MAPERRを表しています。
意味はコメントアウトにある通りでしょう。

ちなみに余談で、他にも色々panicはありますが、例えばメモリリークさせてしまった場合も、シグナル起因のpanicな訳ではないので特にSIG〜と言う表示は出ません。

package main

func main() {
  for {
  　　b := make([]byte, 100000000000)
   _ = b
  }
}
/*
fatal error: runtime: out of memory

runtime stack:
runtime.throw(0x4697aa, 0x16)
	/usr/local/go/src/runtime/panic.go:566 +0x95
runtime.sysMap(0xc420100000, 0x1748770000, 0xc400008000, 0x4b4bd8)
	/usr/local/go/src/runtime/mem_linux.go:219 +0x1d0
runtime.(*mheap).sysAlloc(0x49c660, 0x1748770000, 0xc420000ea0)
	/usr/local/go/src/runtime/malloc.go:407 +0x37a
runtime.(*mheap).grow(0x49c660, 0xba43b8, 0x0)
	/usr/local/go/src/runtime/mheap.go:726 +0x62
runtime.(*mheap).allocSpanLocked(0x49c660, 0xba43b8, 0x4994d0)
	/usr/local/go/src/runtime/mheap.go:630 +0x4f2
runtime.(*mheap).alloc_m(0x49c660, 0xba43b8, 0x100000000, 0x0)
	/usr/local/go/src/runtime/mheap.go:515 +0xe0
runtime.(*mheap).alloc.func1()
	/usr/local/go/src/runtime/mheap.go:579 +0x4b
runtime.systemstack(0x7fffcdb679f0)
	/usr/local/go/src/runtime/asm_amd64.s:314 +0xab
runtime.(*mheap).alloc(0x49c660, 0xba43b8, 0x10100000000, 0x7fffcdb67a58)
	/usr/local/go/src/runtime/mheap.go:580 +0x73
runtime.largeAlloc(0x174876e800, 0xc42000c001, 0x410d01)
	/usr/local/go/src/runtime/malloc.go:774 +0x93
runtime.mallocgc.func1()
	/usr/local/go/src/runtime/malloc.go:669 +0x3e
runtime.systemstack(0x499700)
	/usr/local/go/src/runtime/asm_amd64.s:298 +0x79
runtime.mstart()
	/usr/local/go/src/runtime/proc.go:1079

goroutine 1 [running]:
runtime.systemstack_switch()
	/usr/local/go/src/runtime/asm_amd64.s:252 fp=0xc420037e10 sp=0xc420037e08
runtime.mallocgc(0x174876e800, 0x457920, 0x403f01, 0xc42000e118)
	/usr/local/go/src/runtime/malloc.go:670 +0x903 fp=0xc420037eb0 sp=0xc420037e10
runtime.makeslice(0x457920, 0x174876e800, 0x174876e800, 0xc42000e0c0, 0x0, 0xc4200001a0)
	/usr/local/go/src/runtime/slice.go:57 +0x7b fp=0xc420037f08 sp=0xc420037eb0
main.main()
	/home/runner/main.go:4 +0x41 fp=0xc420037f48 sp=0xc420037f08
runtime.main()
	/usr/local/go/src/runtime/proc.go:183 +0x1f4 fp=0xc420037fa0 sp=0xc420037f48
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc420037fa8 sp=0xc420037fa0
*/

なかなか圧巻の。。。いや悪寒の光景ですね。

###addr=0x0
addr=0x0はsiginfo.si_addrを表しています。
単純にアクセスしたエラーの起因となったメモリ番地は0と言う事でしょう。

###pc=0x104f386
これはプログラムカウンタと言って、デバッグ目的で出てるカウンターです。
プロセッサの話です。

プログラムカウンタ
アドレスレジスタの一種で、実行する命令のアドレスを指し示すレジスタ。命令の読み込みを行なう際にはその内容がアドレスバス上に出力され、また命令を読み込む度に読み取った命令の分だけ値が増加するようになっている。
---レジスタ (コンピュータ) wikipedia https://ja.wikipedia.org/wiki/%E3%83%AC%E3%82%B8%E3%82%B9%E3%82%BF_(%E3%82%B3%E3%83%B3%E3%83%94%E3%83%A5%E3%83%BC%E3%82%BF)

要は次に実行すべきだった命令を指し示すメモリーの番地を指し示しています。
しかし純粋な疑問として、panicを起こされた場合、「panicによる出力越し」でしかそのプログラムカウンタは見えないのでは？と思われます。panic自体がプログラム全体を止めてしまうため、そのあとそのgoroutineからポインタを貰ってスタックトレースしてプログラムカウンタを引っ張ってくる・・・という事ができなさそうです。何故なら前にプログラムが死んでしまうからです。

しかしそれでもちゃんと向き合い方があるのでご紹介します。

##プログラムカウンタとの向き合い方

プログラムカウンタの話をうだうだ続けても仕方ないので、追う方法だけ。⁴

package main

import (
    "fmt"
    "io"
    "os"
    "runtime"
)

func main() {
    os.Exit(run(os.Stderr))
}

func run(log io.Writer) (exit int) {
    defer func() {
        if r := recover(); r != nil {
            fmt.Fprintf(log, "Panic: %v\n", r)
            for depth := 0; ; depth++ {
                pc, src, line, ok := runtime.Caller(depth)
                if !ok {
                    break
                }
                fmt.Fprintf(log, " -> %d: %x: %s:%d\n", depth, pc, src, line)
            }
            exit = 1
        }
    }()

    doPanic()
    exit = 0
    return
}

func doPanic() {
  var p *interface{}
  *p = 0
}

/*
Panic: runtime error: invalid memory address or nil pointer dereference
 -> 0: d583f: /tmp/sandbox143689162/main.go:19
 -> 1: 861ff: /usr/local/go/src/runtime/asm_amd64p32.s:472
 -> 2: 5057f: /usr/local/go/src/runtime/panic.go:491
 -> 3: 4ee7f: /usr/local/go/src/runtime/panic.go:63
 -> 4: 4e2ff: /usr/local/go/src/runtime/os_nacl.go:60
 -> 5: d54d2: /tmp/sandbox143689162/main.go:36
 -> 6: d54d1: /tmp/sandbox143689162/main.go:29
 -> 7: d53ff: /tmp/sandbox143689162/main.go:11
 -> 8: 534bf: /usr/local/go/src/runtime/proc.go:195
 -> 9: 88820: /usr/local/go/src/runtime/asm_amd64p32.s:1040
*/

Goでプログラムカウンタを追う王道はruntime.Caller()を使う方法です。
ですが、そもそも先ほど引用させて頂いた通り、一度panicとなってしまうとプログラム全体は緊急終了してしまい、肝心のruntime.Caller()を実行する事なくプログラム自体が終了してしまいます。

そこでrecoverを行い、panicから救助してあげて、表示する事により例え途中でpanicを起こしていてもそのpanicを起こしたプログラムカウンタが終えるようにします。
めでたしめでたし。⁵

##話を戻して、、、

さて２行目はこのくらいです。終始シグナルの話をしていましたが、今回はメモリ違反によるセグフォなので、Goとしても受け取ったシグナルを表示してくれていたのでしょう。そこそこ向き合えた実感がわいてきましたね笑
次は、いわゆるスタックトレースの話にうつります。

##エラー４行目以降：スタックトレース
スタックトレースと言うのは、プログラムの実行過程を記録したスタックフレームを記録しておくことです。⁶Goのpanicでもコンソール上でこのスタックトレースを表示する、つまり断末魔を表示してやると言う事はpanicのもつ大きな仕事です。
さて見ていきます。

goroutine 1 [running]:
main.main()
        /Users/nnao45/panic-test/panic01.go:5 +0x26
exit status 2

###goroutine 1 [running]:

まず初めに実行されているgoroutineの"通し番号"が出ます。
１個目…そう、main.mainの事です。
そのプログラムを動かしているコンピュータ上ではどれくらいgoroutineがスタックされるかを見たいときは、delveなどのデバッガを使いましょう。

$ dlv debug panic01.go
Type 'help' for list of commands.
(dlv) b main.main:2
Breakpoint 1 set at 0x1053c08 for main.main() ./panic01.go:5
(dlv) c
> main.main() ./panic01.go:5 (hits goroutine(1):1 total:1) (PC: 0x1053c08)
     1: package main
     2:
     3: func main() {
     4:         var p *interface{}
=>   5:         *p = 0
     6: }
(dlv) goroutines
[3 goroutines]
* Goroutine 1 - User: ./panic01.go:5 main.main (0x1053c08) (thread 1833131)
  Goroutine 2 - User: /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:288 runtime.gopark (0x102733d)
  Goroutine 3 - User: /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:288 runtime.gopark (0x102733d)

オロロ？[3 goroutines]って書いてあるじゃないか？
それはこのアヤシゲなruntime.goparkを掘り下げれば分かります。
ソースコードが一番のソース。。。

proc.go

  // Puts the current goroutine into a waiting state and calls unlockf.
  // If unlockf returns false, the goroutine is resumed.
  // unlockf must not access this G's stack, as it may be moved between
  // the call to gopark and the call to unlockf.
  func gopark(unlockf func(*g, unsafe.Pointer) bool, lock unsafe.Pointer, reason string, traceEv byte, traceskip int) {
  	mp := acquirem()
  	gp := mp.curg
  	status := readgstatus(gp)
  	if status != _Grunning && status != _Gscanrunning {
  		throw("gopark: bad g status")
  	}
  	mp.waitlock = lock
  	mp.waitunlockf = *(*unsafe.Pointer)(unsafe.Pointer(&unlockf))
  	gp.waitreason = reason
  	mp.waittraceev = traceEv
  	mp.waittraceskip = traceskip
  	releasem(mp)
  	// can't do anything that might move the G between Ms here.
  	mcall(park_m)
  }

src/runtime/proc.go
コメントアウトだけ読んでいただければ良いのですが、Goはgoroutineを事前に一定の数だけスタックさせておき、任意のgoroutineがgoparkを読んだ時に、代入されたlockfがtrueならパーキングしておく事で必要最低限のgoroutineを動かしておくわけです。

なのでもちろん、作りまくればpanicのスタックトレースのgoroutineの数も変わります。
ちなみにこのgoroutine 1の1は総数ではなく、該当のpanicを起こしたgoroutineの通し番号です。

package main

func main() {
    ch := make(chan struct{}, 0)
    go func(){
      <-ch
    }()
    go func(){
      <-ch
    }()
    go func(){
      var p *interface{}
      *p = nil
    }()
    <-ch
}
/*
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x104f4ef]

goroutine 6 [running]:
main.main.func3()
        /Users/nnao45/panic-test/panic01.go:13 +0x1f
created by main.main
        /Users/nnao45/panic-test/panic01.go:11 +0x96
exit status 2
*/

はて、そういえばrunningってのはそりゃgoroutineが動いてるってのはわかるんですが、
他のrunning以外の状態ってあまり見かけませんね。実際、goroutineがidleとかそういうのもあるのですが、リソース不足とかそういうのを意図的に起こす必要があって中々再現するのが難しいのですが、ふふ、ご用意できるものがありました。続きはオマケ2で。

/Users/nnao45/panic-test/panic01.go:5 +0x26

さてスタックトレースとして見るべき場所は後はここだけ。
ムムム！！+0x26これはなんだ・・・。

※これは次の項目に後述する方が分かりやすいので、そうします。defer()笑

んま、これで一通り舐めれた事になりました。お疲れ様でした。
はて・・・・何か忘れているような・・・・はっ！！！！

そもそも結局今回のpanicによるコンソール出力は何の機構がやっているの?

今まではざっくりとそもそも用語やそもそものUNIXシステムのアーキテクト、Goの仕組みを確認をしましたが、やはり「あの黒魔術チックな文章は結局"どういうコードから"コンソールに出力されているか」気になりますね。見ていきましょう。

どう見るか、そりゃソースコードしかない訳です。

まずは1行目から。

##panic: runtime error: invalid memory address or nil pointer dereference

Goでpanicが起きる際に、必ずそのpanicがどういった内容なのか表すメッセージが発されます。
この「どういった内容なのか」と言うのは正確には「Goのランタイムが検知した異常を、Go自身が切り分けた結果」です。

panic: runtime error: invalid memory address or nil pointer dereference

このメッセージ自体が何の機構から発せられているか追ってみます。

var memoryError = error(errorString("invalid memory address or nil pointer dereference"))

func panicmem() {
	panicCheckMalloc(memoryError)
	panic(memoryError)
}

どうやらこのmemoryError変数がpanicmem()で呼ばれる事によって表示されるようです。
（ぬるぽによるエラーなど標準パッケージもユーザが勝手にpanic(hoge)といった形で実装しても同様にpanic()関数を通して起こるように見えますね）。

更にこのmemoryErrorに関してはpanicmem()のクロージャ内に包まれてるだけ（多分）ように見えるので、とりあえずはこのpanicmem()を呼ばれ元を追えば良さそうです。

前述もしましたが、ぬるぽ自体はSIGSEGVを引き起こしているので、どうやらシグナル周りの関数を追えば良さそうです。と言う事でこれでしょう。

golang/go/src/runtime/signal_linux_amd64.go

// sigpanic turns a synchronous signal into a run-time panic.
// If the signal handler sees a synchronous panic, it arranges the
// stack to look like the function where the signal occurred called
// sigpanic, sets the signal's PC value to sigpanic, and returns from
// the signal handler. The effect is that the program will act as
// though the function that got the signal simply called sigpanic
// instead.
func sigpanic() {
	g := getg()
	if !canpanic(g) {
		throw("unexpected signal during runtime execution")
	}

	switch g.sig {
	case _SIGBUS:
		if g.sigcode0 == _BUS_ADRERR && g.sigcode1 < 0x1000 {
			panicmem()
		}
		// Support runtime/debug.SetPanicOnFault.
		if g.paniconfault {
			panicmem()
		}
		print("unexpected fault address ", hex(g.sigcode1), "\n")
		throw("fault")
	case _SIGSEGV:
		if (g.sigcode0 == 0 || g.sigcode0 == _SEGV_MAPERR || g.sigcode0 == _SEGV_ACCERR) && g.sigcode1 < 0x1000 {
			panicmem()
		}
		// Support runtime/debug.SetPanicOnFault.
		if g.paniconfault {
			panicmem()
		}
		print("unexpected fault address ", hex(g.sigcode1), "\n")
		throw("fault")
	case _SIGFPE:
		switch g.sigcode0 {
		case _FPE_INTDIV:
			panicdivide()
		case _FPE_INTOVF:
			panicoverflow()
		}
		panicfloat()
	}

	if g.sig >= uint32(len(sigtable)) {
		// can't happen: we looked up g.sig in sigtable to decide to call sigpanic
		throw("unexpected signal value")
	}
	panic(errorString(sigtable[g.sig].name))
}

少し長くなっていますが、まだここを深掘りします。本題の肝の部分なので頑張ってみます。
このコメントアウトを見れば分かりますが、この関数はGoのruntime panicと同期して引き起こされます。
まずg:=getg()していますが、このgはGoが動く上で非常に重要です、そう皆さんも良くご存知、

A "G" is simply a goroutine. It's represented by type g. When a goroutine exits, its g object is returned to a pool of free gs and can later be reused for some other goroutine.
----HACKING.md https://github.com/golang/go/src/runtime/HACKING.md

gはシンプルにgoroutineの事をさしています。

// getg returns the pointer to the current g.
// The compiler rewrites calls to this function into instructions
// that fetch the g directly (from TLS or from the dedicated register).
func getg() *g

そしてgetg()する事によって現在のgoroutineのポインタを呼び出します。
そのgoroutineによって呼び出されたsigpanic()によって、goroutineモジュールのsigの中身を解析され、もしそれがぬるぽに該当するシグナルだった場合、晴れてpanicmem()が発動してコンソールに表示されるという運びになっています。

panic: runtime error: invalid memory address or nil pointer dereference

##[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x104f37f]
さて続いて2行目ですが、panicを引き起こしたプログラムの中身に迫ります。
panicを起こす時の本体の関数はdopanic(unused int)関数です。
こいつを掘っていけば答えが出てくるはずです。

//go:nosplit
func dopanic(unused int) {
	pc := getcallerpc()
	sp := getcallersp(unsafe.Pointer(&unused))
	gp := getg()
	systemstack(func() {
		dopanic_m(gp, pc, sp) // should never return
	})
	*(*int)(nil) = 0
}

func dopanic_m(gp *g, pc, sp uintptr) {
	if gp.sig != 0 {
		signame := signame(gp.sig)
		if signame != "" {
			print("[signal ", signame)
		} else {
			print("[signal ", hex(gp.sig))
		}
		print(" code=", hex(gp.sigcode0), " addr=", hex(gp.sigcode1), " pc=", hex(gp.sigpc), "]\n")
	}

	level, all, docrash := gotraceback()
	_g_ := getg()
	if level > 0 {
		if gp != gp.m.curg {
			all = true
		}
		if gp != gp.m.g0 {
			print("\n")
			goroutineheader(gp)
			traceback(pc, sp, 0, gp)
		} else if level >= 2 || _g_.m.throwing > 0 {
			print("\nruntime stack:\n")
			traceback(pc, sp, 0, gp)
		}
		if !didothers && all {
			didothers = true
			tracebackothers(gp)
		}
	}
	unlock(&paniclk)

	if atomic.Xadd(&panicking, -1) != 0 {
		// Some other m is panicking too.
		// Let it print what it needs to print.
		// Wait forever without chewing up cpu.
		// It will exit when it's done.
		lock(&deadlock)
		lock(&deadlock)
	}

	if docrash {
		crash()
	}

	exit(2)
}

dopanic_m(gp *g, pc, sp uintptr)コヤツが本丸のようですね。
さて見ていきましょう。
まず引数です。
gp、これは上の方にも書きましたが、goroutineのポインタです。
pcはプログラムカウンタですね、ふふふ、パッと分かりましたね。嬉しくないですか？笑
spはプログラムカウンタのスタックポインタを表しています。

では実行部分です。
この関数を呼んだpanicがGoのランタイムパニックではなくシグナル起因だった場合（if gp.sig != 0）、シグナルの情報を書きます。
ここが、

[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x104f37f]

の部分です。

##goroutine 1 [running]:
次にgoroutineheader(gp *g)関数です。

func goroutineheader(gp *g) {
	gpstatus := readgstatus(gp)

	isScan := gpstatus&_Gscan != 0
	gpstatus &^= _Gscan // drop the scan bit

	// Basic string status
	var status string
	if 0 <= gpstatus && gpstatus < uint32(len(gStatusStrings)) {
		status = gStatusStrings[gpstatus]
	} else {
		status = "???"
	}

	// Override.
	if gpstatus == _Gwaiting && gp.waitreason != "" {
		status = gp.waitreason
	}

	// approx time the G is blocked, in minutes
	var waitfor int64
	if (gpstatus == _Gwaiting || gpstatus == _Gsyscall) && gp.waitsince != 0 {
		waitfor = (nanotime() - gp.waitsince) / 60e9
	}
	print("goroutine ", gp.goid, " [", status)
	if isScan {
		print(" (scan)")
	}
	if waitfor >= 1 {
		print(", ", waitfor, " minutes")
	}
	if gp.lockedm != 0 {
		print(", locked to thread")
	}
	print("]:\n")
}

https://github.com/golang/go/blob/master/src/runtime/traceback.go#L799
gp.goidと言うのが、panicを呼んだgoroutineのIDの事でしょうね。
ここが、

goroutine 1 [running]:

です。

##スタックトレース部分
最後にgotraceback()関数を呼んでいます。
この関数によりスタックトレースを出力するのですが、呼ばれるレベルにより出力されるスタックトレースが変わります。これはGo側がデフォルトでよしなに決めています。
ちなみに外部から環境変数の方のGOTRACEBACKの値を変えるによりスタックフレームの出力を変えれます(詳しくはオマケ1で)。

// Generic traceback.  Handles runtime stack prints (pcbuf == nil),
// the runtime.Callers function (pcbuf != nil), as well as the garbage
// collector (callback != nil).  A little clunky to merge these, but avoids
// duplicating the code and all its subtlety.
func gentraceback(pc0 uintptr, sp0 uintptr, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max int, callback func(*stkframe, unsafe.Pointer) bool, v unsafe.Pointer, flags uint) int {
//snip
if printing {
			if (flags&_TraceRuntimeFrames) != 0 || showframe(f, gp) {
				// Print during crash.
				//	main(0x1, 0x2, 0x3)
				//		/home/rsc/go/src/runtime/x.go:23 +0xf
				//
				tracepc := frame.pc // back up to CALL instruction for funcline.
				if (n > 0 || flags&_TraceTrap == 0) && frame.pc > f.entry && !waspanic {
					tracepc--
				}
				print(gofuncname(f), "(")
				argp := (*[100]uintptr)(unsafe.Pointer(frame.argp))
				for i := uintptr(0); i < frame.arglen/ptrSize; i++ {
					if i >= 10 {
						print(", ...")
						break
					}
					if i != 0 {
						print(", ")
					}
					print(hex(argp[i]))
				}
				print(")\n")
				file, line := funcline(f, tracepc)
				print("\t", file, ":", line)
				if frame.pc > f.entry {
					print(" +", hex(frame.pc-f.entry))
				}
				if g.m.throwing > 0 && gp == g.m.curg || gotraceback >= 2 {
					print(" fp=", hex(frame.fp), " sp=", hex(frame.sp))
				}
				print("\n")
				nprint++
			}
		}
//snip

ツー事で、

/Users/nnao45/panic-test/panic01.go:5 +0x26
さてスタックトレースとして見るべき場所は後はここだけ。
ムムム！！+0x26これはなんだ・・・。

この答えは上のソース通り、panicを呼んだgpのプログラムカウンタからその関数がどれくらいカウンタがスタックされたかの差分、と言うのが、、、、、答えや！！！！！！！！（長かったっっw）
と言う事でここが、

main.main()
        /Users/nnao45/panic-test/panic01.go:5 +0x26

です。
と、、、いうわけで今回は一通りGoのPanicに向き合えたと思います。
Panicが起きていると言う事は重大な障害が起きているのは間違い無いので、
そのpanicが何をトリガーにして起きているかしっかり把握しておくことで障害の切り分けや安定運用へ役に立つかと思います。

オマケ1：`GOTRACEBACK`の値を変える。

GOTRACEBACKの値を変えると、panicで表示されるスタックトレースの粒度を変えることができます。

①GOTRACEBACK=0

$ GOTRACEBACK=0 go run panic01.go
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x104f386]
exit status 2

②GOTRACEBACK=1

$ GOTRACEBACK=1 go run panic01.go
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x104f386]

goroutine 1 [running]:
main.main()
        /Users/nnao45/panic-test/panic01.go:5 +0x26
exit status 2

③GOTRACEBACK=2

$ GOTRACEBACK=2 go run panic01.go
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x104f386]

goroutine 1 [running]:
panic(0x105cea0, 0x10a7ac0)
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:540 +0x45e fp=0xc42003fef0 sp=0xc42003fe48 pc=0x102247e
runtime.panicmem()
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:63 +0x5e fp=0xc42003ff10 sp=0xc42003fef0 pc=0x10211ae
runtime.sigpanic()
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/signal_unix.go:367 +0x17c fp=0xc42003ff60 sp=0xc42003ff10 pc=0x1034aec
main.main()
        /Users/nnao45/panic-test/panic01.go:5 +0x26 fp=0xc42003ff80 sp=0xc42003ff60 pc=0x104f386
runtime.main()
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:195 +0x226 fp=0xc42003ffe0 sp=0xc42003ff80 pc=0x1024086
runtime.goexit()
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/asm_amd64.s:2337 +0x1 fp=0xc42003ffe8 sp=0xc42003ffe0 pc=0x1049c51

goroutine 2 [force gc (idle)]:
runtime.gopark(0x106f930, 0x10a82e0, 0x106c078, 0xf, 0x14, 0x1)
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:287 +0x12c fp=0xc42002a768 sp=0xc42002a738 pc=0x102452c
runtime.goparkunlock(0x10a82e0, 0x106c078, 0xf, 0xc420000114, 0x1)
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:293 +0x5e fp=0xc42002a7a8 sp=0xc42002a768 pc=0x102461e
runtime.forcegchelper()
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:245 +0xcc fp=0xc42002a7e0 sp=0xc42002a7a8 pc=0x102434c
runtime.goexit()
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/asm_amd64.s:2337 +0x1 fp=0xc42002a7e8 sp=0xc42002a7e0 pc=0x1049c51
created by runtime.init.4
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:234 +0x35

goroutine 3 [GC sweep wait]:
runtime.gopark(0x106f930, 0x10a8380, 0x106be1e, 0xd, 0x1018c14, 0x1)
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:287 +0x12c fp=0xc42002af60 sp=0xc42002af30 pc=0x102452c
runtime.goparkunlock(0x10a8380, 0x106be1e, 0xd, 0x14, 0x1)
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:293 +0x5e fp=0xc42002afa0 sp=0xc42002af60 pc=0x102461e
runtime.bgsweep(0xc420052000)
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/mgcsweep.go:52 +0xa3 fp=0xc42002afd8 sp=0xc42002afa0 pc=0x1018d13
runtime.goexit()
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/asm_amd64.s:2337 +0x1 fp=0xc42002afe0 sp=0xc42002afd8 pc=0x1049c51
created by runtime.gcenable
        /usr/local/Cellar/go/1.9.2/libexec/src/runtime/mgc.go:216 +0x58
exit status 2

オマケ2：`goroutine x [running]:`以外も見てみたい。

実はオマケ１のようにmain.main関数以外goroutineを作っていない状態でGOTRACEBACK=2をすれば、スタックトレースの中でgoparkで停滞させられているgoroutineの状態を見ると、goroutine 2 [force gc (idle)]:だのgoroutine 3 [GC sweep wait]:だの書いてあリ、確認することができます。
さらに他には、channel周りで起こすことが可能です。

package main

import (
  "fmt"
  "time"
)

func main() {
  queue := make(chan string, 3)

  time.Sleep(1 * time.Second)
  queue <- "hop"
  fmt.Println("hop")

  time.Sleep(1 * time.Second)
  queue <- "step"
  fmt.Println("step")

  time.Sleep(1 * time.Second)
  queue <- "jump"
  fmt.Println("jump")

  time.Sleep(1 * time.Second)
  queue <- "die!"
  fmt.Println("die!")
}
/*
hop
step
jump
fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
	/tmp/sandbox901549475/main.go:24 +0x200

Program exited.
*/

確かに、goroutine 1 [chan send]:・・・・！
これもいつもと違う表記のpanicです！やったねたえちゃん！

バッファ付きのchannelで解放する前に容量以上のチャンネルを詰めようとすると死ぬやつですね。

注釈

Goのpanicで表示されるメッセージですが、実はこれといったフォーマットがある訳ではなく、そのGoのランタイムが検知できた異常によって、変わっていきます。なので今回はぬるぽ周りの話を中心としますが、この内容がもちろんGoのpanicの全てではなく、あくまで雰囲気と、どういったレイヤーの話かを掴み取って頂ければ幸いです。 ↩
実は最近↓の注釈のようなpanicに関する記事がGoコミュニティにポツポツと連続で投稿されてされており、情報も集まっているいい機会だと思ったのが大きなモチベーションとなりました。故に引用が非常に多い記事となっていますが（引用させて頂いたブログの方々には敬意と感謝を表します）、panic自体私が普段触れない部分が大きく、また聞きした情報は基本載せないと言うスタイル故にです。ただ、ただ引用しているだけではなく、ソースコードの部分は筆者自身の手で調べていったので、まぁこのブログも多少は存在意義はあるかなと笑 ↩
参考:https://joeshaw.org/understanding-go-panic-output/ ↩
参考:http://text.baldanders.info/golang/stack-trace-and-panic-handling/ ↩
デバッガを使えば終わる話ですが、外部ライブラリに頼らずに確認出来る方法があれば知っておいて損はないと思っています。 ↩
参考:https://www.weblio.jp/content/%E3%82%B9%E3%82%BF%E3%83%83%E3%82%AF%E3%83%88%E3%83%AC%E3%83%BC%E3%82%B9 ↩

188

109

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up