Failed to start volume

[Madhu-1]

Observed behavior

failed to start volume from glustercli, glusterd2 service is going down due to panic, even Recover middleware is also not handling the panic

Expected/desired behavior

volume start should be successful, and middleware should handle panic

Details on how to reproduce (minimal and precise)

• create a volume

  ./build/glustercli volume create test1 328fbe9f-3b23-4fb3-bfa6-80d9802fcff0:/3 0b86dc7a-e243-4cf5-a523-5dca73b87cdd:/3 a6f7791f-6ca3-41ae-962f-01590680c7a3:/3 --force
  test3 Volume created successfully

• start a volume

  ./build/glustercli volume start test1
  volume start failed
  Post http://127.0.0.1:24007/v1/volumes/test1/start: EOF

Information about the environment:

• Glusterd2 version used (e.g. v4.1.0 or master): master
• Operating system used: centos
• Glusterd2 compiled from sources, as a package (rpm/deb), or container: source
• Using External ETCD: (yes/no, if yes ETCD version): yes
• If container, which container image:
• Using kubernetes, openshift, or direct install: direct
• If kubernetes/openshift, is gluster running inside kubernetes/openshift or outside:

Other useful information

• glusterd2 log from failed node

  
  DEBU[2018-08-21 10:42:35.811707] new transaction created                       reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[transaction.go:62:transaction.NewTxn]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:35.811749] attempting to obtain lock                     lockID=test1 reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[lock.go:159:transaction.(*Txn).lock]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:35.812681] lock obtained                                 lockID=test1 reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[lock.go:170:transaction.(*Txn).lock]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:35.813888] Starting transaction                          reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[transaction.go:124:transaction.(*Txn).Do]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:35.814547] Running step on node.                         node=a6f7791f-6ca3-41ae-962f-01590680c7a3 reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[step.go:135:transaction.runStepFuncOnNode]" step=vol-start.StartBricks txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:35.814676] Running step on node.                         node=328fbe9f-3b23-4fb3-bfa6-80d9802fcff0 reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[step.go:135:transaction.runStepFuncOnNode]" step=vol-start.StartBricks txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:35.814751] Running step on node.                         node=0b86dc7a-e243-4cf5-a523-5dca73b87cdd reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[step.go:135:transaction.runStepFuncOnNode]" step=vol-start.StartBricks txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  INFO[2018-08-21 10:42:35.816063] Starting brick                                brick="328fbe9f-3b23-4fb3-bfa6-80d9802fcff0:/1" reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[volume-start.go:32:volumes.startAllBricks]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe volume=test1
  DEBU[2018-08-21 10:42:35.816233] Obtained lock on pmap port lock file.         lock-file=/var/run/glusterd2_pmap_port_49152.lock source="[pmap.go:97:pmap.(*registryType).TryPortLock]"
  DEBU[2018-08-21 10:42:35.816355] Obtained lock on pmap port lock file.         lock-file=/var/run/glusterd2_pmap_port_49153.lock source="[pmap.go:97:pmap.(*registryType).TryPortLock]"
  DEBU[2018-08-21 10:42:35.816448] Starting daemon.                              args="--volfile-server 127.0.0.1 --volfile-server-port 24007 --volfile-id test1.328fbe9f-3b23-4fb3-bfa6-80d9802fcff0.1 -p /usr/local/var/run/glusterd2/328fbe9f-3b23-4fb3-bfa6-80d9802fcff0-1.pid -S /usr/local/var/run/glusterd2/85cc7d0a5d2f2ddd.socket --brick-name /1 --brick-port 49153 -l /usr/local/var/log/glusterd2/glusterfs/bricks/1.log --xlator-option *-posix.glusterd-uuid=328fbe9f-3b23-4fb3-bfa6-80d9802fcff0 --xlator-option test1-server.transport.socket.listen-port=49153" name=glusterfsd path=/usr/sbin/glusterfsd reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[daemon.go:60:daemon.Start]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:35.816622] connected to remote                           remote="dhcp43-106.lab.eng.blr.redhat.com:24008" remotepeer="a6f7791f-6ca3-41ae-962f-01590680c7a3(dhcp43-106.lab.eng.blr.redhat.com)" reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[rpc-client.go:47:transaction.runStepOn]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:35.817181] connected to remote                           remote="dhcp42-71.lab.eng.blr.redhat.com:24008" remotepeer="0b86dc7a-e243-4cf5-a523-5dca73b87cdd(dhcp42-71.lab.eng.blr.redhat.com)" reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[rpc-client.go:47:transaction.runStepOn]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  ERRO[2018-08-21 10:42:36.051020] TxnSvc.Runstep failed on peer                 error="exit status 1" remotepeer="a6f7791f-6ca3-41ae-962f-01590680c7a3(dhcp43-106.lab.eng.blr.redhat.com)" reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[rpc-client.go:77:transaction.runStepOn]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  ERRO[2018-08-21 10:42:36.051104] Step failed on node.                          error="exit status 1" node=a6f7791f-6ca3-41ae-962f-01590680c7a3 reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[step.go:119:transaction.runStepFuncOnNodes]" step=vol-start.StartBricks txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  ERRO[2018-08-21 10:42:36.052164] TxnSvc.Runstep failed on peer                 error="exit status 1" remotepeer="0b86dc7a-e243-4cf5-a523-5dca73b87cdd(dhcp42-71.lab.eng.blr.redhat.com)" reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[rpc-client.go:77:transaction.runStepOn]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  ERRO[2018-08-21 10:42:36.052240] Step failed on node.                          error="exit status 1" node=0b86dc7a-e243-4cf5-a523-5dca73b87cdd reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[step.go:119:transaction.runStepFuncOnNodes]" step=vol-start.StartBricks txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  ERRO[2018-08-21 10:42:36.052280] Transaction failed, rolling back changes      error="Step vol-start.StartBricks failed on 2 nodes" reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[transaction.go:143:transaction.(*Txn).Do]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:36.052325] Running step on node.                         node=a6f7791f-6ca3-41ae-962f-01590680c7a3 reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[step.go:135:transaction.runStepFuncOnNode]" step=vol-start.StartBricksUndo txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:36.052498] Running step on node.                         node=328fbe9f-3b23-4fb3-bfa6-80d9802fcff0 reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[step.go:135:transaction.runStepFuncOnNode]" step=vol-start.StartBricksUndo txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:36.052562] Running step on node.                         node=0b86dc7a-e243-4cf5-a523-5dca73b87cdd reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[step.go:135:transaction.runStepFuncOnNode]" step=vol-start.StartBricksUndo txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  INFO[2018-08-21 10:42:36.053559] volume start failed, stopping brick           brick="328fbe9f-3b23-4fb3-bfa6-80d9802fcff0:/1" reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[volume-start.go:56:volumes.stopAllBricks]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe volume=test1
  DEBU[2018-08-21 10:42:36.053694] Stopping daemon.                              name=glusterfsd pid=10629 reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[daemon.go:166:daemon.Stop]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  DEBU[2018-08-21 10:42:36.053805] Obtained lock on pmap port lock file.         lock-file=/var/run/glusterd2_pmap_port_49152.lock source="[pmap.go:97:pmap.(*registryType).TryPortLock]"
  DEBU[2018-08-21 10:42:36.053909] Obtained lock on pmap port lock file.         lock-file=/var/run/glusterd2_pmap_port_49154.lock source="[pmap.go:97:pmap.(*registryType).TryPortLock]"
  DEBU[2018-08-21 10:42:36.054140] connected to remote                           remote="dhcp43-106.lab.eng.blr.redhat.com:24008" remotepeer="a6f7791f-6ca3-41ae-962f-01590680c7a3(dhcp43-106.lab.eng.blr.redhat.com)" reqid=b685fe19-d36f-42e4-a5a7-f19248bd8908 source="[rpc-client.go:47:transaction.runStepOn]" txnid=29eac45c-ea9c-4468-a9cd-be00ef7392fe
  panic: runtime error: invalid memory address or nil pointer dereference
  [signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0x585146]

