Etcd panic in robustness tests blackhole failpoint #15595

serathius · 2023-03-30T20:14:41Z

What happened?

Robustness Nightly are failing due to etcd panic.
https://github.com/etcd-io/etcd/actions/runs/4562802681

What did you expect to happen?

Etcd should not panic due to network issues

How can we reproduce it (as minimally and precisely as possible)?

Run robustness tests blackhole tests enough times.
See https://github.com/etcd-io/etcd/actions/workflows/robustness-nightly.yaml

Anything else we need to know?

No response

Etcd version (please run commands below)

N/A

Etcd configuration (command line flags or environment variables)

N/A

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

N/A

Relevant log output

2023-03-30T10:25:27.3144193Z     logger.go:130: 2023-03-30T10:25:26.312Z	INFO	Triggering failpoint
2023-03-30T10:25:27.3144599Z         	{"failpoint": "blackhole"}
2023-03-30T10:25:27.3145371Z     failpoints.go:328: Blackholing traffic from and to member "TestRobustnessClusterOfSize3HighTraffic-test-1"
2023-03-30T10:25:27.3146769Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): {"level":"warn","ts":"2023-03-30T10:25:26.811397Z","caller":"etcdserver/v3_server.go:831","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":11854185818228622438,"retry-timeout":"500ms"}
2023-03-30T10:25:27.3148279Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): {"level":"warn","ts":"2023-03-30T10:25:26.812944Z","caller":"etcdserver/v3_server.go:831","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":14186768950229826371,"retry-timeout":"500ms"}
2023-03-30T10:25:27.3149756Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-1) (28035): {"level":"warn","ts":"2023-03-30T10:25:26.813508Z","caller":"etcdserver/v3_server.go:831","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":6108155643657295548,"retry-timeout":"500ms"}
2023-03-30T10:25:27.3265010Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): {"level":"warn","ts":"2023-03-30T10:25:27.312399Z","caller":"etcdserver/v3_server.go:831","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":11854185818228622438,"retry-timeout":"500ms"}
2023-03-30T10:25:27.3266115Z     failpoints.go:332: Traffic restored from and to member "TestRobustnessClusterOfSize3HighTraffic-test-1"
2023-03-30T10:25:27.3267790Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): {"level":"info","ts":"2023-03-30T10:25:27.314167Z","caller":"traceutil/trace.go:171","msg":"trace[1342822156] linearizableReadLoop","detail":"{readStateIndex:601; appliedIndex:602; }","duration":"1.003816961s","start":"2023-03-30T10:25:26.310341Z","end":"2023-03-30T10:25:27.314158Z","steps":["trace[1342822156] 'read index received'  (duration: 1.003814761s)","trace[1342822156] 'applied index is now lower than readState.Index'  (duration: 1.5µs)"],"step_count":2}
2023-03-30T10:25:27.3269807Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-1) (28035): {"level":"info","ts":"2023-03-30T10:25:27.313778Z","caller":"traceutil/trace.go:171","msg":"trace[1664249991] linearizableReadLoop","detail":"{readStateIndex:601; appliedIndex:602; }","duration":"1.000933919s","start":"2023-03-30T10:25:26.31283Z","end":"2023-03-30T10:25:27.313764Z","steps":["trace[1664249991] 'read index received'  (duration: 1.000931819s)","trace[1664249991] 'applied index is now lower than readState.Index'  (duration: 1.5µs)"],"step_count":2}
2023-03-30T10:25:27.3271798Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): {"level":"info","ts":"2023-03-30T10:25:27.315185Z","caller":"traceutil/trace.go:171","msg":"trace[2074038161] linearizableReadLoop","detail":"{readStateIndex:601; appliedIndex:601; }","duration":"1.002760046s","start":"2023-03-30T10:25:26.312412Z","end":"2023-03-30T10:25:27.315172Z","steps":["trace[2074038161] 'read index received'  (duration: 1.002757745s)","trace[2074038161] 'applied index is now lower than readState.Index'  (duration: 1.601µs)"],"step_count":2}
2023-03-30T10:25:27.3274893Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): {"level":"panic","ts":"2023-03-30T10:25:27.31731Z","logger":"raft","caller":"v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:99","msg":"index, 7, is out of range [1]","stacktrace":"go.etcd.io/raft/v3.(*raftLog).maybeAppend\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:99\ngo.etcd.io/raft/v3.(*raft).handleAppendEntries\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1517\ngo.etcd.io/raft/v3.stepFollower\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1472\ngo.etcd.io/raft/v3.(*raft).Step\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1021\ngo.etcd.io/raft/v3.(*node).run\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:357"}
2023-03-30T10:25:27.3277939Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): {"level":"panic","ts":"2023-03-30T10:25:27.317178Z","logger":"raft","caller":"v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:99","msg":"index, 6, is out of range [1]","stacktrace":"go.etcd.io/raft/v3.(*raftLog).maybeAppend\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:99\ngo.etcd.io/raft/v3.(*raft).handleAppendEntries\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1517\ngo.etcd.io/raft/v3.stepFollower\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1472\ngo.etcd.io/raft/v3.(*raft).Step\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1021\ngo.etcd.io/raft/v3.(*node).run\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:357"}
2023-03-30T10:25:27.3279523Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): panic: index, 7, is out of range [1]
2023-03-30T10:25:27.3280186Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 
2023-03-30T10:25:27.3280872Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): goroutine 138 [running]:
2023-03-30T10:25:27.3281737Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.uber.org/zap/zapcore.CheckWriteAction.OnWrite(0x0?, 0x0?, {0x0?, 0x0?, 0xc0010faee0?})
2023-03-30T10:25:27.3282611Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.uber.org/zap@v1.24.0/zapcore/entry.go:198 +0x65
2023-03-30T10:25:27.3283467Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc0004840d0, {0x0, 0x0, 0x0})
2023-03-30T10:25:27.3284295Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.uber.org/zap@v1.24.0/zapcore/entry.go:264 +0x3ec
2023-03-30T10:25:27.3285253Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.uber.org/zap.(*SugaredLogger).log(0xc0000123a0, 0x4, {0x108f80c?, 0x40dc27?}, {0xc0010fafc0?, 0xeced00?, 0x1?}, {0x0, 0x0, 0x0})
2023-03-30T10:25:27.3286094Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.uber.org/zap@v1.24.0/sugar.go:295 +0xee
2023-03-30T10:25:27.3286869Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.uber.org/zap.(*SugaredLogger).Panicf(...)
2023-03-30T10:25:27.3287622Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.uber.org/zap@v1.24.0/sugar.go:189
2023-03-30T10:25:27.3288638Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.etcd.io/etcd/server/v3/etcdserver.(*zapRaftLogger).Panicf(0xc000460230?, {0x108f80c?, 0x1?}, {0xc0010fafc0?, 0x0?, 0x203000?})
2023-03-30T10:25:27.3289528Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.etcd.io/etcd/server/v3/etcdserver/zap_raft.go:102 +0x49
2023-03-30T10:25:27.3290438Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.etcd.io/raft/v3.(*raftLog).maybeAppend(0xc000460230, 0x259, 0x2, 0x25a, {0xc001ae8c60?, 0x1, 0x1})
2023-03-30T10:25:27.3291677Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:99 +0x190
2023-03-30T10:25:27.3292770Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.etcd.io/raft/v3.(*raft).handleAppendEntries(0xc0004c9b80, {0x3, 0xf2d60a7c86d2c4e1, 0xb078ae59d09754c4, 0x2, 0x2, 0x259, {0xc001ae8c60, 0x1, 0x1}, ...})
2023-03-30T10:25:27.3293723Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1517 +0x77
2023-03-30T10:25:27.3294782Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.etcd.io/raft/v3.stepFollower(0xc0004c9b80, {0x3, 0xf2d60a7c86d2c4e1, 0xb078ae59d09754c4, 0x2, 0x2, 0x259, {0xc001ae8c60, 0x1, 0x1}, ...})
2023-03-30T10:25:27.3295693Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1472 +0x2f8
2023-03-30T10:25:27.3296667Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.etcd.io/raft/v3.(*raft).Step(0xc0004c9b80, {0x3, 0xf2d60a7c86d2c4e1, 0xb078ae59d09754c4, 0x2, 0x2, 0x259, {0xc001ae8c60, 0x1, 0x1}, ...})
2023-03-30T10:25:27.3297577Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1021 +0x1375
2023-03-30T10:25:27.3298364Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): go.etcd.io/raft/v3.(*node).run(0xc000492de0)
2023-03-30T10:25:27.3299191Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:357 +0x98a
2023-03-30T10:25:27.3299952Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): created by go.etcd.io/raft/v3.StartNode
2023-03-30T10:25:27.3300787Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-0) (28026): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:231 +0x65
2023-03-30T10:25:27.3301657Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): panic: index, 6, is out of range [1]
2023-03-30T10:25:27.3302324Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 
2023-03-30T10:25:27.3303003Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): goroutine 152 [running]:
2023-03-30T10:25:27.3303876Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.uber.org/zap/zapcore.CheckWriteAction.OnWrite(0x0?, 0x203000?, {0x0?, 0x0?, 0xc00007c080?})
2023-03-30T10:25:27.3304736Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.uber.org/zap@v1.24.0/zapcore/entry.go:198 +0x65
2023-03-30T10:25:27.3305589Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc00048d380, {0x0, 0x0, 0x0})
2023-03-30T10:25:27.3306489Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.uber.org/zap@v1.24.0/zapcore/entry.go:264 +0x3ec
2023-03-30T10:25:27.3307446Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.uber.org/zap.(*SugaredLogger).log(0xc000486508, 0x4, {0x108f80c?, 0x40dc27?}, {0xc00198f280?, 0xeced00?, 0x1?}, {0x0, 0x0, 0x0})
2023-03-30T10:25:27.3308268Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.uber.org/zap@v1.24.0/sugar.go:295 +0xee
2023-03-30T10:25:27.3309043Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.uber.org/zap.(*SugaredLogger).Panicf(...)
2023-03-30T10:25:27.3309869Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.uber.org/zap@v1.24.0/sugar.go:189
2023-03-30T10:25:27.3310857Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.etcd.io/etcd/server/v3/etcdserver.(*zapRaftLogger).Panicf(0xc00017e4d0?, {0x108f80c?, 0x1?}, {0xc00198f280?, 0x0?, 0x203000?})
2023-03-30T10:25:27.3311754Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.etcd.io/etcd/server/v3/etcdserver/zap_raft.go:102 +0x49
2023-03-30T10:25:27.3312735Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.etcd.io/raft/v3.(*raftLog).maybeAppend(0xc00017e4d0, 0x25a, 0x2, 0x25a, {0xc0019a90e0?, 0x1, 0x1})
2023-03-30T10:25:27.3313619Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:99 +0x190
2023-03-30T10:25:27.3314643Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.etcd.io/raft/v3.(*raft).handleAppendEntries(0xc00056f1e0, {0x3, 0x9b0ed86c9976a482, 0xb078ae59d09754c4, 0x2, 0x2, 0x25a, {0xc0019a90e0, 0x1, 0x1}, ...})
2023-03-30T10:25:27.3315569Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1517 +0x77
2023-03-30T10:25:27.3316553Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.etcd.io/raft/v3.stepFollower(0xc00056f1e0, {0x3, 0x9b0ed86c9976a482, 0xb078ae59d09754c4, 0x2, 0x2, 0x25a, {0xc0019a90e0, 0x1, 0x1}, ...})
2023-03-30T10:25:27.3317464Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1472 +0x2f8
2023-03-30T10:25:27.3318537Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.etcd.io/raft/v3.(*raft).Step(0xc00056f1e0, {0x3, 0x9b0ed86c9976a482, 0xb078ae59d09754c4, 0x2, 0x2, 0x25a, {0xc0019a90e0, 0x1, 0x1}, ...})
2023-03-30T10:25:27.3319435Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1021 +0x1375
2023-03-30T10:25:27.3320224Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): go.etcd.io/raft/v3.(*node).run(0xc00055b380)
2023-03-30T10:25:27.3321052Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:357 +0x98a
2023-03-30T10:25:27.3321837Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): created by go.etcd.io/raft/v3.StartNode
2023-03-30T10:25:27.3322660Z /home/runner/work/etcd/etcd/bin/etcd (TestRobustnessClusterOfSize3HighTraffic-test-2) (28025): 	go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:231 +0x65

