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/build/cmd/golangbuild: LUCI builders run into result_adapter fail to parse FAIL message when there's a build failure #65467

Open
cherrymui opened this issue Feb 2, 2024 · 6 comments
Labels
Builders x/build issues (builders, bots, dashboards) NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@cherrymui
Copy link
Member

cherrymui commented Feb 2, 2024

#!watchflakes
post <- mode == "build" &&
	((`rdb-stream` && `cannot parse row .*, invalid character 'F' looking for beginning of value`) ||
		log ~ `cannot parse row .*, invalid character 'F' looking for beginning of value`)
@gopherbot gopherbot added the Builders x/build issues (builders, bots, dashboards) label Feb 2, 2024
@gopherbot gopherbot added this to the Unreleased milestone Feb 2, 2024
@cherrymui
Copy link
Member Author

Probably already fixed.

@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- mode == "build" && `rdb-stream` && `cannot parse row .*, invalid character 'F' looking for beginning of value`
2024-01-23 00:04 x_sys-go1.20-windows-386 sys@c3fa2b8b release-branch.go1.20@a95136a8 [build] (log)
[I2024-01-22T16:05:51.163787-08:00 2424 0 sink.go:276] SinkServer: warm-up started
[I2024-01-22T16:05:51.163787-08:00 2424 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-01-22T16:05:51.165781-08:00 2424 0 sink.go:281] SinkServer: warm-up ended
[I2024-01-22T16:05:51.166842-08:00 2424 0 cmd_stream.go:473] rdb-stream: starting the test command - ["C:\\b\\s\\w\\ir\\cache\\tools\\bin\\result_adapter" "go" "-v=false" "--" "C:\\b\\s\\w\\ir\\x\\w\\goroot\\bin\\go" "test" "-json" "-short" "./..."]
# golang.org/x/sys/windows
windows\env_windows_test.go:9:2: package slices is not in GOROOT (C:\b\s\w\ir\x\w\goroot\src\slices)
cannot parse row "FAIL\tgolang.org/x/sys/windows [setup failed]", invalid character 'F' looking for beginning of value
ok  	golang.org/x/sys/cpu	0.045s
ok  	golang.org/x/sys/execabs	0.090s
ok  	golang.org/x/sys/unix/internal/mkmerge	0.071s
ok  	golang.org/x/sys/windows/mkwinsyscall	0.072s
ok  	golang.org/x/sys/windows/registry	0.070s
ok  	golang.org/x/sys/windows/svc	1.469s
ok  	golang.org/x/sys/windows/svc/eventlog	0.046s
ok  	golang.org/x/sys/windows/svc/mgr	0.075s
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-01-22T16:06:04.128643-08:00 2424 0 cmd_stream.go:469] rdb-stream: the test process terminated
[I2024-01-22T16:06:04.128643-08:00 2424 0 sink.go:371] SinkServer: shutdown started
[I2024-01-22T16:06:04.128643-08:00 2424 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-01-22T16:06:04.128643-08:00 2424 0 sink_server.go:95] SinkServer: draining TestResult channel started
[I2024-01-22T16:06:04.227404-08:00 2424 0 sink_server.go:97] SinkServer: draining TestResult channel ended
[I2024-01-22T16:06:04.227404-08:00 2424 0 sink_server.go:99] SinkServer: draining Artifact channel started
[I2024-01-22T16:06:04.298219-08:00 2424 0 sink_server.go:101] SinkServer: draining Artifact channel ended
[I2024-01-22T16:06:04.298219-08:00 2424 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-01-22T16:06:04.298219-08:00 2424 0 cmd_stream.go:401] rdb-stream: exiting with 1
2024-01-23 00:04 x_sys-go1.20-windows-amd64 sys@c3fa2b8b release-branch.go1.20@a95136a8 [build] (log)
[I2024-01-22T16:06:17.312875-08:00 7940 0 sink.go:276] SinkServer: warm-up started
[I2024-01-22T16:06:17.313702-08:00 7940 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-01-22T16:06:17.315774-08:00 7940 0 sink.go:281] SinkServer: warm-up ended
[I2024-01-22T16:06:17.316772-08:00 7940 0 cmd_stream.go:473] rdb-stream: starting the test command - ["C:\\b\\s\\w\\ir\\cache\\tools\\bin\\result_adapter" "go" "-v=false" "--" "C:\\b\\s\\w\\ir\\x\\w\\goroot\\bin\\go" "test" "-json" "-short" "./..."]
# golang.org/x/sys/windows
windows\env_windows_test.go:9:2: package slices is not in GOROOT (C:\b\s\w\ir\x\w\goroot\src\slices)
cannot parse row "FAIL\tgolang.org/x/sys/windows [setup failed]", invalid character 'F' looking for beginning of value
ok  	golang.org/x/sys/cpu	0.045s
ok  	golang.org/x/sys/execabs	0.063s
ok  	golang.org/x/sys/unix/internal/mkmerge	0.056s
ok  	golang.org/x/sys/windows/mkwinsyscall	0.045s
ok  	golang.org/x/sys/windows/registry	0.039s
ok  	golang.org/x/sys/windows/svc	0.706s
ok  	golang.org/x/sys/windows/svc/eventlog	0.034s
ok  	golang.org/x/sys/windows/svc/mgr	0.041s
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-01-22T16:06:28.005255-08:00 7940 0 cmd_stream.go:469] rdb-stream: the test process terminated
[I2024-01-22T16:06:28.006115-08:00 7940 0 sink.go:371] SinkServer: shutdown started
[I2024-01-22T16:06:28.006229-08:00 7940 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-01-22T16:06:28.006229-08:00 7940 0 sink_server.go:95] SinkServer: draining TestResult channel started
[I2024-01-22T16:06:28.171747-08:00 7940 0 sink_server.go:97] SinkServer: draining TestResult channel ended
[I2024-01-22T16:06:28.171747-08:00 7940 0 sink_server.go:99] SinkServer: draining Artifact channel started
[I2024-01-22T16:06:28.270703-08:00 7940 0 sink_server.go:101] SinkServer: draining Artifact channel ended
[I2024-01-22T16:06:28.270703-08:00 7940 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-01-22T16:06:28.270703-08:00 7940 0 cmd_stream.go:401] rdb-stream: exiting with 1
2024-01-23 00:04 x_sys-go1.20-windows-amd64-longtest sys@c3fa2b8b release-branch.go1.20@a95136a8 [build] (log)
[I2024-01-22T16:06:12.073117-08:00 2980 0 sink.go:276] SinkServer: warm-up started
[I2024-01-22T16:06:12.073231-08:00 2980 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-01-22T16:06:12.075995-08:00 2980 0 sink.go:281] SinkServer: warm-up ended
[I2024-01-22T16:06:12.077195-08:00 2980 0 cmd_stream.go:473] rdb-stream: starting the test command - ["C:\\b\\s\\w\\ir\\cache\\tools\\bin\\result_adapter" "go" "-v=false" "--" "C:\\b\\s\\w\\ir\\x\\w\\goroot\\bin\\go" "test" "-json" "./..."]
# golang.org/x/sys/windows
windows\env_windows_test.go:9:2: package slices is not in GOROOT (C:\b\s\w\ir\x\w\goroot\src\slices)
cannot parse row "FAIL\tgolang.org/x/sys/windows [setup failed]", invalid character 'F' looking for beginning of value
ok  	golang.org/x/sys/cpu	0.037s
ok  	golang.org/x/sys/execabs	0.078s
ok  	golang.org/x/sys/unix/internal/mkmerge	0.068s
ok  	golang.org/x/sys/windows/mkwinsyscall	0.073s
ok  	golang.org/x/sys/windows/registry	0.079s
ok  	golang.org/x/sys/windows/svc	4.487s
ok  	golang.org/x/sys/windows/svc/eventlog	1.125s
ok  	golang.org/x/sys/windows/svc/mgr	0.080s
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-01-22T16:06:26.278932-08:00 2980 0 cmd_stream.go:469] rdb-stream: the test process terminated
[I2024-01-22T16:06:26.279198-08:00 2980 0 sink.go:371] SinkServer: shutdown started
[I2024-01-22T16:06:26.279198-08:00 2980 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-01-22T16:06:26.279198-08:00 2980 0 sink_server.go:95] SinkServer: draining TestResult channel started
[I2024-01-22T16:06:26.442973-08:00 2980 0 sink_server.go:97] SinkServer: draining TestResult channel ended
[I2024-01-22T16:06:26.442973-08:00 2980 0 sink_server.go:99] SinkServer: draining Artifact channel started
[I2024-01-22T16:06:26.501184-08:00 2980 0 sink_server.go:101] SinkServer: draining Artifact channel ended
[I2024-01-22T16:06:26.501184-08:00 2980 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-01-22T16:06:26.502258-08:00 2980 0 cmd_stream.go:401] rdb-stream: exiting with 1
[I2024-01-22T16:06:26.502258-08:00 2980 0 cmd_stream.go:426] Caught InterruptEvent
2024-01-23 00:04 x_sys-go1.20-windows-amd64-race sys@c3fa2b8b release-branch.go1.20@a95136a8 [build] (log)
[I2024-01-22T16:05:51.761805-08:00 3972 0 sink.go:276] SinkServer: warm-up started
[I2024-01-22T16:05:51.761805-08:00 3972 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-01-22T16:05:51.764794-08:00 3972 0 sink.go:281] SinkServer: warm-up ended
[I2024-01-22T16:05:51.765644-08:00 3972 0 cmd_stream.go:473] rdb-stream: starting the test command - ["C:\\b\\s\\w\\ir\\cache\\tools\\bin\\result_adapter" "go" "-v=false" "--" "C:\\b\\s\\w\\ir\\x\\w\\goroot\\bin\\go" "test" "-json" "-short" "-race" "./..."]
# golang.org/x/sys/windows
windows\env_windows_test.go:9:2: package slices is not in GOROOT (C:\b\s\w\ir\x\w\goroot\src\slices)
cannot parse row "FAIL\tgolang.org/x/sys/windows [setup failed]", invalid character 'F' looking for beginning of value
ok  	golang.org/x/sys/cpu	1.051s
ok  	golang.org/x/sys/execabs	1.115s
ok  	golang.org/x/sys/unix/internal/mkmerge	1.214s
ok  	golang.org/x/sys/windows/mkwinsyscall	1.113s
ok  	golang.org/x/sys/windows/registry	1.073s
ok  	golang.org/x/sys/windows/svc	11.607s
ok  	golang.org/x/sys/windows/svc/eventlog	1.057s
ok  	golang.org/x/sys/windows/svc/mgr	1.072s
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-01-22T16:06:18.478799-08:00 3972 0 cmd_stream.go:469] rdb-stream: the test process terminated
[I2024-01-22T16:06:18.478799-08:00 3972 0 sink.go:371] SinkServer: shutdown started
[I2024-01-22T16:06:18.478799-08:00 3972 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-01-22T16:06:18.478799-08:00 3972 0 sink_server.go:95] SinkServer: draining TestResult channel started
[I2024-01-22T16:06:18.571000-08:00 3972 0 sink_server.go:97] SinkServer: draining TestResult channel ended
[I2024-01-22T16:06:18.571000-08:00 3972 0 sink_server.go:99] SinkServer: draining Artifact channel started
[I2024-01-22T16:06:18.641635-08:00 3972 0 sink_server.go:101] SinkServer: draining Artifact channel ended
[I2024-01-22T16:06:18.641635-08:00 3972 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-01-22T16:06:18.641635-08:00 3972 0 cmd_stream.go:401] rdb-stream: exiting with 1
2024-01-23 00:04 x_sys-go1.20-windows-arm64 sys@c3fa2b8b release-branch.go1.20@a95136a8 [build] (log)
[I2024-01-23T02:01:41.052581Z 3024 0 sink.go:276] SinkServer: warm-up started
[I2024-01-23T02:01:41.052581Z 3024 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-01-23T02:01:41.055304Z 3024 0 sink.go:281] SinkServer: warm-up ended
[I2024-01-23T02:01:41.055857Z 3024 0 cmd_stream.go:473] rdb-stream: starting the test command - ["C:\\Users\\swarming\\.swarming\\w\\ir\\cache\\tools\\bin\\result_adapter" "go" "-v=false" "--" "C:\\Users\\swarming\\.swarming\\w\\ir\\x\\w\\goroot\\bin\\go" "test" "-json" "-short" "./..."]
# golang.org/x/sys/windows
windows\env_windows_test.go:9:2: package slices is not in GOROOT (C:\Users\swarming\.swarming\w\ir\x\w\goroot\src\slices)
cannot parse row "FAIL\tgolang.org/x/sys/windows [setup failed]", invalid character 'F' looking for beginning of value
ok  	golang.org/x/sys/cpu	0.108s
ok  	golang.org/x/sys/execabs	0.146s
ok  	golang.org/x/sys/unix/internal/mkmerge	0.146s
ok  	golang.org/x/sys/windows/mkwinsyscall	0.236s
ok  	golang.org/x/sys/windows/registry	0.100s
ok  	golang.org/x/sys/windows/svc	1.282s
ok  	golang.org/x/sys/windows/svc/eventlog	0.100s
ok  	golang.org/x/sys/windows/svc/mgr	0.096s
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-01-23T02:01:55.608189Z 3024 0 cmd_stream.go:469] rdb-stream: the test process terminated
[I2024-01-23T02:01:55.608189Z 3024 0 sink.go:371] SinkServer: shutdown started
[I2024-01-23T02:01:55.608766Z 3024 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-01-23T02:01:55.608766Z 3024 0 sink_server.go:95] SinkServer: draining TestResult channel started
[I2024-01-23T02:01:55.712744Z 3024 0 sink_server.go:97] SinkServer: draining TestResult channel ended
[I2024-01-23T02:01:55.712744Z 3024 0 sink_server.go:99] SinkServer: draining Artifact channel started
[I2024-01-23T02:01:55.799456Z 3024 0 sink_server.go:101] SinkServer: draining Artifact channel ended
[I2024-01-23T02:01:55.799456Z 3024 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-01-23T02:01:55.799456Z 3024 0 cmd_stream.go:401] rdb-stream: exiting with 1
[I2024-01-23T02:01:55.799456Z 3024 0 cmd_stream.go:426] Caught InterruptEvent

watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- mode == "build" &&
	((`rdb-stream` && `cannot parse row .*, invalid character 'F' looking for beginning of value`) ||
		log ~ `cannot parse row .*, invalid character 'F' looking for beginning of value`)
2024-01-23 00:04 x_sys-go1.20-linux-amd64-misccompile sys@c3fa2b8b release-branch.go1.20@a95136a8 [build] (log)

watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- mode == "build" &&
	((`rdb-stream` && `cannot parse row .*, invalid character 'F' looking for beginning of value`) ||
		log ~ `cannot parse row .*, invalid character 'F' looking for beginning of value`)
2024-05-13 16:40 x_telemetry-go1.21-darwin-amd64-nocgo telemetry@80019551 release-branch.go1.21@8fbd4d7b [build] (log)
[I2024-05-13T09:59:43.807945-07:00 58258 0 sink.go:276] SinkServer: warm-up started
[I2024-05-13T09:59:43.808510-07:00 58258 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-05-13T09:59:43.812076-07:00 58258 0 sink.go:281] SinkServer: warm-up ended
[I2024-05-13T09:59:43.812531-07:00 58258 0 cmd_stream.go:483] rdb-stream: starting the test command - ["/Users/swarming/.swarming/w/ir/cache/tools/bin/result_adapter" "go" "-v=false" "--" "/Users/swarming/.swarming/w/ir/x/w/goroot/bin/go" "test" "-json" "-short" "./..."]
# golang.org/x/telemetry/godev/cmd/telemetrygodev.test
panic: runtime error: index out of range [2147483135] with length 43

