From 2ea69a3ac4f90647f38348d91d0aafe2a2161844 Mon Sep 17 00:00:00 2001 From: Michael Pratt Date: Wed, 15 Dec 2021 16:20:59 -0500 Subject: [PATCH] cmd/coordinator: collapse duplicate execution headers Following CL 371474, cmd/dist may include a "Test execution environment" header which describes the test execution environment. When sharding tests, we want to surface the proper execution environment for each test, which may vary from shard to shard. We could simply print the metadata for each shard in its output, as shard results are printed in an atomic block. However, shards are pretty small and that adds quite a bit of noise to logs. Instead, treat the metadata block like the test header banners: as long as the metadata doesn't change, we don't need to print it again. On the other hand, if the metadata changes, we do print the test header banner again. This isn't strictly necessary, it just serves to improve readability by ensuring that tests are always immediately preceeded by their banner rather than metadata (in the case that metadata changes in the middle of a header block). This CL should be submitted and deployed before CL 371474. For golang/go#50146. Change-Id: Ifca30f7f31237fd8cd0fcd801d198d9c341f695e Reviewed-on: https://go-review.googlesource.com/c/build/+/372538 Trust: Michael Pratt Run-TryBot: Michael Pratt TryBot-Result: Gopher Robot Reviewed-by: Alex Rakoczy --- cmd/coordinator/buildstatus.go | 70 +++++++++++++--- cmd/coordinator/buildstatus_test.go | 123 ++++++++++++++++++++++++---- 2 files changed, 168 insertions(+), 25 deletions(-) diff --git a/cmd/coordinator/buildstatus.go b/cmd/coordinator/buildstatus.go index 4ebfc4cd..ab94a216 100644 --- a/cmd/coordinator/buildstatus.go +++ b/cmd/coordinator/buildstatus.go @@ -1496,6 +1496,7 @@ func (st *buildStatus) runTests(helpers <-chan buildlet.Client) (remoteErr, err close(buildletsGone) }() + var lastMetadata string var lastHeader string var serialDuration time.Duration for _, ti := range set.items { @@ -1516,9 +1517,24 @@ func (st *buildStatus) runTests(helpers <-chan buildlet.Client) (remoteErr, err serialDuration += ti.execDuration if len(ti.output) > 0 { - header, out := parseOutputAndHeader(ti.output) + metadata, header, out := parseOutputAndHeader(ti.output) + printHeader := false + if metadata != lastMetadata { + lastMetadata = metadata + fmt.Fprintf(st, "\n%s\n", metadata) + // Always include the test header after + // metadata changes. This is a readability + // optimization that ensures that tests are + // always immediately preceeded by their test + // banner, even if it is duplicate banner + // because the test metadata changed. + printHeader = true + } if header != lastHeader { lastHeader = header + printHeader = true + } + if printHeader { fmt.Fprintf(st, "\n%s\n", header) } if pool.NewGCEConfiguration().InStaging() { @@ -1551,31 +1567,63 @@ const ( banner = "XXXBANNERXXX:" // flag passed to dist bannerPrefix = "\n" + banner // with the newline added by dist + metadataBannerPrefix = bannerPrefix + "Test execution environment." + outputBanner = "##### " // banner to display in output. ) -var bannerPrefixBytes = []byte(bannerPrefix) +var ( + bannerPrefixBytes = []byte(bannerPrefix) + metadataBannerPrefixBytes = []byte(metadataBannerPrefix) +) -// parseOutputAndHeader parses b and returns the test display header (e.g., -// "##### Testing packages.") and the following output. -func parseOutputAndHeader(b []byte) (header string, out []byte) { +// parseOutputAndHeader parses b and returns the test (optional) environment +// metaadata, display header (e.g., "##### Testing packages.") and the +// following output. +// +// metadata is the optional execution environment metadata block. e.g., +// +// ##### Test execution environment. +// # GOARCH: amd64 +// # CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz +func parseOutputAndHeader(b []byte) (metadata, header string, out []byte) { if !bytes.HasPrefix(b, bannerPrefixBytes) { - return "", b + return "", "", b } - b = b[1:] // skip newline + if bytes.HasPrefix(b, metadataBannerPrefixBytes) { + // Header includes everything up to and including the next + // banner. + rem := b[len(metadataBannerPrefixBytes):] + i := bytes.Index(rem, bannerPrefixBytes) + if i == -1 { + // Metadata block without a following block doesn't + // make sense. Bail. + return "", "", b + } + bi := i + len(metadataBannerPrefixBytes) + // Metadata portion of header, skipping initial and trailing newlines. + metadata = strings.Trim(string(b[:bi]), "\n") + metadata = strings.Replace(metadata, banner, outputBanner, 1) + b = b[bi+1:] // skip newline at start of next banner. + } else { + b = b[1:] // skip newline + } + + // Find end of primary test banner. nl := bytes.IndexByte(b, '\n') if nl == -1 { + // No newline, everything is header. header = string(b) b = nil } else { header = string(b[:nl]) b = b[nl+1:] } - // Replace internal marker banner with the human-friendly - // version. - header = strings.ReplaceAll(header, banner, outputBanner) - return header, b + + // Replace internal marker banner with the human-friendly version. + header = strings.Replace(header, banner, outputBanner, 1) + return metadata, header, b } // maxTestExecError is the number of test execution failures at which diff --git a/cmd/coordinator/buildstatus_test.go b/cmd/coordinator/buildstatus_test.go index 9031ff66..338cf8a1 100644 --- a/cmd/coordinator/buildstatus_test.go +++ b/cmd/coordinator/buildstatus_test.go @@ -15,10 +15,11 @@ import ( // TestParseOutputAndHeader tests header parsing by parseOutputAndHeader. func TestParseOutputAndHeader(t *testing.T) { for _, tc := range []struct { - name string - input []byte - wantHeader string - wantOut []byte + name string + input []byte + wantMetadata string + wantHeader string + wantOut []byte }{ { name: "standard", @@ -28,7 +29,8 @@ ok archive/tar 0.015s ok archive/zip 0.406s ok bufio 0.075s `), - wantHeader: "##### Testing packages.", + wantMetadata: "", + wantHeader: "##### Testing packages.", wantOut: []byte(`ok archive/tar 0.015s ok archive/zip 0.406s ok bufio 0.075s @@ -39,15 +41,17 @@ ok bufio 0.075s input: []byte(` XXXBANNERXXX:Testing packages. `), - wantHeader: "##### Testing packages.", - wantOut: []byte(``), + wantMetadata: "", + wantHeader: "##### Testing packages.", + wantOut: []byte(``), }, { name: "header only missing trailing newline", input: []byte(` XXXBANNERXXX:Testing packages.`), - wantHeader: "##### Testing packages.", - wantOut: []byte(``), + wantMetadata: "", + wantHeader: "##### Testing packages.", + wantOut: []byte(``), }, { name: "no banner", @@ -55,7 +59,8 @@ XXXBANNERXXX:Testing packages.`), ok archive/zip 0.406s ok bufio 0.075s `), - wantHeader: "", + wantMetadata: "", + wantHeader: "", wantOut: []byte(`ok archive/tar 0.015s ok archive/zip 0.406s ok bufio 0.075s @@ -68,7 +73,8 @@ ok archive/tar 0.015s ok archive/zip 0.406s ok bufio 0.075s `), - wantHeader: "", + wantMetadata: "", + wantHeader: "", wantOut: []byte(`XXXBANNERXXX:Testing packages. ok archive/tar 0.015s ok archive/zip 0.406s @@ -83,7 +89,8 @@ ok archive/tar 0.015s ok archive/zip 0.406s ok bufio 0.075s `), - wantHeader: "", + wantMetadata: "", + wantHeader: "", wantOut: []byte(` ##### Testing packages. ok archive/tar 0.015s @@ -91,11 +98,99 @@ ok archive/zip 0.406s ok bufio 0.075s `), }, + { + name: "metadata", + input: []byte(` +XXXBANNERXXX:Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz + +XXXBANNERXXX:Testing packages. +ok archive/tar 0.015s +ok archive/zip 0.406s +ok bufio 0.075s +`), + wantMetadata: `##### Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz`, + wantHeader: "##### Testing packages.", + wantOut: []byte(`ok archive/tar 0.015s +ok archive/zip 0.406s +ok bufio 0.075s +`), + }, + { + name: "metadata missing separator newline", + input: []byte(` +XXXBANNERXXX:Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz +XXXBANNERXXX:Testing packages. +ok archive/tar 0.015s +ok archive/zip 0.406s +ok bufio 0.075s +`), + wantMetadata: `##### Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz`, + wantHeader: "##### Testing packages.", + wantOut: []byte(`ok archive/tar 0.015s +ok archive/zip 0.406s +ok bufio 0.075s +`), + }, + { + name: "metadata missing second banner", + input: []byte(` +XXXBANNERXXX:Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz +`), + wantMetadata: "", + wantHeader: "", + wantOut: []byte(` +XXXBANNERXXX:Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz +`), + }, + { + name: "metadata missing body", + input: []byte(` +XXXBANNERXXX:Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz + +XXXBANNERXXX:Testing packages. +`), + wantMetadata: `##### Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz`, + wantHeader: "##### Testing packages.", + wantOut: []byte(``), + }, + { + name: "metadata missing body and newline", + input: []byte(` +XXXBANNERXXX:Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz + +XXXBANNERXXX:Testing packages.`), + wantMetadata: `##### Test execution environment. +# GOARCH: amd64 +# CPU: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz`, + wantHeader: "##### Testing packages.", + wantOut: []byte(``), + }, } { t.Run(tc.name, func(t *testing.T) { - gotHeader, gotOut := parseOutputAndHeader(tc.input) + gotMetadata, gotHeader, gotOut := parseOutputAndHeader(tc.input) + if gotMetadata != tc.wantMetadata { + t.Errorf("parseOutputAndBanner(%q) got metadata %q want metadata %q", string(tc.input), gotMetadata, tc.wantMetadata) + } if gotHeader != tc.wantHeader { - t.Errorf("parseOutputAndBanner(%q) got banner %q want banner %q", string(tc.input), gotHeader, tc.wantHeader) + t.Errorf("parseOutputAndBanner(%q) got header %q want header %q", string(tc.input), gotHeader, tc.wantHeader) } if string(gotOut) != string(tc.wantOut) { t.Errorf("parseOutputAndBanner(%q) got out %q want out %q", string(tc.input), string(gotOut), string(tc.wantOut))