serathius · 2023-03-30T20:18:50Z

Looks like an issue with raft

serathius · 2023-03-30T20:21:26Z

cc @tbg @pavelkalinnikov

tbg · 2023-03-31T06:22:39Z

Could be an issue with raft, though I would instead expect it to be some issue with how etcd implements with raft. Hard to know without a further investigation. Let me talk it through with Pavel

serathius · 2023-03-31T09:46:33Z

The issue is pretty hard to reproduce, only once or twice per hundred runs. Please let me know what data you need to confirm where the issue is.

… is fixed

… is fixed Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

tests/robustness: Disable testing network blackhole until #15595 is fixed

pav-kv · 2023-03-31T13:39:23Z

I've investigated this a bit. I can see that this is running on raft @ eaa6808e1f7a.

The panic occurs here, e.g. one I'm looking at reports:

panic: index, 7, is out of range [1]

From the stack trace we're seeing that maybeAppend is called with (index=601, logTerm=2, committed=602, ents=<slice with 1 entry>). Normally, the ents slice should contain entries with contiguous Indexes starting from index+1, in this case we must see ents[0].Index == 602. However, I believe ents[0].Index == 609 here, because the findConflict apparently returned the index of the only entry it has scanned.

We're also seeing that there are two panics happening, at around the same time, with almost matching indexes. Presumably the cluster has a leader and 2 followers. The leader sends a weird MsgApp message to both followers and kills them.