goroutine 1 [running]:
cmd/link/internal/loader.(*Loader).resolve(0x1264b60?, 0xc000054b10?, {0x1484b60?, 0x0?})
	cmd/link/internal/loader/loader.go:658 +0x179
...
panic: runtime error: index out of range [2147483135] with length 43

goroutine 1 [running]:
cmd/link/internal/loader.(*Loader).resolve(0x1264b60?, 0xc00076e390?, {0x1484b60?, 0x0?})
	cmd/link/internal/loader/loader.go:658 +0x179
cmd/link/internal/loader.Reloc.Sym(...)
	cmd/link/internal/loader/loader.go:61
cmd/link/internal/ld.(*deadcodePass).flood(0xc00014c920)
	cmd/link/internal/ld/deadcode.go:244 +0xbe5
cmd/link/internal/ld.deadcode(0xc000112200)
...
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-05-13T10:00:25.111127-07:00 58258 0 cmd_stream.go:479] rdb-stream: the test process terminated
[I2024-05-13T10:00:25.111446-07:00 58258 0 sink.go:371] SinkServer: shutdown started
[I2024-05-13T10:00:25.111540-07:00 58258 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-05-13T10:00:25.111567-07:00 58258 0 sink_server.go:95] SinkServer: draining TestResult channel started
[I2024-05-13T10:00:25.202052-07:00 58258 0 sink_server.go:97] SinkServer: draining TestResult channel ended
[I2024-05-13T10:00:25.202093-07:00 58258 0 sink_server.go:99] SinkServer: draining Artifact channel started
[I2024-05-13T10:00:25.297678-07:00 58258 0 sink_server.go:101] SinkServer: draining Artifact channel ended
[I2024-05-13T10:00:25.297724-07:00 58258 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-05-13T10:00:25.297769-07:00 58258 0 cmd_stream.go:411] rdb-stream: exiting with 1

