Skip to content
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

Jump to bottom

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

Open
bcmills opened this issue Sep 11, 2020 · 5 comments
Open

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

bcmills opened this issue Sep 11, 2020 · 5 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Unreleased

Comments

@bcmills
Copy link
Contributor

bcmills commented Sep 11, 2020

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:

0xc000060300PB�t����`��)
        PB�t����`��	PB�t����`��/tmp/sandbox650178755/prog.goPB�t����`��:PB�t����`��28PB�t����`�� +PB�t����`��0x9aPB�t����`��
        PB�t����`��created by PB�t����`��main.TestPanicDoChanPB�t����`��
        PB�t����`��	PB�t����`��/tmp/sandbox650178755/prog.goPB�t����`��:PB�t����`��24PB�t����`�� +PB�t����`��0x5c7PB�t����`��
--- PASS: TestPanicDoChan (0.00s)
PASS
@gopherbot gopherbot added this to the Unreleased milestone Sep 11, 2020
@bcmills bcmills changed the title x/playground: timing headers not stripped from os/exec subprocess output x/playground: faketime headers not stripped from os/exec subprocess output Sep 11, 2020
@bcmills
Copy link
Contributor Author

bcmills commented Sep 11, 2020

CC @golang/osp-team

@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 11, 2020
@dmitshur
Copy link
Contributor

dmitshur commented Sep 11, 2020 •
edited

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
Copy link
Contributor Author

bcmills commented Sep 11, 2020

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
Copy link
Member

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
Copy link
Contributor Author

bcmills commented Sep 11, 2020

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.

@bcmills bcmills mentioned this issue Oct 15, 2020
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Unreleased
Development

No branches or pull requests
4 participants
@prattmic @dmitshur @bcmills @gopherbot