The question is how we get a MsgApp message in which Message.Entries[0].Index != Message.Index + 1. Can it happen that the raftLog.entries function that fetches them returns misplaced entries?

pav-kv · 2023-03-31T13:47:34Z

I think we can add some ad-hoc logging or assertions (both on the sending and receiving end, to localize where it occurs) to confirm that the Message.Entries[0].Index == Message.Index + 1 invariant is broken.

pav-kv · 2023-03-31T14:10:19Z

@serathius I've created a branch in my fork on top of the commit you're running against: https://github.com/pavelkalinnikov/raft/commits/msg-app-invariant. If you could run the test with this commit included (or cherry-picked, whatever works for you), this might help localizing where the issue occurs.

serathius · 2023-03-31T14:15:34Z

@serathius I've created a branch in my fork on top of the commit you're running against: https://github.com/pavelkalinnikov/raft/commits/msg-app-invariant. If you could run the test with this commit included (or cherry-picked, whatever works for you), this might help localizing where the issue occurs.

Awesome! On it.

serathius · 2023-03-31T14:39:59Z

Updated #15600

serathius · 2023-03-31T14:44:27Z

Got it, there are two stacktraces writen at once from two separate members, you can distinguish them by name (TestRobustnessClusterOfSize3LowTraffic-test-2, TestRobustnessClusterOfSize3LowTraffic-test-0) or pid (714482, 714483)

