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 1 commit
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
Prev Previous commit
Next Next commit
chore: Clean up logging
  • Loading branch information
@mafredri
mafredri committed Dec 7, 2022
commit 05b527b9fe7b2f7c2cc73ac78783c579cfaa86dc
41 changes: 16 additions & 25 deletions pty/ptytest/ptytest.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -90,15 +82,15 @@ 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:
}

logClose("logw", logw)
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:
}

Expand All @@ -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)
Expand Down Expand Up @@ -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...)
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