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.

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

x/playground: interleaving stdout and stderr is broken #24659

Closed
ysmolski opened this issue Apr 3, 2018 · 8 comments
Closed

x/playground: interleaving stdout and stderr is broken #24659

ysmolski opened this issue Apr 3, 2018 · 8 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@ysmolski
Copy link
Member

ysmolski commented Apr 3, 2018

The expected output of the program https://play.golang.org/p/5agzWi_tyrw is

error 0
outpt 0
error 1
outpt 1
error 2
outpt 2

Actual output is

outpt 0
outpt 1
outpt 2
error 0
error 1
error 2

I see a way to fix this in playground by writing both stderr and stdout streams into one: stdout. Since playground does not display stderr any different than stdout, we can do this to make its behaviour consistent.

This issue affects tests executed in playground. If the test outputs anything to stderr then the order of lines is not consistent. See #24615

@gopherbot gopherbot added this to the Unreleased milestone Apr 3, 2018
@bcmills
Copy link
Contributor

bcmills commented Apr 3, 2018

(CC: @andybons @josharian)

@bcmills bcmills added the NeedsFix The path to resolution is known, but the work has not been done. label Apr 3, 2018
@gopherbot
Copy link

Change https://golang.org/cl/104857 mentions this issue: playground: fix the order of interleaved stdout and stderr

@gopherbot
Copy link

Change https://golang.org/cl/105235 mentions this issue: runtime: make fake timestamps in Playground writes strict

@ysmolski
Copy link
Member Author

ysmolski commented Apr 7, 2018

Here is some debug output collected by using this:

modified   play.go
@@ -55,7 +55,7 @@ type recorderWriter struct {
 func (w recorderWriter) Write(b []byte) (n int, err error) {
 	w.r.mu.Lock()
 	defer w.r.mu.Unlock()
-
+	fmt.Printf("W %v %q\n", w.kind, string(b))
 	// Append this write to the previous one if it has the same kind.
 	if len(w.r.writes) > 0 {
 		prev := &w.r.writes[len(w.r.writes)-1]

Running this program

	fmt.Fprint(os.Stderr, "e1")
	fmt.Fprint(os.Stdout, "z1")
	fmt.Fprint(os.Stderr, "e2")
	fmt.Fprint(os.Stdout, "z2")
	fmt.Fprint(os.Stderr, "e3")
	fmt.Fprint(os.Stdout, "z3")

gives following recombinations of output:

W stderr "\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02"
W stderr "e1"
W stdout "\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02"
W stderr "\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02e2\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02e3"
W stdout "z1\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02z2\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02z3"
W stderr "\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02"
W stderr "e1"
W stdout "\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02"
W stdout "z1"
W stderr "\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02"
W stdout "\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02z2\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02z3"
W stderr "e2\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02e3"

I have applied the strict time patch to the go and built playground, got following:

W stderr "\x00\x00PB\x11t\xef\xed\xab\x18`\x00\x00\x00\x00\x02"
W stderr "e1"
W stderr "\x00\x00PB\x11t\xef\xed\xab\x18`\x02\x00\x00\x00\x02e2"
W stdout "\x00\x00PB\x11t\xef\xed\xab\x18`\x01\x00\x00\x00\x02z1\x00\x00PB\x11t\xef\xed\xab\x18`\x03\x00\x00\x00\x02z2"
W stderr "\x00\x00PB\x11t\xef\xed\xab\x18`\x04\x00\x00\x00\x02"
W stdout "\x00\x00PB\x11t\xef\xed\xab\x18`\x05\x00\x00\x00\x02z3"
W stderr "e3"

We do get increments in header for every write operation.

It is interesting to note that header and actual data are not passed as a single piece to recordWriter.write. Even with the work done by @bcmills, we have to take another step to solve this. We should aggregate writes of different kinds into separate slices, process them individually from bytes into events and then merge those events slices with a sorting by the strict time values.

@bcmills, does it make sense?

Update: I am working on the playground change complementing the fix by Bryan.

@bcmills
Copy link
Contributor

bcmills commented Apr 7, 2018

Nice analysis. Separate buffering sounds right. (And if we buffer the two streams separately, we can do an O(n) sorted merge instead of an O(n log n) sort!)

@gopherbot
Copy link

Change https://golang.org/cl/105496 mentions this issue: playground: use strict fake timestamps for sorting output

@gopherbot
Copy link

Change https://golang.org/cl/106216 mentions this issue: playground: patch runtime with https://golang.org/cl/105235

gopherbot pushed a commit that referenced this issue Apr 11, 2018
The process reading the output of the binary may read stderr and
stdout separately, and may interleave reads from the two streams
arbitrarily. Because we explicitly serialize writes on the writer
side, we can reuse a timestamp within a single stream without losing
information; however, if we use the same timestamp for write on both
streams, the reader can't tell how to interleave them.

This change ensures that every time we change between the two fds, we
also bump the timestamp. That way, writes within a stream continue to
show the same timestamp, but a sorted merge of the contents of the two
streams always interleaves them in the correct order.

This still requires a corresponding change to the Playground parser to
actually reconstruct the correct interleaving. It currently merges the
two streams without reordering them; it should instead buffer them
separately and perform a sorted merge. (See
https://golang.org/cl/105496.)

Updates #24615.
Updates #24659.

Change-Id: Id789dfcc02eb4247906c9ddad38dac50cf829979
Reviewed-on: https://go-review.googlesource.com/105235
Run-TryBot: Bryan C. Mills <bcmills@google.com>
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Yury Smolsky <yury@smolsky.by>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
@gopherbot
Copy link

Change https://golang.org/cl/106475 mentions this issue: playground: add integration test for https://golang.org/cl/105235

gopherbot pushed a commit to golang/playground that referenced this issue Apr 13, 2018
Add a test case (currently flaky) that checks for deterministic output
ordering.

Updates golang/go#24615.
Updates golang/go#24659.

Change-Id: I7edc5d77a890edcd684ddf2aeee4c7a7dea68af1
Reviewed-on: https://go-review.googlesource.com/106216
Reviewed-by: Andrew Bonventre <andybons@golang.org>
gopherbot pushed a commit to golang/playground that referenced this issue Apr 13, 2018
Add a test case that checks fake timestamps generated by the patched
runtime.write.

Updates golang/go#24615
Updates golang/go#24659

Change-Id: I210cfd4500e7f72567539dd9b3e23da4f907a3e2
Reviewed-on: https://go-review.googlesource.com/106475
Reviewed-by: Bryan C. Mills <bcmills@google.com>
@golang golang locked and limited conversation to collaborators Apr 13, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

3 participants