/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-1) (714484): {"level":"warn","ts":"2023-03-31T16:42:20.590682+0200","caller":"etcdserver/v3_server.go:831","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":6108155669721489885,"retry-timeout":"500ms"}
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-1) (714484): {"level":"info","ts":"2023-03-31T16:42:20.59113+0200","caller":"traceutil/trace.go:171","msg":"trace[530800350] linearizableReadLoop","detail":"{readStateIndex:281; appliedIndex:284; }","duration":"1.002163677s","start":"2023-03-31T16:42:19.588942+0200","end":"2023-03-31T16:42:20.591106+0200","steps":["trace[530800350] 'read index received'  (duration: 1.002157415s)","trace[530800350] 'applied index is now lower than readState.Index'  (duration: 5.2µs)"],"step_count":2}
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): {"level":"info","ts":"2023-03-31T16:42:20.59132+0200","caller":"traceutil/trace.go:171","msg":"trace[1978863180] linearizableReadLoop","detail":"{readStateIndex:281; appliedIndex:282; }","duration":"1.020670431s","start":"2023-03-31T16:42:19.570632+0200","end":"2023-03-31T16:42:20.591302+0200","steps":["trace[1978863180] 'read index received'  (duration: 1.020666434s)","trace[1978863180] 'applied index is now lower than readState.Index'  (duration: 2.895µs)"],"step_count":2}
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): {"level":"info","ts":"2023-03-31T16:42:20.591933+0200","caller":"traceutil/trace.go:171","msg":"trace[858852315] linearizableReadLoop","detail":"{readStateIndex:284; appliedIndex:283; }","duration":"1.022533199s","start":"2023-03-31T16:42:19.569387+0200","end":"2023-03-31T16:42:20.59192+0200","steps":["trace[858852315] 'read index received'  (duration: 1.022344014s)","trace[858852315] 'applied index is now lower than readState.Index'  (duration: 188.474µs)"],"step_count":2}
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): {"level":"panic","ts":"2023-03-31T16:42:20.592092+0200","logger":"raft","caller":"v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:90","msg":"entries invariant broken: entry[0].Index is 290, want 285","stacktrace":"go.etcd.io/raft/v3.(*raftLog).maybeAppend\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:90\ngo.etcd.io/raft/v3.(*raft).handleAppendEntries\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1521\ngo.etcd.io/raft/v3.stepFollower\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1476\ngo.etcd.io/raft/v3.(*raft).Step\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1025\ngo.etcd.io/raft/v3.(*node).run\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:357"}
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): {"level":"panic","ts":"2023-03-31T16:42:20.592137+0200","logger":"raft","caller":"v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:90","msg":"entries invariant broken: entry[0].Index is 290, want 285","stacktrace":"go.etcd.io/raft/v3.(*raftLog).maybeAppend\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:90\ngo.etcd.io/raft/v3.(*raft).handleAppendEntries\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1521\ngo.etcd.io/raft/v3.stepFollower\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1476\ngo.etcd.io/raft/v3.(*raft).Step\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1025\ngo.etcd.io/raft/v3.(*node).run\n\tgo.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:357"}
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): panic: entries invariant broken: entry[0].Index is 290, want 285
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): 
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): goroutine 193 [running]:
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): panic: entries invariant broken: entry[0].Index is 290, want 285
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): 
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): goroutine 47 [running]:
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.uber.org/zap/zapcore.CheckWriteAction.OnWrite(0x0?, 0x36?, {0x0?, 0x0?, 0xc00017ca00?})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.uber.org/zap@v1.24.0/zapcore/entry.go:198 +0x65
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.uber.org/zap/zapcore.CheckWriteAction.OnWrite(0x0?, 0x36?, {0x0?, 0x0?, 0xc00033a6e0?})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.uber.org/zap@v1.24.0/zapcore/entry.go:198 +0x65
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc0000c1a00, {0x0, 0x0, 0x0})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.uber.org/zap@v1.24.0/zapcore/entry.go:264 +0x3ec
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc0004ec1a0, {0x0, 0x0, 0x0})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.uber.org/zap@v1.24.0/zapcore/entry.go:264 +0x3ec
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.uber.org/zap.(*SugaredLogger).log(0xc00024c080, 0x4, {0x108b574?, 0x40dc27?}, {0xc0001f86a0?, 0xece6c0?, 0xc000295401?}, {0x0, 0x0, 0x0})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.uber.org/zap@v1.24.0/sugar.go:295 +0xee
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.uber.org/zap.(*SugaredLogger).Panicf(...)
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.uber.org/zap@v1.24.0/sugar.go:189
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.uber.org/zap.(*SugaredLogger).log(0xc00011c318, 0x4, {0x108b574?, 0x40dc27?}, {0xc001a94db0?, 0xece6c0?, 0xc0002de501?}, {0x0, 0x0, 0x0})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.uber.org/zap@v1.24.0/sugar.go:295 +0xee
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.uber.org/zap.(*SugaredLogger).Panicf(...)
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.uber.org/zap@v1.24.0/sugar.go:189
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.etcd.io/etcd/server/v3/etcdserver.(*zapRaftLogger).Panicf(0x10368e0?, {0x108b574?, 0x2?}, {0xc0001f86a0?, 0x0?, 0x7f2caa95c878?})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.etcd.io/etcd/server/v3/etcdserver.(*zapRaftLogger).Panicf(0x0?, {0x108b574?, 0x2?}, {0xc001a94db0?, 0x0?, 0x1d45d40?})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.etcd.io/etcd/server/v3/etcdserver/zap_raft.go:102 +0x49
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.etcd.io/etcd/server/v3/etcdserver/zap_raft.go:102 +0x49
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.etcd.io/raft/v3.(*raftLog).maybeAppend(0xc0004d45b0, 0x11c, 0x2, 0x11c, {0xc001ca5c20?, 0x1, 0x1})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.etcd.io/raft/v3.(*raftLog).maybeAppend(0xc0004e3f10, 0x11c, 0x2, 0x11c, {0xc001a30f30?, 0x1, 0x1})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:90 +0xee
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/log.go:90 +0xee
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.etcd.io/raft/v3.(*raft).handleAppendEntries(0xc000030b00, {0x3, 0xf2d60a7c86d2c4e1, 0xb078ae59d09754c4, 0x2, 0x2, 0x11c, {0xc001ca5c20, 0x1, 0x1}, ...})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.etcd.io/raft/v3.(*raft).handleAppendEntries(0xc0002089a0, {0x3, 0x9b0ed86c9976a482, 0xb078ae59d09754c4, 0x2, 0x2, 0x11c, {0xc001a30f30, 0x1, 0x1}, ...})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1521 +0x77
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1521 +0x77
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.etcd.io/raft/v3.stepFollower(0xc000030b00, {0x3, 0xf2d60a7c86d2c4e1, 0xb078ae59d09754c4, 0x2, 0x2, 0x11c, {0xc001ca5c20, 0x1, 0x1}, ...})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1476 +0x2f8
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.etcd.io/raft/v3.stepFollower(0xc0002089a0, {0x3, 0x9b0ed86c9976a482, 0xb078ae59d09754c4, 0x2, 0x2, 0x11c, {0xc001a30f30, 0x1, 0x1}, ...})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1476 +0x2f8
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.etcd.io/raft/v3.(*raft).Step(0xc0002089a0, {0x3, 0x9b0ed86c9976a482, 0xb078ae59d09754c4, 0x2, 0x2, 0x11c, {0xc001a30f30, 0x1, 0x1}, ...})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.etcd.io/raft/v3.(*raft).Step(0xc000030b00, {0x3, 0xf2d60a7c86d2c4e1, 0xb078ae59d09754c4, 0x2, 0x2, 0x11c, {0xc001ca5c20, 0x1, 0x1}, ...})
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1025 +0x1375
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): go.etcd.io/raft/v3.(*node).run(0xc0006942a0)
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/raft.go:1025 +0x1375
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): go.etcd.io/raft/v3.(*node).run(0xc0006ae840)
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:357 +0x98a
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:357 +0x98a
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483): created by go.etcd.io/raft/v3.StartNode
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482): created by go.etcd.io/raft/v3.StartNode
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-2) (714482):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:231 +0x65
/src/go.etcd.io/etcd/bin/etcd (TestRobustnessClusterOfSize3LowTraffic-test-0) (714483):        go.etcd.io/raft/v3@v3.0.0-20221201111702-eaa6808e1f7a/node.go:231 +0x65

