Retain process logs on robustness tests

Adding a set of functions which retain e2e etcd process logs after stop and
saving next to the visualized model during robustness tests.

Spun out of #16018 where I used it for easier local debugging on model
violations. Fixes #15079 partially.

Signed-off-by: Thomas Jungblut <tjungblu@redhat.com>

tests/framework/e2e/cluster_proxy.go

@@ -112,6 +112,14 @@ func (p *proxyEtcdProcess) Logs() LogsExpect {
 	return p.etcdProc.Logs()
 }
 
+func (p *proxyEtcdProcess) Lines() []string {
+	return p.etcdProc.Logs().Lines()
+}
+
+func (p *proxyEtcdProcess) LineCount() int {
+	return p.etcdProc.Logs().LineCount()
+}
+
 func (p *proxyEtcdProcess) Kill() error {
 	return p.etcdProc.Kill()
 }

tests/framework/e2e/etcd_process.go

@@ -40,8 +40,14 @@ var (
 	EtcdServerReadyLines = []string{"ready to serve client requests"}
 )
 
+type LogLines interface {
+	Lines() []string
+	LineCount() int
+}
+
 // EtcdProcess is a process that serves etcd requests.
 type EtcdProcess interface {
+	LogLines
 	EndpointsGRPC() []string
 	EndpointsHTTP() []string
 	EndpointsMetrics() []string
@@ -61,9 +67,8 @@ type EtcdProcess interface {
 }
 
 type LogsExpect interface {
+	LogLines
 	ExpectWithContext(context.Context, string) (string, error)
-	Lines() []string
-	LineCount() int
 }
 
 type EtcdServerProcess struct {
@@ -72,6 +77,7 @@ type EtcdServerProcess struct {
 	proxy      proxy.Server
 	failpoints *BinaryFailpoints
 	donec      chan struct{} // closed when Interact() terminates
+	logs       *procLogs
 }
 
 type EtcdServerProcessConfig struct {
@@ -108,7 +114,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: &procLogs{}}
 	if cfg.GoFailPort != 0 {
 		ep.failpoints = &BinaryFailpoints{member: ep}
 	}
@@ -124,8 +130,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 +183,7 @@ func (ep *EtcdServerProcess) Stop() (err error) {
 		return nil
 	}
 	defer func() {
+		ep.logs.append(ep.proc.Lines())
 		ep.proc = nil
 	}()
 
@@ -235,6 +242,14 @@ func (ep *EtcdServerProcess) Logs() LogsExpect {
 	return ep.proc
 }
 
+func (ep *EtcdServerProcess) Lines() []string {
+	return ep.logs.Lines()
+}
+
+func (ep *EtcdServerProcess) LineCount() int {
+	return ep.logs.LineCount()
+}
+
 func (ep *EtcdServerProcess) Kill() error {
 	ep.cfg.lg.Info("killing server...", zap.String("name", ep.cfg.Name))
 	return ep.proc.Signal(syscall.SIGKILL)
@@ -378,3 +393,20 @@ 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 procLogs struct {
+	procLogs []string
+}
+
+func (m *procLogs) append(lines []string) {
+	m.procLogs = append(m.procLogs, strings.Repeat("=", 50)+"\n")
+	m.procLogs = append(m.procLogs, lines...)
+}
+
+func (m *procLogs) Lines() []string {
+	return m.procLogs
+}
+
+func (m *procLogs) LineCount() int {
+	return len(m.procLogs)
+}

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.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)

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")
 	}