watchflakes

@gopherbot gopherbot reopened this May 13, 2024
@dmitshur dmitshur changed the title x/build: LUCI builders fail with rdb-stream fail to parse FAIL message x/build/cmd/golangbuild: LUCI builders fail with rdb-stream fail to parse FAIL message May 14, 2024
@dmitshur
Copy link
Contributor

The problem appears to be in result_adapter, which is what's used to parse go test -json output and upload it to ResultDB. See:

https://source.chromium.org/chromium/infra/infra/+/main:go/src/infra/tools/result_adapter/go.go;l=107;drc=85566a4c3a814796e0f98fd0a0682fa178ddb268

Ultimately the underlying problem is that go test -json sometimes prints non-JSON output (e.g., for build errors). That will be resolved by #62067.

@dmitshur dmitshur added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 14, 2024
@dmitshur dmitshur changed the title x/build/cmd/golangbuild: LUCI builders fail with rdb-stream fail to parse FAIL message x/build/cmd/golangbuild: LUCI builders run into result_adapter fail to parse FAIL message when there's a build failure May 14, 2024
@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels May 14, 2024
@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- mode == "build" &&
	((`rdb-stream` && `cannot parse row .*, invalid character 'F' looking for beginning of value`) ||
		log ~ `cannot parse row .*, invalid character 'F' looking for beginning of value`)