pav-kv · 2023-03-31T15:16:23Z

The strange part is that this fires at the latest stage: on the follower upon receiving MsgApp. I added the assertions to the code that creates the MsgApp message, it is not triggered. So some corruption might be happening while the message is in transit?

pav-kv · 2023-03-31T15:43:31Z

@serathius What does the robustness "blackhole" mode do? Does it fiddle with the messages content, or drop them, or something else?

serathius · 2023-03-31T16:22:28Z

We run proxy before each members peer port and blackhole the traffic.

etcd/pkg/proxy/server.go

Lines 103 to 115 in 6a995d2

    
           // BlackholeTx drops all "outgoing" packets before "forwarding". 
        
           // "BlackholeTx" operation is a wrapper around "ModifyTx" with 
        
           // a function that returns empty bytes. 
        
           BlackholeTx() 
        
           // UnblackholeTx removes blackhole operation on "sending". 
        
           UnblackholeTx() 
        
           // BlackholeRx drops all "incoming" packets to client. 
        
           // "BlackholeRx" operation is a wrapper around "ModifyRx" with 
        
           // a function that returns empty bytes. 
        
           BlackholeRx() 
        
           // UnblackholeRx removes blackhole operation on "receiving". 
        
           UnblackholeRx()

It should just drop data.

