Panic in event handler will be blocked by defer func

[gobomb]

When we use event handler, sometime it will panic in handler, we expect the process will crash. But it just prints the call stack and never exits. I read the code and found that the panic will blocked by defer wg.Wait() .

I run process which just panic simpliy in an event handler , use gcore [pid] to produce the coredump, and use dlv core to check the call stack. I found these:

(dlv) gr 8 bt
 0  0x0000000000435570 in runtime.gopark
    at C:/Go/src/runtime/proc.go:305
 1  0x00000000004456b0 in runtime.goparkunlock
    at C:/Go/src/runtime/proc.go:310
 2  0x00000000004456b0 in runtime.semacquire1
    at C:/Go/src/runtime/sema.go:144
 3  0x0000000000445302 in sync.runtime_Semacquire
    at C:/Go/src/runtime/sema.go:56
 4  0x000000000047c2a4 in sync.(*WaitGroup).Wait
    at C:/Go/src/sync/waitgroup.go:130
 5  0x0000000001082c5d in k8s.io/apimachinery/pkg/util/wait.(*Group).Wait
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:47
 6  0x000000000046039b in runtime.call32
    at C:/Go/src/runtime/asm_amd64.s:1
 7  0x0000000000432298 in runtime.reflectcallSave
    at C:/Go/src/runtime/panic.go:879
 8  0x0000000000432159 in runtime.runOpenDeferFrame
    at C:/Go/src/runtime/panic.go:853
 9  0x000000000043249d in runtime.gopanic
    at C:/Go/src/runtime/panic.go:967
10  0x00000000007aa305 in k8s.io/apimachinery/pkg/util/runtime.HandleCrash
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/pkg/util/runtime/runtime.go:55
11  0x000000000046039b in runtime.call32
    at C:/Go/src/runtime/asm_amd64.s:1
12  0x0000000000432298 in runtime.reflectcallSave
    at C:/Go/src/runtime/panic.go:879
13  0x0000000000432159 in runtime.runOpenDeferFrame
    at C:/Go/src/runtime/panic.go:853
14  0x000000000043249d in runtime.gopanic
    at C:/Go/src/runtime/panic.go:967
15  0x00000000010d72be in main.(*controller).addPVCFunc
    at C:/Users/86182/gopath/src/github.com/weaveworks/panicDump/main.go:103
16  0x00000000010d764e in main.(*controller).addPVCFunc-fm
    at C:/Users/86182/gopath/src/github.com/weaveworks/panicDump/main.go:96
17  0x000000000109919a in k8s.io/client-go/tools/cache.(*ResourceEventHandlerFuncs).OnAdd
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/tools/cache/controller.go:198
18  0x00000000010964da in k8s.io/client-go/tools/cache.newInformer.func1
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/tools/cache/controller.go:370
19  0x000000000108e765 in k8s.io/client-go/tools/cache.(*DeltaFIFO).Pop
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/tools/cache/delta_fifo.go:422
20  0x000000000108bf20 in k8s.io/client-go/tools/cache.(*controller).processLoop
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/tools/cache/controller.go:153
21  0x000000000109904a in k8s.io/client-go/tools/cache.(*controller).processLoop-fm
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/tools/cache/controller.go:151
22  0x00000000010832ff in k8s.io/apimachinery/pkg/util/wait.JitterUntil.func1
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:152
23  0x0000000001082f58 in k8s.io/apimachinery/pkg/util/wait.JitterUntil
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:153
24  0x000000000108bca1 in k8s.io/apimachinery/pkg/util/wait.Until
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:88
25  0x000000000108bca1 in k8s.io/client-go/tools/cache.(*controller).Run
    at C:/Users/86182/gopath/pkg/mod/k8s.io/[email protected]/tools/cache/controller.go:125
26  0x0000000000461f71 in runtime.goexit
    at C:/Go/src/runtime/asm_amd64.s:1373

We can see the panic was called at frame 16 , and was catched by k8s.io/apimachinery/pkg/util/runtime.HandleCrash at 10. It printed the call stack in HandleCrash and panic again. The defer func was call at frame 8, it's k8s.io/apimachinery/pkg/util/wait.(*Group).Wait (at 5). Panic was blocked at here. Finally, this goroutine was scheduled to gopark , would not exit or crash the whole process.

The go code in tools/cache/controller.go is :

