x/playground: faketime headers not stripped from os/exec subprocess output

[bcmills]

What did you do?

https://play.golang.org/p/Gi7BzeGhs6Q

What did you expect to see?

Similar output to go test -v when running the test locally:

$ go test -v
=== RUN   TestPanicDoChan
=== PAUSE TestPanicDoChan
=== CONT  TestPanicDoChan
    main_test.go:55: /tmp/go-build979564443/b001/example.com.test -test.run=TestPanicDoChan -test.v:
        === RUN   TestPanicDoChan
        fatal error: all goroutines are asleep - deadlock!

        goroutine 1 [chan receive]:
        testing.(*T).Run(0xc000001380, 0x550089, 0xf, 0x5581a8, 0x4831c6)
                /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1203 +0x2da
        testing.runTests.func1(0xc000001200)
                /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1475 +0x78
        testing.tRunner(0xc000001200, 0xc000072de0)
                /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1157 +0xef
        testing.runTests(0xc00000c060, 0x627270, 0x1, 0x1, 0x0, 0x0, 0x0, 0x40d3b0)
                /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1473 +0x2fe
        testing.(*M).Run(0xc000110000, 0x0)
                /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1381 +0x1eb
        main.main()
                _testmain.go:43 +0x138

        goroutine 6 [chan receive]:
        example%2ecom.TestPanicDoChan(0xc000001380)
                /tmp/tmp.ghGKUvokgN/example.com/main_test.go:39 +0x61e
        testing.tRunner(0xc000001380, 0x5581a8)
                /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1157 +0xef
        created by testing.(*T).Run
                /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1202 +0x2b3

        goroutine 7 [chan receive]:
        example%2ecom.TestPanicDoChan.func1.2(0x4134eb, 0xd0, 0x538fe0, 0x50257ab94168e01)
                /tmp/tmp.ghGKUvokgN/example.com/main_test.go:30 +0x4a
        golang.org/x/sync/singleflight.(*Group).doCall(0xc0000524f0, 0xc00005c2a0, 0x0, 0x0, 0xc00003e798)
                /tmp/tmp.ghGKUvokgN/_gopath/pkg/mod/golang.org/x/sync@v0.0.0-20200625203802-6e8e738ad208/singleflight/singleflight.go:97 +0x2e
        golang.org/x/sync/singleflight.(*Group).Do(0xc0000524f0, 0x0, 0x0, 0xc00003e798, 0x91ad385ba9787, 0xc00003e7c0, 0x4d388f, 0xc000001380, 0x6bd3b)
                /tmp/tmp.ghGKUvokgN/_gopath/pkg/mod/golang.org/x/sync@v0.0.0-20200625203802-6e8e738ad208/singleflight/singleflight.go:67 +0x1c5
        example%2ecom.TestPanicDoChan.func1(0xc0000524f0, 0xc000022300, 0xc000022360)
                /tmp/tmp.ghGKUvokgN/example.com/main_test.go:28 +0x9a
        created by example%2ecom.TestPanicDoChan
                /tmp/tmp.ghGKUvokgN/example.com/main_test.go:24 +0x5c7
--- PASS: TestPanicDoChan (0.01s)
PASS
ok      example.com     0.019s

What did you see instead?

Mangled output containing faketime headers:

0xc000060300PBt���`
)
        PBt���`

 PBt���`
/tmp/sandbox650178755/prog.goPBt���`

:PBt���`
28PBt���`
 +PBt���`
0x9aPBt���`


        PBt���`
created by PBt���`
main.TestPanicDoChanPBt���`


        PBt���`

 PBt���`
/tmp/sandbox650178755/prog.goPBt���`

:PBt���`
24PBt���`
 +PBt���`
0x5c7PBt���`


--- PASS: TestPanicDoChan (0.00s)
PASS

[bcmills]

CC @golang/osp-team

[dmitshur]

I understand this issue is related to but not the same as #38751. The difference here is that it happens specifically for subprocess output even when the output is not large. Is that right?

[bcmills]

Correct. And the fix here is probably independent of that fix. (Probably os/exec should be patched to strip out timestamp headers from stdout and stderr? But maybe there's a better approach, like suppressing the timestamping entirely in subprocesses.)

[prattmic]

The fundamental issue here is that stdout/stderr of faketime binaries is simply not meant to be generally consumable. Rather it is intended only for handling by the playground itself.

I don't think have os/exec strip headers would be a robust fix, as intermediate processes could still get confused. e.g., exec a bash script, which exec's the original binary and parses its output. In this case, the stdout/stderr is never passing through os/exec, so it doesn't get a chance to fix it up.

A more robust solution that comes to mind would be to only enable faketime headers if a specific environment variable is set. The playground would always set this variable, and the faketime binary should probably clear it on init so it isn't inherited by os/exec calls.

---

At a higher level, I think we need to step back and think about whether we really want to support subprocesses on the playground. The sandbox can support it just fine, but I think these kinds of weird issues are going to keep coming up as long as we have faketime. If we don't support it, we could disable os/exec entirely. (Users could still directly invoke the syscalls, but we have no support there).

[bcmills]

Personally, I think enabling faketime by an environment variable, clearing that environment variable early during process-init, and allowing os/exec in general is probably the way to go. I would hate to drop os/exec entirely in the Playground, given that the sandbox can handle it.