From 07322d86a7d3331d52c03b5a72e3b3d35320add5 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Wed, 7 Dec 2022 14:28:17 +0000 Subject: [PATCH 1/3] fix: Improve ptytest closure on expect match timeout To ensure ptytest closure always happens the same way, we now define a new `Close` function on `PTY` and always call the close function instead of manually closing read/writers. A few additional log messages have been added as well, to better understand the shutdown process in case of errors. --- pty/ptytest/ptytest.go | 89 ++++++++++++++++++++++++------------------ 1 file changed, 51 insertions(+), 38 deletions(-) diff --git a/pty/ptytest/ptytest.go b/pty/ptytest/ptytest.go index 1bca67fe71178..50cd598c10416 100644 --- a/pty/ptytest/ptytest.go +++ b/pty/ptytest/ptytest.go @@ -46,24 +46,6 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY { // Use pipe for logging. logDone := make(chan struct{}) logr, logw := io.Pipe() - t.Cleanup(func() { - ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) - defer cancel() - - logf(t, name, "close logw on cleanup") - _ = logw.Close() - - logf(t, name, "close logr on cleanup") - _ = logr.Close() - - logf(t, name, "logr and logw closed") - - select { - case <-ctx.Done(): - fatalf(t, name, "cleanup", "log pipe did not close in time") - case <-logDone: // Guard against logging after test. - } - }) // Write to log and output buffer. copyDone := make(chan struct{}) @@ -72,36 +54,60 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY { go func() { defer close(copyDone) _, err := io.Copy(w, ptty.Output()) - _ = out.closeErr(err) + logf(t, name, "copy done: %v", err) + logf(t, name, "closing out") + err = out.closeErr(err) + logf(t, name, "closed out: %v", err) }() + + tpty := &PTY{ + t: t, + PTY: ptty, + out: out, + name: name, + + runeReader: bufio.NewReaderSize(out, utf8.UTFMax), + } + // Ensure pty is cleaned up at the end of test. t.Cleanup(func() { - ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + _ = tpty.Close() + }) + + logClose := func(name string, c io.Closer) { + tpty.logf("closing %s", name) + err := c.Close() + tpty.logf("closed %s: %v", name, err) + } + // Set the actual close function for the tpty. + tpty.close = func(reason string) error { + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitMedium) defer cancel() + tpty.logf("closing tpty: %s", reason) + // Close pty only so that the copy goroutine can consume the // remainder of it's buffer and then exit. - logf(t, name, "close pty on cleanup") - err := ptty.Close() - // Pty may already be closed, so don't fail the test, but log - // the error in case it's significant. - logf(t, name, "closed pty: %v", err) - + logClose("pty", ptty) select { case <-ctx.Done(): - fatalf(t, name, "cleanup", "copy did not close in time") + fatalf(t, name, "close", "copy did not close in time") case <-copyDone: } - }) - tpty := &PTY{ - t: t, - PTY: ptty, - out: out, - name: name, + logClose("logw", logw) + logClose("logr", logr) + select { + case <-ctx.Done(): + fatalf(t, name, "close", "log pipe did not close in time") + case <-logDone: + } - runeReader: bufio.NewReaderSize(out, utf8.UTFMax), + tpty.logf("closed tpty") + + return nil } + // Log all output as part of test for easier debugging on errors. go func() { defer close(logDone) s := bufio.NewScanner(logr) @@ -116,13 +122,20 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY { type PTY struct { pty.PTY - t *testing.T - out *stdbuf - name string + t *testing.T + close func(reason string) error + out *stdbuf + name string runeReader *bufio.Reader } +func (p *PTY) Close() error { + p.t.Helper() + + return p.close("close") +} + func (p *PTY) ExpectMatch(str string) string { p.t.Helper() @@ -160,7 +173,7 @@ func (p *PTY) ExpectMatch(str string) string { return buffer.String() case <-timeout.Done(): // Ensure goroutine is cleaned up before test exit. - _ = p.out.closeErr(p.Close()) + _ = p.close("expect match timeout") <-match p.fatalf("match exceeded deadline", "wanted %q; got %q", str, buffer.String()) From 05b527b9fe7b2f7c2cc73ac78783c579cfaa86dc Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Wed, 7 Dec 2022 14:37:46 +0000 Subject: [PATCH 2/3] chore: Clean up logging --- pty/ptytest/ptytest.go | 41 ++++++++++++++++------------------------- 1 file changed, 16 insertions(+), 25 deletions(-) diff --git a/pty/ptytest/ptytest.go b/pty/ptytest/ptytest.go index 50cd598c10416..28e5816116723 100644 --- a/pty/ptytest/ptytest.go +++ b/pty/ptytest/ptytest.go @@ -51,14 +51,6 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY { copyDone := make(chan struct{}) out := newStdbuf() w := io.MultiWriter(logw, out) - go func() { - defer close(copyDone) - _, err := io.Copy(w, ptty.Output()) - logf(t, name, "copy done: %v", err) - logf(t, name, "closing out") - err = out.closeErr(err) - logf(t, name, "closed out: %v", err) - }() tpty := &PTY{ t: t, @@ -90,7 +82,7 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY { logClose("pty", ptty) select { case <-ctx.Done(): - fatalf(t, name, "close", "copy did not close in time") + tpty.fatalf("close", "copy did not close in time") case <-copyDone: } @@ -98,7 +90,7 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY { logClose("logr", logr) select { case <-ctx.Done(): - fatalf(t, name, "close", "log pipe did not close in time") + tpty.fatalf("close", "log pipe did not close in time") case <-logDone: } @@ -107,6 +99,15 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY { return nil } + go func() { + defer close(copyDone) + _, err := io.Copy(w, ptty.Output()) + tpty.logf("copy done: %v", err) + tpty.logf("closing out") + err = out.closeErr(err) + tpty.logf("closed out: %v", err) + }() + // Log all output as part of test for easier debugging on errors. go func() { defer close(logDone) @@ -203,30 +204,20 @@ func (p *PTY) WriteLine(str string) { func (p *PTY) logf(format string, args ...interface{}) { p.t.Helper() - logf(p.t, p.name, format, args...) -} - -func (p *PTY) fatalf(reason string, format string, args ...interface{}) { - p.t.Helper() - fatalf(p.t, p.name, reason, format, args...) -} - -func logf(t *testing.T, name, format string, args ...interface{}) { - t.Helper() // Match regular logger timestamp format, we seem to be logging in // UTC in other places as well, so match here. - t.Logf("%s: %s: %s", time.Now().UTC().Format("2006-01-02 15:04:05.000"), name, fmt.Sprintf(format, args...)) + p.t.Logf("%s: %s: %s", time.Now().UTC().Format("2006-01-02 15:04:05.000"), p.name, fmt.Sprintf(format, args...)) } -func fatalf(t *testing.T, name, reason, format string, args ...interface{}) { - t.Helper() +func (p *PTY) fatalf(reason string, format string, args ...interface{}) { + p.t.Helper() // Ensure the message is part of the normal log stream before // failing the test. - logf(t, name, "%s: %s", reason, fmt.Sprintf(format, args...)) + p.logf("%s: %s", reason, fmt.Sprintf(format, args...)) - require.FailNowf(t, reason, format, args...) + require.FailNowf(p.t, reason, format, args...) } // stdbuf is like a buffered stdout, it buffers writes until read. From dda5b2d8d4dd7f2ed40ce113acb54608d26edf80 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Wed, 7 Dec 2022 14:43:42 +0000 Subject: [PATCH 3/3] Use WaitShort --- pty/ptytest/ptytest.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pty/ptytest/ptytest.go b/pty/ptytest/ptytest.go index 28e5816116723..9ce0f5bb7c0f6 100644 --- a/pty/ptytest/ptytest.go +++ b/pty/ptytest/ptytest.go @@ -72,7 +72,7 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY { } // Set the actual close function for the tpty. tpty.close = func(reason string) error { - ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitMedium) + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) defer cancel() tpty.logf("closing tpty: %s", reason)