pav-kv · 2023-03-31T17:03:13Z

Looking at the implementation here, I see that the modifiers are applied to a byte stream. Is it possible that, as a result of turning this thing on/off, some message is assembled from non-contiguous parts of the byte stream? Say, could this MsgApp message actually be the result of 2 messages truncated and concatenated in a weird way? Protobuf is pretty flexible w.r.t. duplicate tags etc, so in theory a "valid" message could be created this way.

pav-kv · 2023-03-31T17:04:36Z

@serathius Also, is it possible that this stream drops only a part of the message (which represents a prefix of Entries), so that the message gets assembled from partial bytes?

pav-kv · 2023-03-31T17:25:17Z

The problem with such an application-level "dropping" is that it doesn't look like a stream corruption from the TCP point of view. The stream is tampered with, but to the TCP receiver this is still a valid stream, so it just feeds a modified stream to the application layer. All sorts of application-level corruption can happen this way.

The real TCP-level packet loss would have been spotted by the receiver, and it wouldn't be able to proceed from the middle of the stream when it recovers.

UPD: It might be HTTP that gRPC relies on, not necessarily directly TCP (not sure what the actual stack is). The proxy that you linked tampers with the stream above HTTP, right? And this gets retransmitted over HTTP, and fed into gRPC at the receiver end.

serathius · 2023-04-01T10:17:13Z

I think you might be right, I have tested peer communication with TLS and I'm unable to reproduce. Need to investigatehow the proxy manages to execute man in the middle attack (I don't provide certs to it).

As for proxy layer, it looks like L4 proxy (TCP) and not L7 (http, grpc). However one thing I noticed that packates buffered and code that drops traffic runs on bytes and not whole packets, which means they could be split in the middle. That would be the incorrect behavior you mentioned that results in non-natural network failure.

serathius · 2023-04-01T13:37:04Z

Hmm, ~~buffer used in proxy has 48KiB and not 64KiB as is the maximum TCP packet size. Maybe that's cause of packets being cut.~~ I'm looking for alternative way to implement proxy to compare. If time permits, I would like to confirm that this bug is really caused by packet being cut in half.
cc @aojea

…d-io#15595 is fixed" This reverts commit 013e25f. Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

serathius · 2023-04-03T10:21:04Z

Closing based on fact that TLS fixes the issue. Replacing pkg/proxy with proper network failure simulator should be tracked in separate issue.