goroutine 173 [running]: context.propagateCancel(0x0, 0x0, 0x12c7be0, 0xc420b3aac0) /usr/local/go/src/context/context.go:243 +0x26 context.WithCancel(0x0, 0x0, 0x1b5f080, 0xfa5100, 0xc420018ae8) /usr/local/go/src/context/context.go:232 +0x111 github.com/gluster/glusterd2/vendor/golang.org/x/net/context.WithCancel(0x0, 0x0, 0x1b, 0x0, 0x0) /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/vendor/golang.org/x/net/context/go17.go:33 +0x35 github.com/gluster/glusterd2/vendor/google.golang.org/grpc.newClientStream(0x0, 0x0, 0x1b3b0c0, 0xc420018900, 0x11db414, 0x1b, 0x0, 0x0, 0x0, 0x0, ...) /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/vendor/google.golang.org/grpc/stream.go:161 +0x119 github.com/gluster/glusterd2/vendor/google.golang.org/grpc.invoke(0x0, 0x0, 0x11db414, 0x1b, 0x1095760, 0xc4207672f0, 0x1084ba0, 0xc4200b8c80, 0xc420018900, 0x0, ...) /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/vendor/google.golang.org/grpc/call.go:70 +0xa9 github.com/gluster/glusterd2/vendor/google.golang.org/grpc.(ClientConn).Invoke(0xc420018900, 0x0, 0x0, 0x11db414, 0x1b, 0x1095760, 0xc4207672f0, 0x1084ba0, 0xc4200b8c80, 0x0, ...) /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/vendor/google.golang.org/grpc/call.go:37 +0x1b3 github.com/gluster/glusterd2/vendor/google.golang.org/grpc.Invoke(0x0, 0x0, 0x11db414, 0x1b, 0x1095760, 0xc4207672f0, 0x1084ba0, 0xc4200b8c80, 0xc420018900, 0x0, ...) /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/vendor/google.golang.org/grpc/call.go:60 +0xc1 github.com/gluster/glusterd2/glusterd2/transaction.(txnSvcClient).RunStep(0xc42000ee40, 0x0, 0x0, 0xc4207672f0, 0x0, 0x0, 0x0, 0x0, 0x1, 0xc4200cf900) /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/glusterd2/transaction/transaction-rpc.pb.go:105 +0xd2 github.com/gluster/glusterd2/glusterd2/transaction.runStepOn(0x0, 0x0, 0x11d9a8d, 0x19, 0xc4206ab5b0, 0x10, 0x10, 0x12da400, 0xc420667410, 0x0, ...) /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/glusterd2/transaction/rpc-client.go:70 +0x4c6 github.com/gluster/glusterd2/glusterd2/transaction.runStepFuncOnNode(0x0, 0x0, 0x11d9a8d, 0x19, 0x12da400, 0xc420667410, 0xc4206ab5b0, 0x10, 0x10, 0xc420b87c20) /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/glusterd2/transaction/step.go:142 +0x400 created by github.com/gluster/glusterd2/glusterd2/transaction.runStepFuncOnNodes /home/mrajanna/workspace/heketi_pr/src/github.com/gluster/glusterd2/glusterd2/transaction/step.go:99 +0x160

[atinmu]

@Madhu-1 This sounds very basic. Is it a regression?

[Madhu-1]

@atinmu it's not a regression, but somehow I hit this issue.

[prashanthpai]

RCA: Although the stack trace points to a code path inside go's built-in context library, the culprit is our undo code path in txn framework which propagated nil context all the way down to the RPC layer. This is handled correctly in the Do path however and hence that's why it wasn't hit easily.