Robustness retry failpoint #16094
Merged
Robustness retry failpoint #16094
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
serathius
force-pushed
the
robustness-retry-failpoint
branch
3 times, most recently
from
bbec906
to
2a98ed5
Compare
Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>
serathius
force-pushed
the
robustness-retry-failpoint
branch
from
2a98ed5
to
43b2477
Compare
|
Wow, a full pass! https://github.com/etcd-io/etcd/actions/runs/5298895986?pr=16094 |
serathius
force-pushed
the
robustness-retry-failpoint
branch
from
7d3da81
to
43b2477
Compare
jmhbnz
reviewed
Jun 17, 2023
| lg.Info("Setting up gofailpoint", zap.String("failpoint", f.Name())) | ||
| err := member.Failpoints().Setup(ctx, f.failpoint, "panic") | ||
| if err != nil { | ||
| lg.Info("goFailpoint setup failed", zap.String("failpoint", f.Name()), zap.Error(err)) | ||
| continue |
There was a problem hiding this comment.
Can you provide some history/context on why gofailpoint setup can fail? Perhaps a comment line somewhere here would help future readers of this code as well.
There was a problem hiding this comment.
I don't know why :P, I haven't been able to reproduce the issue locally. Only on CI this happens, guessing some deadlock or zombie process thingy.
There was a problem hiding this comment.
Dump the log from https://github.com/etcd-io/etcd/actions/runs/5298895925/jobs/9591523910 for release-3.5. Check the goroutines after timeout. There were only two waitProcess stacks.
2023-06-17T18:53:04.8466750Z goroutine 680492 [syscall, 125 minutes]:
2023-06-17T18:53:04.8467149Z syscall.Syscall6(0x1000100000000?, 0x0?, 0x2?, 0xc000b80800?, 0x0?, 0x0?, 0xffffffffffffffff?)
2023-06-17T18:53:04.8467555Z /opt/hostedtoolcache/go/1.19.10/x64/src/syscall/syscall_linux.go:90 +0x36
2023-06-17T18:53:04.8467898Z os.(*Process).blockUntilWaitable(0xc0004ea570)
2023-06-17T18:53:04.8468466Z /opt/hostedtoolcache/go/1.19.10/x64/src/os/wait_waitid.go:32 +0x87
2023-06-17T18:53:04.8468749Z os.(*Process).wait(0xc0004ea570)
2023-06-17T18:53:04.8469186Z /opt/hostedtoolcache/go/1.19.10/x64/src/os/exec_unix.go:22 +0x28
2023-06-17T18:53:04.8469465Z os.(*Process).Wait(...)
2023-06-17T18:53:04.8469777Z /opt/hostedtoolcache/go/1.19.10/x64/src/os/exec.go:132
2023-06-17T18:53:04.8470136Z go.etcd.io/etcd/pkg/v3/expect.(*ExpectProcess).waitProcess(0xc0000e8600)
2023-06-17T18:53:04.8470523Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:270 +0x5b
2023-06-17T18:53:04.8470883Z go.etcd.io/etcd/pkg/v3/expect.(*ExpectProcess).waitSaveExitErr(0xc0000e8600)
2023-06-17T18:53:04.8471271Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:142 +0x59
2023-06-17T18:53:04.8471622Z created by go.etcd.io/etcd/pkg/v3/expect.NewExpectWithEnv
2023-06-17T18:53:04.8656733Z goroutine 680504 [syscall, 125 minutes]:
2023-06-17T18:53:04.8657117Z syscall.Syscall6(0xc00014ee40?, 0xc00014eddc?, 0xc00014ef90?, 0x1?, 0xc00014edd8?, 0xc00014ef01?, 0x2?)
2023-06-17T18:53:04.8657568Z /opt/hostedtoolcache/go/1.19.10/x64/src/syscall/syscall_linux.go:90 +0x36
2023-06-17T18:53:04.8657917Z os.(*Process).blockUntilWaitable(0xc000136480)
2023-06-17T18:53:04.8658283Z /opt/hostedtoolcache/go/1.19.10/x64/src/os/wait_waitid.go:32 +0x87
2023-06-17T18:53:04.8658574Z os.(*Process).wait(0xc000136480)
2023-06-17T18:53:04.8658907Z /opt/hostedtoolcache/go/1.19.10/x64/src/os/exec_unix.go:22 +0x28
2023-06-17T18:53:04.8659188Z os.(*Process).Wait(...)
2023-06-17T18:53:04.8659497Z /opt/hostedtoolcache/go/1.19.10/x64/src/os/exec.go:132
2023-06-17T18:53:04.8659865Z go.etcd.io/etcd/pkg/v3/expect.(*ExpectProcess).waitProcess(0xc0005aa0c0)
2023-06-17T18:53:04.8660255Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:270 +0x5b
2023-06-17T18:53:04.8660620Z go.etcd.io/etcd/pkg/v3/expect.(*ExpectProcess).waitSaveExitErr(0xc0005aa0c0)
2023-06-17T18:53:04.8661015Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:142 +0x59
2023-06-17T18:53:04.8661376Z created by go.etcd.io/etcd/pkg/v3/expect.NewExpectWithEnv
2023-06-17T18:53:04.8661753Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:79 +0x285Because the one member is down.
2023-06-17T16:47:32.7945331Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): goroutine 211 [running]:
2023-06-17T16:47:32.7946881Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/gofail/runtime.actPanic(0x0?)
2023-06-17T16:47:32.7948074Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/gofail@v0.1.0/runtime/terms.go:318 +0x69
2023-06-17T16:47:32.7949038Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/gofail/runtime.(*term).do(...)
2023-06-17T16:47:32.7950001Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/gofail@v0.1.0/runtime/terms.go:290
2023-06-17T16:47:32.8040147Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/gofail/runtime.(*terms).eval(0xc00008ad80?)
2023-06-17T16:47:32.8041872Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-0) (30389): {"level":"warn","ts":"2023-06-17T16:47:32.794133Z","caller":"rafthttp/stream.go:421","msg":"lost TCP streaming connection with remote peer","stream-reader-type":"stream Message","local-member-id":"eabdbb777cf498cb","remote-peer-id":"ac4ec652f10e5b49","error":"EOF"}
2023-06-17T16:47:32.8044223Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-0) (30389): {"level":"warn","ts":"2023-06-17T16:47:32.794683Z","caller":"rafthttp/stream.go:421","msg":"lost TCP streaming connection with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"eabdbb777cf498cb","remote-peer-id":"ac4ec652f10e5b49","error":"EOF"}
2023-06-17T16:47:32.8045360Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/gofail@v0.1.0/runtime/terms.go:105 +0xeb
2023-06-17T16:47:32.8046231Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/gofail/runtime.(*Failpoint).Acquire(0xc00022f520?)
2023-06-17T16:47:32.8047198Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/gofail@v0.1.0/runtime/failpoint.go:38 +0xa5
2023-06-17T16:47:32.8048076Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/etcd/server/v3/etcdserver.(*raftNode).start.func1()
2023-06-17T16:47:32.8048958Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/etcd/server/v3/etcdserver/raft.go:238 +0x9b6
2023-06-17T16:47:32.8050297Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): created by go.etcd.io/etcd/server/v3/etcdserver.(*raftNode).start
2023-06-17T16:47:32.8051299Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-1) (30400): go.etcd.io/etcd/server/v3/etcdserver/raft.go:169 +0x7a
2023-06-17T16:47:32.8052733Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-2) (30390): {"level":"warn","ts":"2023-06-17T16:47:32.801145Z","caller":"rafthttp/stream.go:421","msg":"lost TCP streaming connection with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"bf19ae4419db00dc","remote-peer-id":"ac4ec652f10e5b49","error":"EOF"}
2023-06-17T16:47:32.8054480Z /tmp/etcd-release-3.5-failpoints/bin/etcd (TestRobustnessHighTrafficClusterOfSize3-test-2) (30390): {"level":"warn","ts":"2023-06-17T16:47:32.801254Z","caller":"rafthttp/stream.go:421","msg":"lost TCP streaming connection with remote peer","stream-reader-type":"stream Message","local-member-id":"bf19ae4419db00dc","remote-peer-id":"ac4ec652f10e5b49","error":"EOF"}
2023-06-17T16:47:32.8058055Z logger.go:130: 2023-06-17T16:47:32.802Z INFO goFailpoint setup failed {"failpoint": "raftBeforeLeaderSend", "error": "Put \"http://127.0.0.1:22381/raftBeforeLeaderSend\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"}
2023-06-17T16:47:32.8059887Z logger.go:130: 2023-06-17T16:47:32.802Z INFO Setting up gofailpoint {"failpoint": "raftBeforeLeaderSend"}
2023-06-17T16:47:32.8062012Z logger.go:130: 2023-06-17T16:47:32.802Z INFO goFailpoint setup failed {"failpoint": "raftBeforeLeaderSend", "error": "Put \"http://127.0.0.1:22381/raftBeforeLeaderSend\": dial tcp 127.0.0.1:22381: connect: connection refused"}
2023-06-17T16:47:32.8063463Z logger.go:130: 2023-06-17T16:47:32.802Z INFO Setting up gofailpoint {"failpoint": "raftBeforeLeaderSend"}
2023-06-17T16:47:32.8065735Z logger.go:130: 2023-06-17T16:47:32.803Z INFO goFailpoint setup failed {"failpoint": "raftBeforeLeaderSend", "error": "Put \"http://127.0.0.1:22381/raftBeforeLeaderSend\": dial tcp 127.0.0.1:22381: connect: connection refused"}
I think we should enhance the waitProcess
Line 270 in 6f2a5b7
If the waitProcess return unexpected syscall error, we should also update the exitCode.
I download the code and check it. It's weird. We set timeout is 1 minute but it still run two hours, even if we have select <-ctx.Done().
There was a problem hiding this comment.
why gofailpoint setup can fail
I think if it is panic, the server can't return the error in time, like.
2023-06-17T16:47:32.8058055Z logger.go:130: 2023-06-17T16:47:32.802Z INFO goFailpoint setup failed {"failpoint": "raftBeforeLeaderSend", "error": "Put \"http://127.0.0.1:22381/raftBeforeLeaderSend\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"}
There was a problem hiding this comment.
Can you look at this @fuweid ?
There was a problem hiding this comment.
Yes. I reproduced it in my local but the log was flushed in tmux and it lost (truncated) 😢 . Reproducing
There was a problem hiding this comment.
found that issue from expect package and reproduced it in my local. Will file a pr later(OOO currently)
There was a problem hiding this comment.
Can you share what problem you found? It causes problem with working on robustness tests.
There was a problem hiding this comment.
Filed #16134
Can someone look into that?
There was a problem hiding this comment.
Sorry for the late reply. Filed pull request to handle this #16137
jmhbnz
approved these changes
Jun 18, 2023
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Please read https://github.com/etcd-io/etcd/blob/main/CONTRIBUTING.md#contribution-flow.