Based on Fu Wei's idea, we employ blocking on L7 but without using external tools. The main idea is to read out `X-PeerURLs` from the header, since this is how peer traffic identifies itself to others. As we also know that all node will create direct connections with its peers, so the traffic blocking will actually happen at all nodes' proxy (contrary to the current design, where only the proxy of the peer that's being blackholed. However, this way of blocking (by `X-PeerURLs` from the header) will miss certain types of traffic to certain endpoints, e.g. /members, /version, and /raft/probing. See below for the log extract, as it's header doesn't contain X-PeerURLs information. - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /members - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /version - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /raft/probing In order to read out `X-PeerURLs` from the header, we need to terminate the SSL connection, as we can't drop cleartext traffic (ref [1]). Thus, a new option `e2e.WithSSLTerminationProxy(true)` is introduced, which will change the network flow into A -- B's SSL termination proxy - B's transparent proxy - B ^ newly introduced ^ in the original codebase This prototype doesn't address - blocking only RX or TX traffic - slowness when performing test cleanup , and the coding convention needs to be improved as it's still a PoC References: [1] etcd-io#15595

Based on Fu Wei's idea, we employ blocking on L7 but without using external tools. The main idea is to read out `X-PeerURLs` from the header, since this is how peer traffic identifies itself to others. As we also know that all nodes will create direct connections with their peers, so the traffic blocking will actually happen at all nodes' proxies (contrary to the current design, where only the proxy of the peer is being blackholed. However, this way of blocking (by `X-PeerURLs` from the header) will miss certain types of traffic to certain endpoints, e.g. /members, /version, and /raft/probing. See below for the log extract, as its header doesn't contain X-PeerURLs information. - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /members - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /version - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /raft/probing In order to read out `X-PeerURLs` from the header, we need to terminate the SSL connection, as we can't drop cleartext traffic (ref [1]). Thus, a new option `e2e.WithSSLTerminationProxy(true)` is introduced, which will change the network flow into ``` A -- B's SSL termination proxy - B's transparent proxy - B ^ newly introduced ^ in the original codebase ``` This prototype doesn't address - blocking only RX or TX traffic - slowness when performing test cleanup , and the coding convention needs to be improved as it's still a PoC References: [1] etcd-io#15595

Based on Fu Wei's idea, we employ blocking on L7 but without using external tools. [Main ideas] The main idea is 1) utilize the `X-PeerURLs` field from the header, as we know all traffic to peer will contain this header field. 2) As we also know that all nodes will create direct connections with their peers, so the traffic blocking will have to happen at all nodes' proxies, contrary to the current design, where only the proxy of the peer is being blackholed. Based on the main ideas, we introduce a SSL termination proxy so we can obtain the `X-PeerURLs` field from the header. [Issues] There are 2 known issues with this approach 1) still leaking some traffic. But the leaked traffic (as discussed later won't affect the blackhole idea that we would like to achieve (as stream and pipeline traffic between raft nodes are now properly terminated) 2) we would need to employ SSL termination proxy, which might lead to a small performance hit For 1), as this way of blocking (by utilizing `X-PeerURLs` from the header) will miss certain types of traffic to certain endpoints, as the traffic to some endpoints doesn't have the `X-PeerURLs` field. Currently, here are the known ones: /members, /version, and /raft/probing. As you can see from the log, its header doesn't contain the `X-PeerURLs` field, but only the following fields: - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /members - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /version - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /raft/probing For 2) in order to read out `X-PeerURLs` from the header, we need to terminate the SSL connection, as we can't drop cleartext traffic (ref [1]). Thus, a new option `e2e.WithSSLTerminationProxy(true)` is introduced, which will change the network flow into ``` A -- B's SSL termination proxy - B's transparent proxy - B ^ newly introduced ^ in the original codebase ``` [Known improvements required before turning RFC into PR] The prototype needs to be further improved for code review after fixing the following issues: - blocking only RX or TX traffic (as currently a call to `blackholeTX` or `blackholeRX` will black both TX and RX traffic instead of just the specified one. - slowness when performing test cleanup (I think this is related to the SSL timeout setting, but I haven't looked into it yet) - coding style improvements References: [1] etcd-io#15595

Based on Fu Wei's idea, we employ blocking on L7 but without using external tools. [Main ideas] The main idea is 1) utilize the `X-PeerURLs` field from the header, as we know all traffic to peer will contain this header field. 2) As we also know that all nodes will create direct connections with their peers, so the traffic blocking will have to happen at all nodes' proxies, contrary to the current design, where only the proxy of the peer is being blackholed. Based on the main ideas, we introduce a SSL termination proxy so we can obtain the `X-PeerURLs` field from the header. [Issues] There are 2 known issues with this approach 1) still leaking some traffic. But the leaked traffic (as discussed later won't affect the blackhole idea that we would like to achieve (as stream and pipeline traffic between raft nodes are now properly terminated) 2) we would need to employ SSL termination proxy, which might lead to a small performance hit For 1), as this way of blocking (by utilizing `X-PeerURLs` from the header) will miss certain types of traffic to certain endpoints, as the traffic to some endpoints doesn't have the `X-PeerURLs` field. Currently, here are the known ones: /members, /version, and /raft/probing. As you can see from the log, its header doesn't contain the `X-PeerURLs` field, but only the following fields: - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /members - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /version - map[Accept-Encoding:[gzip] User-Agent:[Go-http-client/1.1]] /raft/probing For 2) in order to read out `X-PeerURLs` from the header, we need to terminate the SSL connection, as we can't drop cleartext traffic (ref [1]). Thus, a new option `e2e.WithSSLTerminationProxy(true)` is introduced, which will change the network flow into ``` A -- B's SSL termination proxy - B's transparent proxy - B ^ newly introduced ^ in the original codebase ``` [Known improvements required before turning RFC into PR] The prototype needs to be further improved for code review after fixing the following issues: - blocking only RX or TX traffic (as currently a call to `blackholeTX` or `blackholeRX` will black both TX and RX traffic instead of just the specified one. - slowness when performing test cleanup (I think this is related to the SSL timeout setting, but I haven't looked into it yet) - coding style improvements References: [1] etcd-io#15595 Signed-off-by: Chun-Hung Tseng <henrybear327@gmail.com>

serathius added the type/bug label Mar 30, 2023

serathius mentioned this issue Mar 30, 2023

Ensure healthy cluster after robustness failpoint #15596

Closed

serathius mentioned this issue Mar 31, 2023

tests: Reproduce 15595 #15600

Closed

serathius added a commit to serathius/etcd that referenced this issue Mar 31, 2023

tests/robustness: Disable testing network blackhole until etcd-io#15595…

77f7cbc

… is fixed

serathius added a commit to serathius/etcd that referenced this issue Mar 31, 2023

tests/robustness: Disable testing network blackhole until etcd-io#15595…

223b804

… is fixed Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

serathius added a commit to serathius/etcd that referenced this issue Mar 31, 2023

tests/robustness: Disable testing network blackhole until etcd-io#15595…

2465f9f

… is fixed Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

serathius added a commit to serathius/etcd that referenced this issue Mar 31, 2023

tests/robustness: Disable testing network blackhole until etcd-io#15595…

39820cd

… is fixed Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

serathius added a commit to serathius/etcd that referenced this issue Mar 31, 2023

tests/robustness: Disable testing network blackhole until etcd-io#15595…

013e25f

… is fixed Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

serathius added a commit that referenced this issue Mar 31, 2023

Merge pull request #15601 from serathius/robustness-disable-blackhole

4529f01

tests/robustness: Disable testing network blackhole until #15595 is fixed

serathius added the priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. label Mar 31, 2023

serathius pinned this issue Mar 31, 2023

serathius removed the priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. label Apr 1, 2023

serathius unpinned this issue Apr 1, 2023

serathius added a commit to serathius/etcd that referenced this issue Apr 1, 2023

Revert "tests/robustness: Disable testing network blackhole until etc…

479d9a7

…d-io#15595 is fixed" This reverts commit 013e25f. Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

serathius added a commit to serathius/etcd that referenced this issue Apr 1, 2023

Revert "tests/robustness: Disable testing network blackhole until etc…

03214c0

…d-io#15595 is fixed" This reverts commit 013e25f. Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

serathius added a commit to serathius/etcd that referenced this issue Apr 1, 2023

Revert "tests/robustness: Disable testing network blackhole until etc…

2d9e35b

…d-io#15595 is fixed" This reverts commit 013e25f. Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>

ahrtr mentioned this issue Apr 2, 2023

Robustness fix blackhole #15610

Merged

serathius closed this as completed Apr 3, 2023

serathius mentioned this issue Apr 3, 2023

tests: Ensure healthy cluster before and after robustness failpoint #15604

Merged

This was referenced Apr 13, 2023

Etcd should be resiliant to packet manipulation #15704

Open

raft: use a type-safe slice of log entries etcd-io/raft#46

Closed

ahrtr mentioned this issue Apr 14, 2023

Nominate @tjungblu @cenkalti and @pavelkalinnikov as members #15714

Closed

henrybear327 mentioned this issue Apr 23, 2024

Attempt to make Blockhole blocking on L7 henrybear327/etcd#4

Closed

henrybear327 mentioned this issue Apr 28, 2024

[RFC] Attempt to make Blockhole blocking on L7 #17891

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Etcd panic in robustness tests blackhole failpoint #15595

Etcd panic in robustness tests blackhole failpoint #15595

serathius commented Mar 30, 2023 •

edited

Loading

serathius commented Mar 30, 2023

serathius commented Mar 30, 2023

tbg commented Mar 31, 2023

serathius commented Mar 31, 2023

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023 •

edited

Loading

serathius commented Mar 31, 2023 •

edited

Loading

serathius commented Mar 31, 2023

serathius commented Mar 31, 2023 •

edited

Loading

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023

serathius commented Mar 31, 2023 •

edited

Loading

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023 •

edited

Loading

serathius commented Apr 1, 2023

serathius commented Apr 1, 2023 •

edited

Loading

serathius commented Apr 3, 2023

Etcd panic in robustness tests blackhole failpoint #15595

Etcd panic in robustness tests blackhole failpoint #15595

Comments

serathius commented Mar 30, 2023 • edited Loading

What happened?

What did you expect to happen?

How can we reproduce it (as minimally and precisely as possible)?

Anything else we need to know?

Etcd version (please run commands below)

Etcd configuration (command line flags or environment variables)

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

Relevant log output

serathius commented Mar 30, 2023

serathius commented Mar 30, 2023

tbg commented Mar 31, 2023

serathius commented Mar 31, 2023

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023 • edited Loading

serathius commented Mar 31, 2023 • edited Loading

serathius commented Mar 31, 2023

serathius commented Mar 31, 2023 • edited Loading

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023

serathius commented Mar 31, 2023 • edited Loading

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023

pav-kv commented Mar 31, 2023 • edited Loading

serathius commented Apr 1, 2023

serathius commented Apr 1, 2023 • edited Loading

serathius commented Apr 3, 2023

serathius commented Mar 30, 2023 •

edited

Loading

pav-kv commented Mar 31, 2023 •

edited

Loading

serathius commented Mar 31, 2023 •

edited

Loading

serathius commented Mar 31, 2023 •

edited

Loading

serathius commented Mar 31, 2023 •

edited

Loading

pav-kv commented Mar 31, 2023 •

edited

Loading

serathius commented Apr 1, 2023 •

edited

Loading