2024-05-15 13:08 x_tools-go1.21-windows-arm64 tools@d40dfd59 release-branch.go1.21@0fa334d4 [build] (log)
[I2024-05-15T13:10:22.547428Z 25748 0 sink.go:276] SinkServer: warm-up started
[I2024-05-15T13:10:22.547428Z 25748 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-05-15T13:10:22.549631Z 25748 0 sink.go:281] SinkServer: warm-up ended
[I2024-05-15T13:10:22.550179Z 25748 0 cmd_stream.go:475] rdb-stream: starting the test command - ["C:\\Users\\swarming\\.swarming\\w\\ir\\cache\\tools\\bin\\result_adapter.exe" "go" "-v=false" "--" "C:\\Users\\swarming\\.swarming\\w\\ir\\x\\w\\goroot\\bin\\go" "test" "-json" "-short" "./..."]
# golang.org/x/tools/gopls/internal/protocol/command
runtime: VirtualAlloc of 32768 bytes failed with errno=1455
fatal error: out of memory

runtime stack:
runtime.throw({0x7ff7c63bfae2?, 0x4000088000?})
...
fatal error: out of memory

runtime stack:
runtime.throw({0x7ff7c63bfae2?, 0x4001079000?})
	runtime/panic.go:1077 +0x40 fp=0x9b879ff5d0 sp=0x9b879ff5a0 pc=0x7ff7c5b35880
runtime.sysUsedOS(0x4001078000, 0x2000)
	runtime/mem_windows.go:83 +0x17c fp=0x9b879ff630 sp=0x9b879ff5d0 pc=0x7ff7c5b0dd4c
runtime.sysUsed(...)
	runtime/mem.go:77
runtime.(*mheap).allocSpan(0x7ff7c6aa96a0, 0x1, 0x0, 0x0?)
...
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-05-15T13:10:39.402817Z 25748 0 cmd_stream.go:471] rdb-stream: the test process terminated
[I2024-05-15T13:10:39.402817Z 25748 0 sink.go:371] SinkServer: shutdown started
[I2024-05-15T13:10:39.402817Z 25748 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-05-15T13:10:39.402817Z 25748 0 sink_server.go:96] SinkServer: draining TestResult channel started
[I2024-05-15T13:10:39.503301Z 25748 0 sink_server.go:98] SinkServer: draining TestResult channel ended
[I2024-05-15T13:10:39.503301Z 25748 0 sink_server.go:100] SinkServer: draining Artifact channel started
[I2024-05-15T13:10:39.631277Z 25748 0 sink_server.go:102] SinkServer: draining Artifact channel ended
[I2024-05-15T13:10:39.631277Z 25748 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-05-15T13:10:39.631277Z 25748 0 cmd_stream.go:403] rdb-stream: exiting with 1

watchflakes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Builders x/build issues (builders, bots, dashboards) NeedsFix The path to resolution is known, but the work has not been done.
Projects
Status: Active
Development

No branches or pull requests

3 participants