From ab50d8084bf2e58a4a4fada6f70b4e3b67fd397c Mon Sep 17 00:00:00 2001 From: Thomas Jungblut Date: Wed, 14 Jun 2023 16:07:12 +0200 Subject: [PATCH] Retain process logs on robustness tests Adding a new flag to retain e2e etcd process logs after stop and saving next to the visualized model. Spun out of etcd-io#16018 where I used it for easier local debugging on model violations. Fixes #15079 partially. Signed-off-by: Thomas Jungblut --- tests/framework/e2e/etcd_process.go | 48 ++++++++++++++++++++++--- tests/robustness/report.go | 11 ++++++ tests/robustness/validate/operations.go | 4 ++- 3 files changed, 58 insertions(+), 5 deletions(-) diff --git a/tests/framework/e2e/etcd_process.go b/tests/framework/e2e/etcd_process.go index 38934f861b69..86a0d975f756 100644 --- a/tests/framework/e2e/etcd_process.go +++ b/tests/framework/e2e/etcd_process.go @@ -72,6 +72,7 @@ type EtcdServerProcess struct { proxy proxy.Server failpoints *BinaryFailpoints donec chan struct{} // closed when Interact() terminates + logs *multiLogsExpect } type EtcdServerProcessConfig struct { @@ -108,7 +109,7 @@ func NewEtcdServerProcess(cfg *EtcdServerProcessConfig) (*EtcdServerProcess, err return nil, err } } - ep := &EtcdServerProcess{cfg: cfg, donec: make(chan struct{})} + ep := &EtcdServerProcess{cfg: cfg, donec: make(chan struct{}), logs: &multiLogsExpect{}} if cfg.GoFailPort != 0 { ep.failpoints = &BinaryFailpoints{member: ep} } @@ -124,8 +125,8 @@ func (ep *EtcdServerProcess) EndpointsHTTP() []string { } func (ep *EtcdServerProcess) EndpointsMetrics() []string { return []string{ep.cfg.MetricsURL} } -func (epc *EtcdServerProcess) Etcdctl(opts ...config.ClientOption) *EtcdctlV3 { - etcdctl, err := NewEtcdctl(epc.Config().Client, epc.EndpointsGRPC(), opts...) +func (ep *EtcdServerProcess) Etcdctl(opts ...config.ClientOption) *EtcdctlV3 { + etcdctl, err := NewEtcdctl(ep.Config().Client, ep.EndpointsGRPC(), opts...) if err != nil { panic(err) } @@ -177,6 +178,8 @@ func (ep *EtcdServerProcess) Stop() (err error) { return nil } defer func() { + // retain the logs part of the process for later expects + ep.logs.procLogs = append(ep.logs.procLogs, ep.proc) ep.proc = nil }() @@ -230,7 +233,7 @@ func (ep *EtcdServerProcess) Config() *EtcdServerProcessConfig { return ep.cfg } func (ep *EtcdServerProcess) Logs() LogsExpect { if ep.proc == nil { - ep.cfg.lg.Panic("Please grab logs before process is stopped") + return ep.logs } return ep.proc } @@ -378,3 +381,40 @@ func GetVersionFromBinary(binaryPath string) (*semver.Version, error) { return nil, fmt.Errorf("could not find version in binary output of %s, lines outputted were %v", binaryPath, lines) } + +type multiLogsExpect struct { + procLogs []LogsExpect +} + +func (m *multiLogsExpect) ExpectWithContext(ctx context.Context, s string) (string, error) { + var lastErr error + for _, log := range m.procLogs { + r, err := log.ExpectWithContext(ctx, s) + if err != nil { + lastErr = err + continue + } + + return r, nil + } + + return "", lastErr +} + +func (m *multiLogsExpect) Lines() []string { + var logLines []string + for _, log := range m.procLogs { + // visually separate the different process invocations + logLines = append(logLines, strings.Repeat("=", 50)+"\n") + logLines = append(logLines, log.Lines()...) + } + return logLines +} + +func (m *multiLogsExpect) LineCount() int { + var count int + for _, log := range m.procLogs { + count += log.LineCount() + } + return count +} diff --git a/tests/robustness/report.go b/tests/robustness/report.go index 4e995acbdb07..26421a031a8e 100644 --- a/tests/robustness/report.go +++ b/tests/robustness/report.go @@ -67,6 +67,9 @@ func (r *report) Report(t *testing.T, force bool) { for _, member := range r.clus.Procs { memberDataDir := filepath.Join(path, fmt.Sprintf("server-%s", member.Config().Name)) persistMemberDataDir(t, r.lg, member, memberDataDir) + + logsFile := filepath.Join(path, fmt.Sprintf("server-%s.log", member.Config().Name)) + persistMemberLogs(t, r.lg, member, logsFile) } if r.clientReports != nil { sort.Slice(r.clientReports, func(i, j int) bool { @@ -118,6 +121,14 @@ func persistWatchResponses(t *testing.T, lg *zap.Logger, path string, responses } } +func persistMemberLogs(t *testing.T, lg *zap.Logger, member e2e.EtcdProcess, path string) { + lg.Info("Saving member logs dir", zap.String("member", member.Config().Name), zap.String("path", path)) + err := os.WriteFile(path, []byte(strings.Join(member.Logs().Lines(), "")), 0644) + if err != nil { + t.Fatal(err) + } +} + func persistWatchEvents(t *testing.T, lg *zap.Logger, path string, events []traffic.TimedWatchEvent) { lg.Info("Saving watch events", zap.String("path", path)) file, err := os.OpenFile(path, os.O_RDWR|os.O_CREATE|os.O_TRUNC, 0755) diff --git a/tests/robustness/validate/operations.go b/tests/robustness/validate/operations.go index 9189af12675a..2fce39a8196a 100644 --- a/tests/robustness/validate/operations.go +++ b/tests/robustness/validate/operations.go @@ -25,7 +25,9 @@ import ( ) func validateOperationHistoryAndReturnVisualize(t *testing.T, lg *zap.Logger, operations []porcupine.Operation) (visualize func(basepath string)) { - linearizable, info := porcupine.CheckOperationsVerbose(model.NonDeterministicModel, operations, 5*time.Minute) + const timeout = 5 * time.Minute + lg.Info("Running porcupine to check operations", zap.String("model", "NonDeterministicModel"), zap.Duration("timeout", timeout)) + linearizable, info := porcupine.CheckOperationsVerbose(model.NonDeterministicModel, operations, timeout) if linearizable == porcupine.Illegal { t.Error("Model is not linearizable") }