From b7ef57b57a2b3f36de619412958112e940fd49f7 Mon Sep 17 00:00:00 2001 From: Ben Hoyt Date: Sun, 22 May 2022 21:10:49 +1200 Subject: [PATCH 1/5] First make test (correctly) fail to show the issue --- interp/newexecute_test.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/interp/newexecute_test.go b/interp/newexecute_test.go index 7c74e592..cfb14f47 100644 --- a/interp/newexecute_test.go +++ b/interp/newexecute_test.go @@ -139,6 +139,7 @@ func TestExecuteContextCancel(t *testing.T) { } func TestExecuteContextSystemTimeout(t *testing.T) { + started := time.Now() interpreter := newInterp(t, `BEGIN { print system("sleep 4") }`) ctx, cancel := context.WithTimeout(context.Background(), 5*time.Millisecond) defer cancel() @@ -146,6 +147,10 @@ func TestExecuteContextSystemTimeout(t *testing.T) { if !errors.Is(err, context.DeadlineExceeded) { t.Fatalf("expected DeadlineExceeded error, got: %v", err) } + elapsed := time.Since(started) + if elapsed > time.Second { + t.Fatalf("should have taken ~5ms, took %v", elapsed) + } } func newInterp(t *testing.T, src string) *interp.Interpreter { From 7dbf903aae05c7ad273ec524b68cd2001c6b7210 Mon Sep 17 00:00:00 2001 From: Ben Hoyt Date: Tue, 24 May 2022 15:32:57 +1200 Subject: [PATCH 2/5] Reduce test fail time from 4s to 1s --- interp/newexecute_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/interp/newexecute_test.go b/interp/newexecute_test.go index cfb14f47..4c267a93 100644 --- a/interp/newexecute_test.go +++ b/interp/newexecute_test.go @@ -140,7 +140,7 @@ func TestExecuteContextCancel(t *testing.T) { func TestExecuteContextSystemTimeout(t *testing.T) { started := time.Now() - interpreter := newInterp(t, `BEGIN { print system("sleep 4") }`) + interpreter := newInterp(t, `BEGIN { print system("sleep 1") }`) ctx, cancel := context.WithTimeout(context.Background(), 5*time.Millisecond) defer cancel() _, err := interpreter.ExecuteContext(ctx, nil) @@ -148,7 +148,7 @@ func TestExecuteContextSystemTimeout(t *testing.T) { t.Fatalf("expected DeadlineExceeded error, got: %v", err) } elapsed := time.Since(started) - if elapsed > time.Second { + if elapsed > 500*time.Millisecond { t.Fatalf("should have taken ~5ms, took %v", elapsed) } } From 49a9ca0e8d55b34b868e06638bb48a0ae0b3eab3 Mon Sep 17 00:00:00 2001 From: Ben Hoyt Date: Tue, 24 May 2022 16:13:48 +1200 Subject: [PATCH 3/5] Ensure system() terminates when context is cancelled This is an issue with the (grand)child process holding stdout/stderr, so per https://github.com/golang/go/issues/21922#issuecomment-338792340 use a pipe to work around this. --- interp/interp_test.go | 3 ++- interp/newexecute_test.go | 25 +++++++++++++++++++++++-- interp/vm.go | 32 +++++++++++++++++++++++++++++--- 3 files changed, 54 insertions(+), 6 deletions(-) diff --git a/interp/interp_test.go b/interp/interp_test.go index d1a4ba0f..e62ce35a 100644 --- a/interp/interp_test.go +++ b/interp/interp_test.go @@ -906,6 +906,7 @@ func testGoAWK( t *testing.T, src, in, out, errStr string, funcs map[string]interface{}, configure func(config *interp.Config), ) { + t.Helper() parserConfig := &parser.ParserConfig{ Funcs: funcs, } @@ -1302,7 +1303,7 @@ func TestSystemCommandNotFound(t *testing.T) { } type mockFlusher struct { - bytes.Buffer + concurrentBuffer flushes []string } diff --git a/interp/newexecute_test.go b/interp/newexecute_test.go index 4c267a93..6d814874 100644 --- a/interp/newexecute_test.go +++ b/interp/newexecute_test.go @@ -6,6 +6,8 @@ import ( "bytes" "context" "errors" + "io/ioutil" + "os" "strings" "testing" "time" @@ -138,12 +140,31 @@ func TestExecuteContextCancel(t *testing.T) { } } -func TestExecuteContextSystemTimeout(t *testing.T) { +// The three cases here are to ensure we test https://github.com/benhoyt/goawk/issues/122 +func TestExecuteContextSystemTimeoutDefault(t *testing.T) { + testExecuteContextSystemTimeout(t, nil) +} + +func TestExecuteContextSystemTimeoutStdoutStderr(t *testing.T) { + testExecuteContextSystemTimeout(t, &interp.Config{ + Output: os.Stdout, + Error: os.Stderr, + }) +} + +func TestExecuteContextSystemTimeoutDiscard(t *testing.T) { + testExecuteContextSystemTimeout(t, &interp.Config{ + Output: ioutil.Discard, + Error: ioutil.Discard, + }) +} + +func testExecuteContextSystemTimeout(t *testing.T, config *interp.Config) { started := time.Now() interpreter := newInterp(t, `BEGIN { print system("sleep 1") }`) ctx, cancel := context.WithTimeout(context.Background(), 5*time.Millisecond) defer cancel() - _, err := interpreter.ExecuteContext(ctx, nil) + _, err := interpreter.ExecuteContext(ctx, config) if !errors.Is(err, context.DeadlineExceeded) { t.Fatalf("expected DeadlineExceeded error, got: %v", err) } diff --git a/interp/vm.go b/interp/vm.go index 49b07f50..b0ccefda 100644 --- a/interp/vm.go +++ b/interp/vm.go @@ -1068,10 +1068,36 @@ func (p *interp) callBuiltin(builtinOp compiler.BuiltinOp) error { cmdline := p.toString(p.peekTop()) cmd := p.execShell(cmdline) cmd.Stdin = p.stdin - cmd.Stdout = p.output - cmd.Stderr = p.errorOutput + + // To ensure we address https://github.com/golang/go/issues/21922, use + // pipes instead of cmd.Stdout and cmd.Stderr directly, otherwise when + // the context is cancelled the (grand)child process won't terminate. + stdoutPipe, err := cmd.StdoutPipe() + if err != nil { + return err + } + stdoutCh := make(chan error) + go func() { + io.Copy(p.output, stdoutPipe) + close(stdoutCh) + }() + stderrPipe, err := cmd.StderrPipe() + if err != nil { + return err + } + stderrCh := make(chan error) + go func() { + io.Copy(p.errorOutput, stderrPipe) + close(stderrCh) + }() + _ = p.flushAll() // ensure synchronization - err := cmd.Run() + err = cmd.Run() + + // Ensure copy goroutines have exited. + <-stdoutCh + <-stderrCh + ret := 0.0 if err != nil { if p.checkCtx && p.ctx.Err() != nil { From 491bca520805cc36c6497a66162fa2074bc0a515 Mon Sep 17 00:00:00 2001 From: Ben Hoyt Date: Tue, 24 May 2022 16:32:20 +1200 Subject: [PATCH 4/5] Move flushAll() to avoid data race --- interp/vm.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/interp/vm.go b/interp/vm.go index b0ccefda..8f824623 100644 --- a/interp/vm.go +++ b/interp/vm.go @@ -1069,6 +1069,8 @@ func (p *interp) callBuiltin(builtinOp compiler.BuiltinOp) error { cmd := p.execShell(cmdline) cmd.Stdin = p.stdin + _ = p.flushAll() // ensure synchronization + // To ensure we address https://github.com/golang/go/issues/21922, use // pipes instead of cmd.Stdout and cmd.Stderr directly, otherwise when // the context is cancelled the (grand)child process won't terminate. @@ -1091,7 +1093,6 @@ func (p *interp) callBuiltin(builtinOp compiler.BuiltinOp) error { close(stderrCh) }() - _ = p.flushAll() // ensure synchronization err = cmd.Run() // Ensure copy goroutines have exited. From 0126d4c82c86b0adf39d708c6a26f44e11291bf8 Mon Sep 17 00:00:00 2001 From: Ben Hoyt Date: Tue, 24 May 2022 17:48:34 +1200 Subject: [PATCH 5/5] Avoid use of cmd.Run() when using Std[out|err]Pipe() Still has some kind of race condition ... not sure why: $ go test ./interp -awk='' -run='Interp/system.*echo_foo' -count=1000 --- FAIL: TestInterp (0.01s) --- FAIL: TestInterp/BEGIN_{_print_system("echo_foo");_print_system("echo_bar")_}__#_!fuzz (0.00s) interp_test.go:879: expected "foo\n0\nbar\n0\n", got "0\nbar\n0\n" --- FAIL: TestInterp (0.01s) --- FAIL: TestInterp/BEGIN_{_print_system("echo_foo");_print_system("echo_bar")_}__#_!fuzz (0.00s) interp_test.go:879: expected "foo\n0\nbar\n0\n", got "0\nbar\n0\n" FAIL FAIL github.com/benhoyt/goawk/interp 5.241s FAIL --- interp/vm.go | 40 ++++++++++++++++++++++++---------------- 1 file changed, 24 insertions(+), 16 deletions(-) diff --git a/interp/vm.go b/interp/vm.go index 8f824623..204cf395 100644 --- a/interp/vm.go +++ b/interp/vm.go @@ -1078,27 +1078,35 @@ func (p *interp) callBuiltin(builtinOp compiler.BuiltinOp) error { if err != nil { return err } - stdoutCh := make(chan error) - go func() { - io.Copy(p.output, stdoutPipe) - close(stdoutCh) - }() stderrPipe, err := cmd.StderrPipe() if err != nil { return err } - stderrCh := make(chan error) - go func() { - io.Copy(p.errorOutput, stderrPipe) - close(stderrCh) - }() - - err = cmd.Run() - - // Ensure copy goroutines have exited. - <-stdoutCh - <-stderrCh + // Start the process (before reading from stdout/stderr). + err = cmd.Start() + if p.checkCtx && err == nil && p.ctx.Err() != nil { + err = p.ctx.Err() + } + if err == nil { + stdoutCh := make(chan error) + go func() { + io.Copy(p.output, stdoutPipe) + close(stdoutCh) + }() + stderrCh := make(chan error) + go func() { + io.Copy(p.errorOutput, stderrPipe) + close(stderrCh) + }() + + // Wait till process completes. + err = cmd.Wait() + + // Ensure copy goroutines have exited. + <-stdoutCh + <-stderrCh + } ret := 0.0 if err != nil { if p.checkCtx && p.ctx.Err() != nil {