Skip to content

fix: Improve ptytest closure on expect match timeout #5337

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Dec 7, 2022
Merged

fix: Improve ptytest closure on expect match timeout #5337

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
07322d8
fix: Improve ptytest closure on expect match timeout
mafredri Dec 7, 2022
05b527b
chore: Clean up logging
mafredri Dec 7, 2022
dda5b2d
Use WaitShort
mafredri Dec 7, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
116 changes: 60 additions & 56 deletions pty/ptytest/ptytest.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,62 +46,69 @@ 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{})
out := newStdbuf()
w := io.MultiWriter(logw, out)
go func() {
defer close(copyDone)
_, err := io.Copy(w, ptty.Output())
_ = out.closeErr(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() {
_ = 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 {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort)
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")
tpty.fatalf("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():
tpty.fatalf("close", "log pipe did not close in time")
case <-logDone:
}

runeReader: bufio.NewReaderSize(out, utf8.UTFMax),
tpty.logf("closed tpty")

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)
s := bufio.NewScanner(logr)
Expand All @@ -116,13 +123,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()

Expand Down Expand Up @@ -160,7 +174,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())
Expand Down Expand Up @@ -190,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...)
Comment on lines +218 to +220
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm curious, is there a reason why these 2 lists are not merged into one call, require.FailNowf?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because require output differs from the common ptytest logs, this may duplicate the information but it gives an easier trail to follow.

}

// stdbuf is like a buffered stdout, it buffers writes until read.
Expand Down