func (c *controller) Run(stopCh <-chan struct{}) {
	defer utilruntime.HandleCrash()
	go func() {
		<-stopCh
		c.config.Queue.Close()
	}()
	r := NewReflector(
		c.config.ListerWatcher,
		c.config.ObjectType,
		c.config.Queue,
		c.config.FullResyncPeriod,
	)
	r.ShouldResync = c.config.ShouldResync
	r.clock = c.clock
	if c.config.WatchErrorHandler != nil {
		r.watchErrorHandler = c.config.WatchErrorHandler
	}

	c.reflectorMutex.Lock()
	c.reflector = r
	c.reflectorMutex.Unlock()

	var wg wait.Group
	defer wg.Wait()                                 // <-- blocked at this line forever

	wg.StartWithChannel(stopCh, r.Run)

	wait.Until(c.processLoop, time.Second, stopCh)  // <-- panic in c.processLoop
}

The sample code I run is:

func main() {
	var kubeconfig string
	var master string

	flag.StringVar(&kubeconfig, "kubeconfig", "", "absolute path to the kubeconfig file")
	flag.StringVar(&master, "master", "", "master url")
	flag.Parse()

	// creates the connection
	config, err := clientcmd.BuildConfigFromFlags(master, kubeconfig)
	if err != nil {
		klog.Fatal(err)
	}

	// creates the clientset
	clientSet, err := kubernetes.NewForConfig(config)
	if err != nil {
		klog.Fatal(err)
	}

	pvCtrl := NewController(clientSet)

	pvCtrl.Loop(wait.NeverStop)
}

func NewController(clientSet *kubernetes.Clientset) controller {
	// List and watch the PersistentVolumeClaims
	lw := &cache.ListWatch{
		ListFunc: func(options metav1.ListOptions) (runtime.Object, error) {
			return clientSet.CoreV1().PersistentVolumeClaims(corev1.NamespaceAll).List(options)
		},
		WatchFunc: func(options metav1.ListOptions) (watch.Interface, error) {
			return clientSet.CoreV1().PersistentVolumeClaims(corev1.NamespaceAll).Watch(options)
		},
	}

	c := controller{
		clientSet:  clientSet,
	}

	claimHandler := cache.ResourceEventHandlerFuncs{
		AddFunc:    c.addPVCFunc,
		DeleteFunc: c.deletePVCFunc,
	}

	c.claimStore, c.claimCtrl = cache.NewInformer(lw, &corev1.PersistentVolumeClaim{}, DefaultResyncPeriod,
		claimHandler)

	return c
}

func (c *controller) Loop(stopCh <-chan struct{}) {
	go c.claimCtrl.Run(stopCh)

	<-stopCh
}

func (c *controller) deletePVCFunc(obj interface{}) {
	_, ok := obj.(*corev1.PersistentVolumeClaim)
	if !ok {
		klog.Errorf("Expected PersistentVolumeClaim but deletePVCFunc received %+v", obj)
		return
	}

}

func (c *controller) addPVCFunc(obj interface{}) {
	_, ok := obj.(*corev1.PersistentVolumeClaim)
	if !ok {
		klog.Errorf("Expected PersistentVolumeClaim but addPVCFunc received %+v", obj)
		return
	}

	panic("Just panic!")
}

versions of docker/k8s/system:

$ docker version
Client: Docker Engine - Community
 Version:           19.03.5
 API version:       1.40
 Go version:        go1.12.12
 Git commit:        633a0ea838
 Built:             Wed Nov 13 07:22:05 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.5
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.12
  Git commit:       633a0ea838
  Built:            Wed Nov 13 07:28:45 2019
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.2.10
  GitCommit:        b34a5c8af56e510852c35414db4c1f4fa6172339
 runc:
  Version:          1.0.0-rc8+dev
  GitCommit:        3e425f80a8c931f88e6d94a8c831b9d5aa481657
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683
$ uname -a
Linux m1.ha.env.lab.io 3.10.0-1062.12.1.el7.x86_64 #1 SMP Tue Feb 4 23:02:59 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
$ kubectl version
Client Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.6", GitCommit:"72c30166b2105cd7d3350f2c28a219e6abcd79eb", GitTreeState:"clean", BuildDate:"2020-01-18T23:31:31Z", GoVersion:"go1.13.5", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.6", GitCommit:"72c30166b2105cd7d3350f2c28a219e6abcd79eb", GitTreeState:"clean", BuildDate:"2020-01-18T23:23:21Z", GoVersion:"go1.13.5", Compiler:"gc", Platform:"linux/amd64"}
Use 'kc' as shortcut of kubectl and 'kd' for 'kubectl describe'

version of go:

go1.14 windows/amd64

go.mod:

	k8s.io/api  v0.17.6
	k8s.io/apimachinery  v0.17.6
	k8s.io/client-go v0.17.6
	k8s.io/klog/v2 v2.0.0
	k8s.io/utils v0.0.0-20200731180307-f00132d28269 // indirect