Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TestCtlV3Elect: test timed out after 15s #6934

Closed
heyitsanthony opened this issue Dec 3, 2016 · 5 comments
Closed

TestCtlV3Elect: test timed out after 15s #6934

heyitsanthony opened this issue Dec 3, 2016 · 5 comments
Assignees
Milestone

Comments

@heyitsanthony
Copy link
Contributor

https://semaphoreci.com/coreos/etcd/branches/master/builds/1249

--- FAIL: TestCtlV3Elect (15.43s)
	ctl_v3_test.go:166: test timed out after 15s
@heyitsanthony heyitsanthony self-assigned this Dec 6, 2016
@heyitsanthony heyitsanthony added this to the v3.2.0 milestone Dec 6, 2016
@xiang90
Copy link
Contributor

xiang90 commented Feb 2, 2017

We got a stack trace for this one

https://semaphoreci.com/coreos/etcd/branches/pull-request-7269/builds/2

testutil.go:55: goroutine 573 [running]:
		github.com/coreos/etcd/pkg/testutil.FatalStack(0x18d7c280, 0x18e71460, 0x18)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/pkg/testutil/testutil.go:54 +0x72
		github.com/coreos/etcd/e2e.testCtl(0x18d7c280, 0x87a1024, 0x0, 0x0, 0x0)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_test.go:166 +0x4dc
		github.com/coreos/etcd/e2e.TestCtlV3Elect(0x18d7c280)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_elect_test.go:26 +0x38
		testing.tRunner(0x18d7c280, 0x87a0dbc)
			/usr/local/golang/1.7.4/go/src/testing/testing.go:610 +0x8c
		created by testing.(*T).Run
			/usr/local/golang/1.7.4/go/src/testing/testing.go:646 +0x2a5
		
		goroutine 1 [chan receive]:
		testing.(*T).Run(0x18d7c280, 0x8738955, 0xe, 0x87a0dbc, 0x18d7c401)
			/usr/local/golang/1.7.4/go/src/testing/testing.go:647 +0x2c4
		testing.RunTests.func1(0x18d7c480)
			/usr/local/golang/1.7.4/go/src/testing/testing.go:793 +0xa1
		testing.tRunner(0x18d7c480, 0x18d3fec0)
			/usr/local/golang/1.7.4/go/src/testing/testing.go:610 +0x8c
		testing.RunTests(0x87a22a4, 0x8a00be0, 0x87, 0x87, 0x1)
			/usr/local/golang/1.7.4/go/src/testing/testing.go:799 +0x332
		testing.(*M).Run(0x18d3ff84, 0x87346da)
			/usr/local/golang/1.7.4/go/src/testing/testing.go:743 +0x79
		github.com/coreos/etcd/e2e.TestMain(0x18d3ff84)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/e2e/main_test.go:27 +0xe5
		main.main()
			github.com/coreos/etcd/e2e/_test/_testmain.go:320 +0x100
		
		goroutine 48 [chan receive]:
		github.com/coreos/etcd/pkg/logutil.(*MergeLogger).outputLoop(0x18e2c590)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/pkg/logutil/merge_logger.go:174 +0x80
		created by github.com/coreos/etcd/pkg/logutil.NewMergeLogger
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/pkg/logutil/merge_logger.go:92 +0xaf
		
		goroutine 580 [semacquire]:
		sync.runtime_notifyListWait(0x18e70bc8, 0x0)
			/usr/local/golang/1.7.4/go/src/runtime/sema.go:267 +0x17b
		sync.(*Cond).Wait(0x18e70bc0)
			/usr/local/golang/1.7.4/go/src/sync/cond.go:57 +0x8d
		github.com/coreos/etcd/pkg/expect.(*ExpectProcess).ExpectFunc(0x18d826e0, 0x87a0f6c, 0x0, 0x0, 0x0, 0x0)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:90 +0x66
		github.com/coreos/etcd/e2e.ctlV3Elect.func1(0x18d826e0, 0x18d0ea20, 0x18e54040)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_elect_test.go:106 +0x38
		created by github.com/coreos/etcd/e2e.ctlV3Elect
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_elect_test.go:111 +0x1ed
		
		goroutine 577 [syscall]:
		syscall.Syscall(0x3, 0x4, 0x18d71000, 0x1000, 0x4, 0x1000, 0x0)
			/usr/local/golang/1.7.4/go/src/syscall/asm_linux_386.s:20 +0x5
		syscall.read(0x4, 0x18d71000, 0x1000, 0x1000, 0x4, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/syscall/zsyscall_linux_386.go:783 +0x5b
		syscall.Read(0x4, 0x18d71000, 0x1000, 0x1000, 0x4, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/syscall/syscall_unix.go:161 +0x45
		os.(*File).read(0x18d2a898, 0x18d71000, 0x1000, 0x1000, 0x4, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/os/file_unix.go:228 +0x4a
		os.(*File).Read(0x18d2a898, 0x18d71000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/os/file.go:101 +0x6f
		bufio.(*Reader).fill(0x18e63f7c)
			/usr/local/golang/1.7.4/go/src/bufio/bufio.go:97 +0x172
		bufio.(*Reader).ReadSlice(0x18e63f7c, 0xa, 0x0, 0x0, 0x0, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/bufio/bufio.go:330 +0x1b4
		bufio.(*Reader).ReadBytes(0x18e63f7c, 0x811fd0a, 0x0, 0x0, 0x0, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/bufio/bufio.go:408 +0x92
		bufio.(*Reader).ReadString(0x18e63f7c, 0x18d2a80a, 0x0, 0x0, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/bufio/bufio.go:448 +0x42
		github.com/coreos/etcd/pkg/expect.(*ExpectProcess).read(0x18d82640)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:66 +0x107
		created by github.com/coreos/etcd/pkg/expect.NewExpect
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:57 +0x1ee
		
		goroutine 574 [syscall]:
		syscall.Syscall(0x3, 0x3, 0x18d87000, 0x1000, 0x187, 0x1000, 0x0)
			/usr/local/golang/1.7.4/go/src/syscall/asm_linux_386.s:20 +0x5
		syscall.read(0x3, 0x18d87000, 0x1000, 0x1000, 0x187, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/syscall/zsyscall_linux_386.go:783 +0x5b
		syscall.Read(0x3, 0x18d87000, 0x1000, 0x1000, 0x187, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/syscall/syscall_unix.go:161 +0x45
		os.(*File).read(0x18d2a560, 0x18d87000, 0x1000, 0x1000, 0x38, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/os/file_unix.go:228 +0x4a
		os.(*File).Read(0x18d2a560, 0x18d87000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/os/file.go:101 +0x6f
		bufio.(*Reader).fill(0x18d2977c)
			/usr/local/golang/1.7.4/go/src/bufio/bufio.go:97 +0x172
		bufio.(*Reader).ReadSlice(0x18d2977c, 0xa, 0x0, 0x0, 0x0, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/bufio/bufio.go:330 +0x1b4
		bufio.(*Reader).ReadBytes(0x18d2977c, 0x811fd0a, 0x0, 0x0, 0x0, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/bufio/bufio.go:408 +0x92
		bufio.(*Reader).ReadString(0x18d2977c, 0x18e5630a, 0x0, 0x0, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/bufio/bufio.go:448 +0x42
		github.com/coreos/etcd/pkg/expect.(*ExpectProcess).read(0x18d82050)
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:66 +0x107
		created by github.com/coreos/etcd/pkg/expect.NewExpect
			/home/runner/workspace/src/github.com/coreos/etcd/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:57 +0x1ee
		
		goroutine 579 [syscall]:
		syscall.Syscall(0x3, 0x6, 0x18e16000, 0x1000, 0x1909dfa0, 0xf779a120, 0x0)
			/usr/local/golang/1.7.4/go/src/syscall/asm_linux_386.s:20 +0x5
		syscall.read(0x6, 0x18e16000, 0x1000, 0x1000, 0xffffffff, 0x0, 0x0)
			/usr/local/golang/1.7.4/go/src/syscall/zsyscall_linux_386.go:783 +0x5b
		syscall.Read(0x6, 0x18e16000, 0x1000, 0x1000, 0x8, 0x0, 0x0)

@heyitsanthony
Copy link
Contributor Author

Still useless, unfortunately-- no idea which ctlV3Elect call it is, only some election process is waiting too long to get leadership. ctlV3Lock is slightly better-- it's blocking on expect.Close() with a trace into the test (instead of being detached on a goroutine), but all that says is it's hanging somewhere on cleanup after getting the SIGTERM.

heyitsanthony pushed a commit to heyitsanthony/etcd that referenced this issue May 5, 2017
Meant to debug etcd-io#6464 and etcd-io#6934

Dumps the output from the etcd/etcdctl servers and SIGQUITs to get a
golang backtrace in case of a hanged process.
heyitsanthony pushed a commit to heyitsanthony/etcd that referenced this issue May 8, 2017
Meant to debug etcd-io#6464 and etcd-io#6934

Dumps the output from the etcd/etcdctl servers and SIGQUITs to get a
golang backtrace in case of a hanged process.
heyitsanthony pushed a commit to heyitsanthony/etcd that referenced this issue May 9, 2017
Meant to debug etcd-io#6464 and etcd-io#6934

Dumps the output from the etcd/etcdctl servers and SIGQUITs to get a
golang backtrace in case of a hanged process.
heyitsanthony pushed a commit to heyitsanthony/etcd that referenced this issue May 10, 2017
Meant to debug etcd-io#6464 and etcd-io#6934

Dumps the output from the etcd/etcdctl servers and SIGQUITs to get a
golang backtrace in case of a hanged process.
heyitsanthony pushed a commit to heyitsanthony/etcd that referenced this issue May 11, 2017
Meant to debug etcd-io#6464 and etcd-io#6934

Dumps the output from the etcd/etcdctl servers and SIGQUITs to get a
golang backtrace in case of a hanged process.
heyitsanthony pushed a commit to heyitsanthony/etcd that referenced this issue May 12, 2017
Meant to debug etcd-io#6464 and etcd-io#6934

Dumps the output from the etcd/etcdctl servers and SIGQUITs to get a
golang backtrace in case of a hanged process.
@heyitsanthony heyitsanthony modified the milestones: v3.3.0, v3.2.0 Jun 9, 2017
@fanminshi
Copy link
Member

via https://jenkins-etcd-public.prod.coreos.systems/job/etcd-proxy/2285/console

=== RUN   TestCtlV3Elect
../bin/etcd-25130: 2017-08-01 04:44:20.934767 W | pkg/flags: unrecognized environment variable ETCD_UNSUPPORTED_ARCH=amd64
../bin/etcd-25130: 2017-08-01 04:44:20.934838 I | etcdmain: etcd Version: 3.2.0+git
../bin/etcd-25130: 2017-08-01 04:44:20.934847 I | etcdmain: Git SHA: 548815c
../bin/etcd-25130: 2017-08-01 04:44:20.934853 I | etcdmain: Go Version: go1.8
../bin/etcd-25130: 2017-08-01 04:44:20.934858 I | etcdmain: Go OS/Arch: linux/amd64
../bin/etcd-25130: 2017-08-01 04:44:20.934864 I | etcdmain: setting maximum number of CPUs to 2, total number of available CPUs is 2
../bin/etcd-25130: 2017-08-01 04:44:20.959511 I | embed: peerTLS: cert = /tmp/testname0.etcd310169886/fixtures/peer/cert.pem, key = /tmp/testname0.etcd310169886/fixtures/peer/key.pem, ca = , trusted-ca = , client-cert-auth = false, crl-file = 
../bin/etcd-25130: 2017-08-01 04:44:20.971362 I | embed: listening for peers on https://localhost:20001
../bin/etcd-25130: 2017-08-01 04:44:20.971534 I | embed: listening for client requests on localhost:20000
../bin/etcd-25130: 2017-08-01 04:44:20.986182 I | etcdserver: name = testname0
../bin/etcd-25130: 2017-08-01 04:44:20.986206 I | etcdserver: data dir = /tmp/testname0.etcd310169886
../bin/etcd-25130: 2017-08-01 04:44:20.986212 I | etcdserver: member dir = /tmp/testname0.etcd310169886/member
../bin/etcd-25130: 2017-08-01 04:44:20.986224 I | etcdserver: heartbeat = 100ms
../bin/etcd-25130: 2017-08-01 04:44:20.986230 I | etcdserver: election = 1000ms
../bin/etcd-25130: 2017-08-01 04:44:20.986236 I | etcdserver: snapshot count = 100000
../bin/etcd-25130: 2017-08-01 04:44:20.986246 I | etcdserver: advertise client URLs = http://localhost:20000
../bin/etcd-25130: 2017-08-01 04:44:20.986273 I | etcdserver: initial advertise peer URLs = https://localhost:20001
../bin/etcd-25130: 2017-08-01 04:44:20.986288 I | etcdserver: initial cluster = testname0=https://localhost:20001
../bin/etcd-25130: 2017-08-01 04:44:20.991095 I | etcdserver: starting member a8f3458387986d in cluster 34c21a2d427db393
../bin/etcd-25130: 2017-08-01 04:44:20.991265 I | raft: a8f3458387986d became follower at term 0
../bin/etcd-25130: 2017-08-01 04:44:20.991304 I | raft: newRaft a8f3458387986d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
../bin/etcd-25130: 2017-08-01 04:44:20.991316 I | raft: a8f3458387986d became follower at term 1
../bin/etcd-25130: 2017-08-01 04:44:20.996525 W | auth: simple token is not cryptographically signed
../bin/etcd-25130: 2017-08-01 04:44:21.024713 I | etcdserver: starting server... [version: 3.2.0+git, cluster version: to_be_decided]
../bin/etcd-25130: 2017-08-01 04:44:21.025627 I | etcdserver/membership: added member a8f3458387986d [https://localhost:20001] to cluster 34c21a2d427db393
../bin/etcd-25130: 2017-08-01 04:44:21.191663 I | raft: a8f3458387986d is starting a new election at term 1
../bin/etcd-25130: 2017-08-01 04:44:21.191750 I | raft: a8f3458387986d became candidate at term 2
../bin/etcd-25130: 2017-08-01 04:44:21.191825 I | raft: a8f3458387986d received MsgVoteResp from a8f3458387986d at term 2
../bin/etcd-25130: 2017-08-01 04:44:21.191848 I | raft: a8f3458387986d became leader at term 2
../bin/etcd-25130: 2017-08-01 04:44:21.191858 I | raft: raft.node: a8f3458387986d elected leader a8f3458387986d at term 2
../bin/etcd-25130: 2017-08-01 04:44:21.192282 I | etcdserver: setting up the initial cluster version to 3.2
../bin/etcd-25130: 2017-08-01 04:44:21.193249 N | etcdserver/membership: set the initial cluster version to 3.2
../bin/etcd-25130: 2017-08-01 04:44:21.193329 I | etcdserver: published {Name:testname0 ClientURLs:[http://localhost:20000]} to cluster 34c21a2d427db393
../bin/etcd-25130: 2017-08-01 04:44:21.193407 I | etcdserver/api: enabled capabilities for version 3.2
../bin/etcd-25130: 2017-08-01 04:44:21.193464 I | embed: ready to serve client requests
../bin/etcd-25130: 2017-08-01 04:44:21.193499 E | etcdmain: forgot to set Type=notify in systemd service file?
../bin/etcd-25130: 2017-08-01 04:44:21.195745 N | embed: serving insecure client requests on 127.0.0.1:20000, this is strongly discouraged!
../bin/etcd-25139: 2017-08-01 04:44:21.204772 W | pkg/flags: unrecognized environment variable ETCD_UNSUPPORTED_ARCH=amd64
../bin/etcd-25139: 2017-08-01 04:44:21.204832 I | etcdmain: etcd Version: 3.2.0+git
../bin/etcd-25139: 2017-08-01 04:44:21.204842 I | etcdmain: Git SHA: 548815c
../bin/etcd-25139: 2017-08-01 04:44:21.204849 I | etcdmain: Go Version: go1.8
../bin/etcd-25139: 2017-08-01 04:44:21.204862 I | etcdmain: Go OS/Arch: linux/amd64
../bin/etcd-25139: 2017-08-01 04:44:21.204868 I | etcdmain: setting maximum number of CPUs to 2, total number of available CPUs is 2
../bin/etcd-25139: 2017-08-01 04:44:21.204878 W | etcdmain: no data-dir provided, using default data-dir ./testname-proxy-0xc420084000.etcd
../bin/etcd-25139: 2017-08-01 04:44:21.204890 N | etcdmain: proxy: this proxy supports v2 API only!
../bin/etcd-25139: 2017-08-01 04:44:21.241047 I | etcdmain: proxy: using peer urls [https://localhost:20001] 
../bin/etcd-25139: 2017-08-01 04:44:21.294133 I | proxy/httpproxy: endpoints found ["http://localhost:20000"]
../bin/etcd-25139: 2017-08-01 04:44:21.294172 I | etcdmain: proxy: listening for client requests on http://localhost:20002
../bin/etcd-25139: 2017-08-01 04:44:21.295512 E | etcdmain: forgot to set Type=notify in systemd service file?
../bin/etcd-25146: 2017-08-01 04:44:21.305643 I | etcdmain: listening for grpc-proxy client requests on localhost:20003
../bin/etcd-25146: 2017-08-01 04:44:21.306434 E | etcdmain: forgot to set Type=notify in systemd service file?
../bin/etcdctl-25154: a/186d5d9c1be87f04
../bin/etcdctl-25154: p1
../bin/etcdctl-25161: Error: context canceled
../bin/etcd-25146: 2017-08-01 04:44:21.531554 I | etcdserver/api/v3rpc: transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:20003->127.0.0.1:55638: read: connection reset by peer
../bin/etcdctl-25170: a/186d5d9c1be87f0d
../bin/etcdctl-25170: p2
panic: test timed out after 15m0s

goroutine 389 [running]:
testing.startAlarm.func1()
	/usr/local/go/src/testing/testing.go:1023 +0xf9
created by time.goFunc
	/usr/local/go/src/time/sleep.go:170 +0x44

goroutine 1 [chan receive, 14 minutes]:
testing.(*T).Run(0xc4201acb60, 0xc849f0, 0xe, 0xcaa8f8, 0xc4201c7c01)
	/usr/local/go/src/testing/testing.go:698 +0x2f4
testing.runTests.func1(0xc4201acb60)
	/usr/local/go/src/testing/testing.go:882 +0x67
testing.tRunner(0xc4201acb60, 0xc4201c7d90)
	/usr/local/go/src/testing/testing.go:657 +0x96
testing.runTests(0xc4201a1a20, 0x103b9e0, 0x78, 0x78, 0xc8259a)
	/usr/local/go/src/testing/testing.go:888 +0x2c1
testing.(*M).Run(0xc42004bf20, 0xc8b5d7)
	/usr/local/go/src/testing/testing.go:822 +0xfc
github.com/coreos/etcd/e2e.TestMain(0xc4201c7f20)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/main_test.go:48 +0x415
main.main()
	github.com/coreos/etcd/e2e/_test/_testmain.go:278 +0xf7

goroutine 17 [syscall, 14 minutes, locked to thread]:
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:2197 +0x1

goroutine 43 [chan receive]:
github.com/coreos/etcd/pkg/logutil.(*MergeLogger).outputLoop(0xc420167f60)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/logutil/merge_logger.go:174 +0x94
created by github.com/coreos/etcd/pkg/logutil.NewMergeLogger
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/logutil/merge_logger.go:92 +0xd4

goroutine 378 [syscall, 14 minutes]:
syscall.Syscall6(0xf7, 0x1, 0x623a, 0xc420049638, 0x1000004, 0x0, 0x0, 0xb42f40, 0x300000001, 0xc420011da0)
	/usr/local/go/src/syscall/asm_linux_amd64.s:44 +0x5
os.(*Process).blockUntilWaitable(0xc42013f0b0, 0xc42001e000, 0x0, 0x0)
	/usr/local/go/src/os/wait_waitid.go:28 +0xa5
os.(*Process).wait(0xc42013f0b0, 0xc42013f0c4, 0x3, 0x0)
	/usr/local/go/src/os/exec_unix.go:22 +0x4d
os.(*Process).Wait(0xc42013f0b0, 0xc4200497e8, 0x49354f, 0xc42013f0b0)
	/usr/local/go/src/os/exec.go:115 +0x2b
os/exec.(*Cmd).Wait(0xc420178160, 0xff95e0, 0xc4201ae268)
	/usr/local/go/src/os/exec/exec.go:435 +0x62
github.com/coreos/etcd/pkg/expect.(*ExpectProcess).close(0xc4201ba500, 0x1, 0xc4200140f0, 0x0)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:152 +0x4b
github.com/coreos/etcd/pkg/expect.(*ExpectProcess).Stop(0xc4201ba500, 0xc4200498e8, 0xa9282b)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:134 +0x30
github.com/coreos/etcd/e2e.(*proxyProc).Stop(0xc42001c3c0, 0x0, 0x0)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/cluster_proxy_test.go:148 +0x3c
github.com/coreos/etcd/e2e.(*proxyEtcdProcess).Stop(0xc42013d7c0, 0xc4200499a0, 0x42b90f)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/cluster_proxy_test.go:83 +0x5b
github.com/coreos/etcd/e2e.(*etcdProcessCluster).Stop(0xc42013d5c0, 0xb, 0xc420049a20)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/cluster_test.go:339 +0x88
github.com/coreos/etcd/e2e.(*etcdProcessCluster).Close(0xc42013d5c0, 0xb, 0x0)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/cluster_test.go:351 +0x2f
github.com/coreos/etcd/e2e.testCtl.func1(0xc42042c000, 0xc420172270)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_test.go:149 +0xe9
runtime.Goexit()
	/usr/local/go/src/runtime/panic.go:366 +0x153
testing.(*common).FailNow(0xc420172270)
	/usr/local/go/src/testing/testing.go:486 +0x39
testing.(*common).Fatalf(0xc420172270, 0xc4201ce4e0, 0x18, 0x0, 0x0, 0x0)
	/usr/local/go/src/testing/testing.go:530 +0x83
github.com/coreos/etcd/pkg/testutil.FatalStack(0xc420172270, 0xc4201ce4e0, 0x18)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/testutil/testutil.go:56 +0x16a
github.com/coreos/etcd/e2e.testCtl(0xc420172270, 0xcaad80, 0x0, 0x0, 0x0)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_test.go:166 +0x452
github.com/coreos/etcd/e2e.TestCtlV3Elect(0xc420172270)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_elect_test.go:31 +0xe2
testing.tRunner(0xc420172270, 0xcaa8f8)
	/usr/local/go/src/testing/testing.go:657 +0x96
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:697 +0x2ca

goroutine 369 [syscall, 14 minutes]:
syscall.Syscall(0x0, 0xa, 0xc420427000, 0x1000, 0x4bd3dc, 0xc42000a716, 0xc4201af204)
	/usr/local/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0xa, 0xc420427000, 0x1000, 0x1000, 0x100, 0xc420036bb8, 0x0)
	/usr/local/go/src/syscall/zsyscall_linux_amd64.go:783 +0x55
syscall.Read(0xa, 0xc420427000, 0x1000, 0x1000, 0xc420036be8, 0x434b0e, 0xc42017a340)
	/usr/local/go/src/syscall/syscall_unix.go:162 +0x49
os.(*File).read(0xc42000e068, 0xc420427000, 0x1000, 0x1000, 0x1, 0x1, 0xc42000a700)
	/usr/local/go/src/os/file_unix.go:165 +0x4f
os.(*File).Read(0xc42000e068, 0xc420427000, 0x1000, 0x1000, 0x1a, 0x100, 0x1a)
	/usr/local/go/src/os/file.go:101 +0x76
bufio.(*Reader).fill(0xc420036f18)
	/usr/local/go/src/bufio/bufio.go:97 +0x117
bufio.(*Reader).ReadSlice(0xc420036f18, 0xc420036d0a, 0x410d82, 0xc4201ce4c0, 0x20, 0x20, 0xb42c80)
	/usr/local/go/src/bufio/bufio.go:338 +0xbb
bufio.(*Reader).ReadBytes(0xc420036f18, 0xa, 0x20, 0xc4201ce4c0, 0x3, 0x3, 0x1a)
	/usr/local/go/src/bufio/bufio.go:416 +0x66
bufio.(*Reader).ReadString(0xc420036f18, 0xc4201af10a, 0x1, 0x1, 0x2, 0xc4201ce4c0)
	/usr/local/go/src/bufio/bufio.go:456 +0x38
github.com/coreos/etcd/pkg/expect.(*ExpectProcess).read(0xc4201ba980)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:80 +0x13c
created by github.com/coreos/etcd/pkg/expect.NewExpectWithEnv
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:70 +0x262

goroutine 381 [syscall, 14 minutes]:
syscall.Syscall6(0xf7, 0x1, 0x6252, 0xc4200477a8, 0x1000004, 0x0, 0x0, 0x2, 0x2, 0xc420047d30)
	/usr/local/go/src/syscall/asm_linux_amd64.s:44 +0x5
os.(*Process).blockUntilWaitable(0xc42013f920, 0xc42001f300, 0x0, 0x0)
	/usr/local/go/src/os/wait_waitid.go:28 +0xa5
os.(*Process).wait(0xc42013f920, 0xc42013f934, 0x3, 0x0)
	/usr/local/go/src/os/exec_unix.go:22 +0x4d
os.(*Process).Wait(0xc42013f920, 0xc420047958, 0x49354f, 0xc42013f920)
	/usr/local/go/src/os/exec.go:115 +0x2b
os/exec.(*Cmd).Wait(0xc420178420, 0xff95e0, 0xc4201ae268)
	/usr/local/go/src/os/exec/exec.go:435 +0x62
github.com/coreos/etcd/pkg/expect.(*ExpectProcess).close(0xc4201ba980, 0xcaae01, 0xc4201a4050, 0xc420047a20)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:152 +0x4b
github.com/coreos/etcd/pkg/expect.(*ExpectProcess).Stop(0xc4201ba980, 0x0, 0x0)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:134 +0x30
github.com/coreos/etcd/e2e.testElect(0xc420172270, 0xc4201ae910, 0xb, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x4e20, ...)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_elect_test.go:104 +0x8d4
github.com/coreos/etcd/e2e.testCtl.func2(0xc42001d5c0, 0xcaad80, 0xc42042c000)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_test.go:157 +0x83
created by github.com/coreos/etcd/e2e.testCtl
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/e2e/ctl_v3_test.go:158 +0x2f8

goroutine 366 [syscall, 14 minutes]:
syscall.Syscall(0x0, 0x7, 0xc4200b2000, 0x1000, 0x4bd3dc, 0xc4201b8113, 0xc420452180)
	/usr/local/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x7, 0xc4200b2000, 0x1000, 0x1000, 0x100, 0xc42003abb8, 0x0)
	/usr/local/go/src/syscall/zsyscall_linux_amd64.go:783 +0x55
syscall.Read(0x7, 0xc4200b2000, 0x1000, 0x1000, 0xc42003abe8, 0x434b0e, 0xc4200b91e0)
	/usr/local/go/src/syscall/syscall_unix.go:162 +0x49
os.(*File).read(0xc42000e038, 0xc4200b2000, 0x1000, 0x1000, 0x1, 0x1, 0xc4201b8100)
	/usr/local/go/src/os/file_unix.go:165 +0x4f
os.(*File).Read(0xc42000e038, 0xc4200b2000, 0x1000, 0x1000, 0xce, 0x100, 0xce)
	/usr/local/go/src/os/file.go:101 +0x76
bufio.(*Reader).fill(0xc42003af18)
	/usr/local/go/src/bufio/bufio.go:97 +0x117
bufio.(*Reader).ReadSlice(0xc42003af18, 0xc42003ad0a, 0x410d82, 0xc4201a1e60, 0x20, 0x20, 0xb42c80)
	/usr/local/go/src/bufio/bufio.go:338 +0xbb
bufio.(*Reader).ReadBytes(0xc42003af18, 0xa, 0x20, 0xc4201a1e60, 0x3, 0x3, 0xce)
	/usr/local/go/src/bufio/bufio.go:416 +0x66
bufio.(*Reader).ReadString(0xc42003af18, 0xc42014480a, 0x1, 0x1, 0x2, 0xc4201a1e60)
	/usr/local/go/src/bufio/bufio.go:456 +0x38
github.com/coreos/etcd/pkg/expect.(*ExpectProcess).read(0xc4201ba500)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:80 +0x13c
created by github.com/coreos/etcd/pkg/expect.NewExpectWithEnv
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:70 +0x262

goroutine 380 [syscall, 14 minutes]:
syscall.Syscall(0x0, 0x5, 0xc42018f000, 0x1000, 0x4bd3dc, 0xc42000a713, 0xc42001aa80)
	/usr/local/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x5, 0xc42018f000, 0x1000, 0x1000, 0x100, 0xc420035bb8, 0x0)
	/usr/local/go/src/syscall/zsyscall_linux_amd64.go:783 +0x55
syscall.Read(0x5, 0xc42018f000, 0x1000, 0x1000, 0xc420035be8, 0x434b0e, 0xc4200b9860)
	/usr/local/go/src/syscall/syscall_unix.go:162 +0x49
os.(*File).read(0xc420192018, 0xc42018f000, 0x1000, 0x1000, 0x1, 0x1, 0xc42000a700)
	/usr/local/go/src/os/file_unix.go:165 +0x4f
os.(*File).Read(0xc420192018, 0xc42018f000, 0x1000, 0x1000, 0x8d, 0x100, 0x8d)
	/usr/local/go/src/os/file.go:101 +0x76
bufio.(*Reader).fill(0xc420035f18)
	/usr/local/go/src/bufio/bufio.go:97 +0x117
bufio.(*Reader).ReadSlice(0xc420035f18, 0xc420035d0a, 0x410d82, 0xc4201909c0, 0x40, 0x40, 0xb42c80)
	/usr/local/go/src/bufio/bufio.go:338 +0xbb
bufio.(*Reader).ReadBytes(0xc420035f18, 0xa, 0x40, 0xc4201909c0, 0x3, 0x3, 0x8d)
	/usr/local/go/src/bufio/bufio.go:416 +0x66
bufio.(*Reader).ReadString(0xc420035f18, 0xc42013df0a, 0x2, 0x2, 0x3, 0xc4201909c0)
	/usr/local/go/src/bufio/bufio.go:456 +0x38
github.com/coreos/etcd/pkg/expect.(*ExpectProcess).read(0xc42001a400)
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:80 +0x13c
created by github.com/coreos/etcd/pkg/expect.NewExpectWithEnv
	/home/jenkins/workspace/etcd-proxy/gopath/src/github.com/coreos/etcd/pkg/expect/expect.go:70 +0x262
exit status 2
FAIL	github.com/coreos/etcd/e2e	900.017s

@heyitsanthony
Copy link
Contributor Author

A related bug (#8355) can be reproduced reliably on jenkins by sending SIGQUIT to the etcdctl process instead of SIGTERM or SIGKILL. Not necessarliy the same bug since it only happens on SIGQUIT, whereas semaphore is os.Interrupt and SIGTERM.

yudai pushed a commit to yudai/etcd that referenced this issue Oct 5, 2017
Meant to debug etcd-io#6464 and etcd-io#6934

Dumps the output from the etcd/etcdctl servers and SIGQUITs to get a
golang backtrace in case of a hanged process.
@xiang90
Copy link
Contributor

xiang90 commented Nov 9, 2017

i have seen this for quite a while, and cannot reproduce it. so closing this for now.

@xiang90 xiang90 closed this as completed Nov 9, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

3 participants