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/build/internal/task: TestTagXRepos failures #56231

Closed
gopherbot opened this issue Oct 14, 2022 · 29 comments
Closed

x/build/internal/task: TestTagXRepos failures #56231

gopherbot opened this issue Oct 14, 2022 · 29 comments
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Unreleased

Comments

@gopherbot
Copy link
Contributor 

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"

Issue created automatically to collect these failures.

Example (log):

2022/10/14 09:11:08 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos3413242940/001/linux-amd64-longtest/0: 1 files, 1 dirs (1.770237ms)
2022/10/14 09:11:08 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos3413242940/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (1.167212ms)
--- FAIL: TestTagXRepos (10.01s)
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:464: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /Users/gopher/workdir/tmp/TestTagXRepos3413242940/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded

— watchflakes
@gopherbot gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 14, 2022
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-14 14:19 darwin-amd64-12_0 build@3481d34e go@a8ca70ff x/build/internal/task.TestTagXRepos (log) 
2022/10/14 09:11:08 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos3413242940/001/linux-amd64-longtest/0: 1 files, 1 dirs (1.770237ms)
2022/10/14 09:11:08 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos3413242940/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (1.167212ms)
--- FAIL: TestTagXRepos (10.01s)
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:464: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /Users/gopher/workdir/tmp/TestTagXRepos3413242940/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded

— watchflakes

@gopherbot gopherbot added the Builders x/build issues (builders, bots, dashboards) label Oct 14, 2022
@gopherbot gopherbot added this to the Unreleased milestone Oct 14, 2022
@heschi
Copy link
Contributor

heschi commented Oct 14, 2022

This test is entirely hermetic and runs in .074 seconds on my workstation, so I dunno what could've happened to cause it to take 100 times longer. If it happens again I suppose I can add timestamps to the log.

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-14 16:33 darwin-amd64-11_0 build@209d9014 go@9ddb8ea7 x/build/internal/task.TestTagXRepos (log) 
2022/10/14 14:10:29 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos1387298848/001/linux-amd64-longtest/0: 1 files, 1 dirs (756.304µs)
2022/10/14 14:10:29 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos1387298848/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (938.005µs)
--- FAIL: TestTagXRepos (10.01s)
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:464: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /Users/gopher/workdir/tmp/TestTagXRepos1387298848/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-14 22:12 darwin-amd64-12_0 build@1aa9c6a3 go@89566448 x/build/internal/task.TestTagXRepos (log) 
2022/10/14 15:21:39 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos4265959818/001/linux-amd64-longtest/0: 1 files, 1 dirs (789.312µs)
2022/10/14 15:21:39 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos4265959818/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (908.147µs)
--- FAIL: TestTagXRepos (10.01s)
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:464: task mod: wait for green post-submit: done: mod~0
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /Users/gopher/workdir/tmp/TestTagXRepos4265959818/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-17 17:51 darwin-amd64-11_0 build@13478d3d go@da6042e8 x/build/internal/task.TestTagXRepos (log) 
2022/10/17 10:54:00 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos513414571/001/linux-amd64-longtest/0: 1 files, 1 dirs (1.000036ms)
2022/10/17 10:54:00 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos513414571/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (953.872µs)
--- FAIL: TestTagXRepos (10.01s)
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [tools go sys mod]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] } {sys golang.org/x/sys [] } {mod golang.org/x/mod [] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:464: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /Users/gopher/workdir/tmp/TestTagXRepos513414571/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-17 20:08 darwin-amd64-10_15 build@16b8a7ce go@947091d3 x/build/internal/task.TestTagXRepos (log) 
2022/10/17 16:13:01 extracted tarball into /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos769089925/001/linux-amd64-longtest/0: 1 files, 1 dirs (751.157µs)
2022/10/17 16:13:01 extracted tarball into /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos769089925/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (761.692µs)
--- FAIL: TestTagXRepos (10.01s)
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos769089925/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-17 20:08 darwin-amd64-10_15 build@16b8a7ce go@947091d3 x/build/internal/task.TestTagXRepos (log) 
2022/10/17 16:31:14 extracted tarball into /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos1215779614/001/linux-amd64-longtest/0: 1 files, 1 dirs (779.39µs)
2022/10/17 16:31:14 extracted tarball into /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos1215779614/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (703.776µs)
--- FAIL: TestTagXRepos (10.01s)
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [mod tools go sys]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] } {sys golang.org/x/sys [] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:464: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos1215779614/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-18 17:49 darwin-amd64-12_0 build@fa98444b go@947091d3 x/build/internal/task.TestTagXRepos (log) 
2022/10/18 10:53:52 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos2810739213/001/linux-amd64-longtest/0: 1 files, 1 dirs (813.54µs)
2022/10/18 10:53:52 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos2810739213/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (753.878µs)
--- FAIL: TestTagXRepos (10.00s)
    tagx_test.go:480: task Select repositories: started
    tagx_test.go:480: task Create plan: started
    tagx_test.go:480: task Select repositories: started
    tagx_test.go:502: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:502: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:484: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:480: task Create plan: started
...
    tagx_test.go:480: task sys: tag if appropriate: started
    tagx_test.go:502: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:484: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:484: task mod: wait for green post-submit: done: mod~0
    tagx_test.go:480: task mod: tag if appropriate: started
    tagx_test.go:484: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:480: task tools: generate updated go.mod: started
    tagx_test.go:502: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /Users/gopher/workdir/tmp/TestTagXRepos2810739213/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:480: task tools: generate updated go.mod: started
    tagx_test.go:437: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Change https://go.dev/cl/444118 mentions this issue: internal/task: increase tagx test verbosity

gopherbot pushed a commit to golang/build that referenced this issue Oct 19, 2022
@heschi @gopherbot
internal/task: increase tagx test verbosity
0db1694 
I have no earthly idea why this script seems to be hanging for 10
seconds. Add more logging.

For golang/go#56231.

Change-Id: I473ae4856c58191c25c70d899520eed0f78738f2
Reviewed-on: https://go-review.googlesource.com/c/build/+/444118
Auto-Submit: Heschi Kreinick <heschi@google.com>
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Heschi Kreinick <heschi@google.com>
Reviewed-by: Dmitri Shuralyov <dmitshur@golang.org>
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-20 20:24 darwin-amd64-12_0 build@8be4277e go@2b21a27f x/build/internal/task.TestTagXRepos (log) 
2022/10/21 08:38:46 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos4074187584/001/linux-amd64-longtest/0: 1 files, 1 dirs (767.699µs)
2022/10/21 08:38:46 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos4074187584/001/linux-amd64-longtest/0/repo: 4 files, 2 dirs (1.916662ms)
--- FAIL: TestTagXRepos (10.00s)
    tagx_test.go:489: task Select repositories: started
    tagx_test.go:489: task Create plan: started
    tagx_test.go:489: task Select repositories: started
    tagx_test.go:511: 2022-10-21 08:38:46.498281 -0700 PDT m=+0.058261223	task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:511: 2022-10-21 08:38:46.498324 -0700 PDT m=+0.058303426	task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:493: task Select repositories: done: [{sys golang.org/x/sys []  } {mod golang.org/x/mod []  } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] 1.16 }]
    tagx_test.go:489: task Create plan: started
...
    tagx_test.go:489: task mod: tag if appropriate: started
    tagx_test.go:493: task mod: tag if appropriate: done: {mod golang.org/x/mod []  v1.0.0}
    tagx_test.go:493: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:489: task sys: tag if appropriate: started
    tagx_test.go:511: 2022-10-21 08:38:46.501611 -0700 PDT m=+0.061591353	task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:493: task sys: tag if appropriate: done: {sys golang.org/x/sys []  v0.2.0}
    tagx_test.go:489: task tools: generate updated go.mod: started
    tagx_test.go:511: 2022-10-21 08:38:56.498725 -0700 PDT m=+10.058704657	task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /Users/gopher/workdir/tmp/TestTagXRepos4074187584/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:489: task tools: generate updated go.mod: started
    tagx_test.go:439: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Change https://go.dev/cl/444797 mentions this issue: internal/task: increase TestTagXRepos timeout

gopherbot pushed a commit to golang/build that referenced this issue Oct 21, 2022
@heschi @gopherbot
internal/task: increase TestTagXRepos timeout
e987ab4 
The log writer flushes every ten seconds, so maybe the reason
https://build.golang.org/log/15994e2898dd9b9d16186fab7bbd4104312323c8
doesn't show any logs from the command is that the test exits too
quickly? Though it's also supposed to flush when the context finishes.
Which leaves me wondering why running bash just...hangs.

For golang/go#56231.

Change-Id: I55d54da191e1fe82036d7bbb28ab512a08bb7dd4
Reviewed-on: https://go-review.googlesource.com/c/build/+/444797
Auto-Submit: Heschi Kreinick <heschi@google.com>
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
Run-TryBot: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Dmitri Shuralyov <dmitshur@golang.org>
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2022-10-17 17:51 darwin-amd64-10_15 build@13478d3d go@b65e259e x/build/internal/task.TestTagXRepos (log) 
2022/10/17 15:22:33 extracted tarball into /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos3358866993/001/linux-amd64-longtest/0: 1 files, 1 dirs (748.034µs)
2022/10/17 15:22:33 extracted tarball into /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos3358866993/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (614.585µs)
--- FAIL: TestTagXRepos (10.00s)
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos3358866993/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded
2022-10-18 17:01 darwin-amd64-12_0 build@26f532d8 go@947091d3 x/build/internal/task.TestTagXRepos (log) 
2022/10/18 10:24:00 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos3133861687/001/linux-amd64-longtest/0: 1 files, 1 dirs (1.20168ms)
2022/10/18 10:24:00 extracted tarball into /Users/gopher/workdir/tmp/TestTagXRepos3133861687/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (762.237µs)
--- FAIL: TestTagXRepos (10.00s)
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:460: task Create plan: started
    tagx_test.go:460: task Select repositories: started
    tagx_test.go:482: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:482: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:464: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:460: task Create plan: started
...
    tagx_test.go:460: task sys: tag if appropriate: started
    tagx_test.go:482: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:464: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:464: task mod: wait for green post-submit: done: mod~0
    tagx_test.go:460: task mod: tag if appropriate: started
    tagx_test.go:464: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:482: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /Users/gopher/workdir/tmp/TestTagXRepos3133861687/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:460: task tools: generate updated go.mod: started
    tagx_test.go:417: context deadline exceeded
2022-10-18 17:49 darwin-amd64-10_15 build@fa98444b go@4fb35d6c x/build/internal/task.TestTagXRepos (log) 
2022/10/18 14:52:05 extracted tarball into /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos1794181244/001/linux-amd64-longtest/0: 1 files, 1 dirs (757.793µs)
2022/10/18 14:52:05 extracted tarball into /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos1794181244/001/linux-amd64-longtest/0/repo: 2 files, 1 dirs (835.819µs)
--- FAIL: TestTagXRepos (10.01s)
    tagx_test.go:480: task Select repositories: started
    tagx_test.go:480: task Create plan: started
    tagx_test.go:480: task Select repositories: started
    tagx_test.go:502: task Select repositories: LOG: Examining repositories [go sys mod tools]
    tagx_test.go:502: task Select repositories: LOG: ignoring go: no semver tag
    tagx_test.go:484: task Select repositories: done: [{sys golang.org/x/sys [] } {mod golang.org/x/mod [] } {tools golang.org/x/tools [golang.org/x/mod golang.org/x/sys] }]
    tagx_test.go:480: task Create plan: started
...
    tagx_test.go:480: task mod: tag if appropriate: started
    tagx_test.go:484: task sys: wait for green post-submit: done: sys~1
    tagx_test.go:480: task sys: tag if appropriate: started
    tagx_test.go:502: task sys: tag if appropriate: LOG: Waiting for approval to tag sys at sys~1 as v0.2.0
    tagx_test.go:484: task sys: tag if appropriate: done: {sys golang.org/x/sys [] v0.2.0}
    tagx_test.go:484: task mod: tag if appropriate: done: {mod golang.org/x/mod [] v1.0.0}
    tagx_test.go:480: task tools: generate updated go.mod: started
    tagx_test.go:502: task tools: generate updated go.mod: LOG: task failed, will retry (1 of 3): command /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-amd64-10_15/tmp/TestTagXRepos1794181244/001/linux-amd64-longtest/0/go/bin/go [get golang.org/x/mod@v1.0.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: ""
    tagx_test.go:480: task tools: generate updated go.mod: started
    tagx_test.go:437: context deadline exceeded

— watchflakes

@dmitshur
Copy link
Contributor

dmitshur commented Sep 7, 2023

Hasn't happened since the increased timeout.

@dmitshur dmitshur closed this as completed Sep 7, 2023
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-08-31 17:14 darwin-amd64-13 build@5d89b9d9 go@9dea791a x/build/internal/task.TestTagXRepos (log) 
2023/08/31 13:24:39 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetryno_existing_tag2763471871/002/linux-amd64/0/work: 1 files, 1 dirs (4.944884ms)
2023/08/31 13:24:39 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetryno_existing_tag2763471871/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (11.083796ms)
2023/08/31 13:24:41 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrygenerated_tag62779510/002/linux-amd64/0/work: 1 files, 1 dirs (2.227732ms)
2023/08/31 13:24:41 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrygenerated_tag62779510/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (10.761088ms)
2023/08/31 13:24:44 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrymaster_tag203105234/002/linux-amd64/0/work: 1 files, 1 dirs (3.007252ms)
2023/08/31 13:24:44 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrymaster_tag203105234/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (8.542526ms)
2023/08/31 13:24:55 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos4112207291/005/linux-amd64-longtest/0/work: 1 files, 1 dirs (1.992929ms)
2023/08/31 13:25:02 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos4112207291/005/linux-amd64-longtest/0/work/repo: 4 files, 2 dirs (6.57550414s)
--- FAIL: TestTagXRepos (69.25s)
    tagx_test.go:584: task Create plan: started
...
    tagx_test.go:606: 2023-08-31 13:25:46.028391 -0400 EDT m=+67.754473942	task tools: wait for submit: LOG: Awaiting review/submit of (unparseable change ID "cl_700db36c364589c88b5018ca27674ec215004c03")
    tagx_test.go:588: task tools: wait for submit: done: 700db36c364589c88b5018ca27674ec215004c03
    tagx_test.go:584: task tools: wait for green post-submit: started
    tagx_test.go:606: 2023-08-31 13:25:51.527982 -0400 EDT m=+73.254065107	task tools: wait for green post-submit: LOG: task failed, will retry (1 of 3): git command failed: signal: killed, stderr 
    tagx_test.go:584: task tools: wait for green post-submit: started
    tagx_test.go:470: context deadline exceeded
2023/08/31 13:25:58 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowith_post-submit_check1242213331/004/linux-amd64-longtest/0/work: 1 files, 1 dirs (951.913µs)
2023/08/31 13:25:58 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowith_post-submit_check1242213331/004/linux-amd64-longtest/0/work/repo: 3 files, 1 dirs (7.057258ms)
2023/08/31 13:26:03 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowithout_post-submit_check3117222812/004/linux-amd64-longtest/0/work: 1 files, 1 dirs (4.052696ms)
2023/08/31 13:26:03 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowithout_post-submit_check3117222812/004/linux-amd64-longtest/0/work/repo: 3 files, 1 dirs (6.126522ms)
2023-09-07 15:49 darwin-amd64-13 build@fedf1c1d go@a35bb44a x/build/internal/task.TestTagXRepos (log) 
2023/09/08 05:59:26 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetryno_existing_tag1717827512/002/linux-amd64/0/work: 1 files, 1 dirs (1.10199ms)
2023/09/08 05:59:26 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetryno_existing_tag1717827512/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (8.513722ms)
2023/09/08 05:59:28 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrygenerated_tag504321571/002/linux-amd64/0/work: 1 files, 1 dirs (848.054µs)
2023/09/08 05:59:29 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrygenerated_tag504321571/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (14.430323ms)
2023/09/08 05:59:31 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrymaster_tag2398821279/002/linux-amd64/0/work: 1 files, 1 dirs (2.173467ms)
2023/09/08 05:59:31 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrymaster_tag2398821279/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (6.91174ms)
2023/09/08 05:59:43 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos3804835640/006/linux-amd64-longtest/0/work: 1 files, 1 dirs (4.213852ms)
2023/09/08 05:59:43 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos3804835640/006/linux-amd64-longtest/0/work/repo: 4 files, 2 dirs (4.707187ms)
2023/09/08 05:59:54 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos3804835640/006/linux-amd64-longtest/1/work: 1 files, 1 dirs (1.723191093s)
2023/09/08 06:00:09 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos3804835640/006/linux-amd64-longtest/1/work/repo: 2 files, 1 dirs (11.339621043s)
--- FAIL: TestTagXRepos (64.72s)
    tagx_test.go:614: task Select repositories: started
    tagx_test.go:614: task Create plan: started
    tagx_test.go:614: task Select repositories: started
    tagx_test.go:636: 2023-09-08 05:59:35.996894 -0400 EDT m=+10.802624672	task Select repositories: LOG: Examining repositories [sys mod tools build]
    tagx_test.go:618: task Select repositories: done: [{sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc00011cae0 0xc00011cb10 0xc00011cb40] 1.16 v1.1.5 } {build golang.org/x/build [0xc00011cb58 0xc00011cb70]   }]
    tagx_test.go:614: task Create plan: started
    tagx_test.go:618: task Create plan: done: <nil>
    tagx_test.go:614: task sys: read branch head: started
    tagx_test.go:614: task mod: wait for green post-submit: started
...
    tagx_test.go:618: task build: wait for submit: done: 244b0f539d57ead79a94a214c58783827e8bcb93
    tagx_test.go:614: task build: don't tag: started
    tagx_test.go:618: task build: don't tag: done: {build golang.org/x/build [0xc0006f2ba0 0xc0006f2bd0]   }
    tagx_test.go:614: task done      : started
    tagx_test.go:618: task done      : done: done!
    tagx_test.go:495: git command failed: signal: killed, stderr 
2023/09/08 06:00:41 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowith_post-submit_check88059146/004/linux-amd64-longtest/0/work: 1 files, 1 dirs (2.848382ms)
2023/09/08 06:00:41 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowith_post-submit_check88059146/004/linux-amd64-longtest/0/work/repo: 3 files, 1 dirs (2.990346ms)
2023/09/08 06:00:46 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowithout_post-submit_check3837290127/004/linux-amd64-longtest/0/work: 1 files, 1 dirs (10.233202ms)
2023/09/08 06:00:46 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowithout_post-submit_check3837290127/004/linux-amd64-longtest/0/work/repo: 3 files, 1 dirs (2.706626ms)

— watchflakes

@bcmills bcmills mentioned this issue Sep 26, 2023
Closed
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-09-22 10:29 darwin-amd64-12_0 build@d5438a6b go@c8caad42 x/build/internal/task.TestTagXRepos (log) 
2023/09/22 22:25:17 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetryno_existing_tag3205278577/002/linux-amd64/0/work: 1 files, 1 dirs (7.561797ms)
2023/09/22 22:25:17 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetryno_existing_tag3205278577/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (14.023277ms)
2023/09/22 22:25:19 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrygenerated_tag295109502/002/linux-amd64/0/work: 1 files, 1 dirs (689.267µs)
2023/09/22 22:25:19 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrygenerated_tag295109502/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (10.356072ms)
2023/09/22 22:25:22 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrymaster_tag1494825246/002/linux-amd64/0/work: 1 files, 1 dirs (2.832608ms)
2023/09/22 22:25:22 extracted tarball into /tmp/buildlet/tmp/TestTagTelemetrymaster_tag1494825246/002/linux-amd64/0/work/telemetry: 6 files, 3 dirs (8.590645ms)
2023/09/22 22:25:33 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos3798202465/006/linux-amd64-longtest/0/work: 1 files, 1 dirs (2.622365ms)
2023/09/22 22:25:34 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos3798202465/006/linux-amd64-longtest/0/work/repo: 4 files, 2 dirs (97.478236ms)
2023/09/22 22:26:24 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos3798202465/006/linux-amd64-longtest/1/work: 1 files, 1 dirs (1.053135ms)
2023/09/22 22:26:27 extracted tarball into /tmp/buildlet/tmp/TestTagXRepos3798202465/006/linux-amd64-longtest/1/work/repo: 2 files, 1 dirs (583.653224ms)
--- FAIL: TestTagXRepos (85.89s)
    tagx_test.go:614: task Create plan: started
    tagx_test.go:614: task Select repositories: started
    tagx_test.go:614: task Select repositories: started
    tagx_test.go:636: 2023-09-22 22:25:27.771159 -0700 PDT m=+14.442557316	task Select repositories: LOG: Examining repositories [build sys mod tools]
    tagx_test.go:618: task Select repositories: done: [{build golang.org/x/build [0xc00028c9d8 0xc00028c9f0]   } {sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc00028ca08 0xc00028ca20 0xc00028ca38] 1.16 v1.1.5 }]
    tagx_test.go:614: task Create plan: started
    tagx_test.go:618: task Create plan: done: <nil>
    tagx_test.go:614: task done      : started
    tagx_test.go:614: task tools: wait for green post-submit: started
...
    tagx_test.go:636: 2023-09-22 22:26:17.401691 -0700 PDT m=+64.073089417	task tools: tag if appropriate: LOG: Tagging tools at 7151dad63e8d21f8d4939c354c9c3742013671d3 as v1.2.0
    tagx_test.go:618: task tools: tag if appropriate: done: {tools golang.org/x/tools [0xc000013230 0xc000013248 0xc000013260] 1.16 v1.1.5 v1.2.0}
    tagx_test.go:614: task build: generate go.mod: started
    tagx_test.go:636: 2023-09-22 22:26:28.275025 -0700 PDT m=+74.946424044	task build: generate go.mod: LOG: task failed, will retry (1 of 3): command /tmp/buildlet/tmp/TestTagXRepos3798202465/006/linux-amd64-longtest/1/work/go/bin/go [get golang.org/x/tools@v1.2.0 golang.org/x/sys@v0.2.0] failed: signal: killed output: "+ case \"$1\" in\n"
    tagx_test.go:614: task build: generate go.mod: started
    tagx_test.go:482: context deadline exceeded
2023/09/22 22:26:53 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowith_post-submit_check1324408354/004/linux-amd64-longtest/0/work: 1 files, 1 dirs (5.070303ms)
2023/09/22 22:26:54 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowith_post-submit_check1324408354/004/linux-amd64-longtest/0/work/repo: 3 files, 1 dirs (10.460098ms)
2023/09/22 22:26:58 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowithout_post-submit_check830871152/004/linux-amd64-longtest/0/work: 1 files, 1 dirs (2.372234ms)
2023/09/22 22:26:58 extracted tarball into /tmp/buildlet/tmp/TestTagSingleRepowithout_post-submit_check830871152/004/linux-amd64-longtest/0/work/repo: 3 files, 1 dirs (1.876413ms)
2023-09-22 19:29 darwin-amd64-12_0 build@433076bf go@de3bae19 x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (65.35s)
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-09-25 20:39:18.905557 -0700 PDT m=+11.981991598	task Select repositories: LOG: Examining repositories [mod tools build sys]
    tagx_test.go:605: task Select repositories: done: [{mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc0007cc210 0xc0007cc228 0xc0007cc240] 1.16 v1.1.5 } {build golang.org/x/build [0xc0007cc258 0xc0007cc270]   } {sys golang.org/x/sys []  v0.1.0 }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task tools: wait for submit: started
    tagx_test.go:601: task tools: generate go.mod: started
...
        ]
    tagx_test.go:601: task tools: mail go.mod: started
    tagx_test.go:605: task tools: mail go.mod: done: cl_7bcf32cefff813a6866965fe313deda91a54de37
    tagx_test.go:601: task tools: wait for submit: started
    tagx_test.go:623: 2023-09-25 20:40:18.866756 -0700 PDT m=+71.943191019	task tools: wait for submit: LOG: Awaiting review/submit of (unparseable change ID "cl_7bcf32cefff813a6866965fe313deda91a54de37")
    tagx_test.go:605: task tools: wait for submit: done: 7bcf32cefff813a6866965fe313deda91a54de37
    tagx_test.go:601: task tools: wait for green post-submit: started
    tagx_test.go:623: 2023-09-25 20:40:18.917388 -0700 PDT m=+71.993822320	task tools: wait for green post-submit: LOG: task failed, will retry (1 of 3): listing project "tools" tags: git command failed: signal: killed, stderr 
    tagx_test.go:601: task tools: wait for green post-submit: started
    tagx_test.go:469: context deadline exceeded

— watchflakes

@gopherbot gopherbot reopened this Sep 26, 2023
@heschi
Copy link
Contributor

heschi commented Sep 26, 2023

As before, I'm pretty confused as to why it would take over 10 seconds to run a short shell script :(

It should be running https://cs.opensource.google/go/x/build/+/master:internal/relui/buildrelease_test.go;l=68-91;drc=40ab14c32b0916a01329a1cde45bde9fb3296118, and given this log:

signal: killed output: "+ case \"$1\" in\n"

the hanging command is most likely a simple ls.

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-09-27 02:35 darwin-amd64-12_0 build@5d3521b0 go@5152be39 x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (91.31s)
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-09-26 19:45:02.074048 -0700 PDT m=+15.875628018	task Select repositories: LOG: Examining repositories [sys mod tools build]
    tagx_test.go:605: task Select repositories: done: [{sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc00056cde0 0xc00056cdf8 0xc00056ce10] 1.16 v1.1.5 } {build golang.org/x/build [0xc00056ce28 0xc00056ce40]   }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task tools: mail go.mod: started
    tagx_test.go:601: task sys: wait for green post-submit: started
...
    tagx_test.go:601: task mod: tag if appropriate: started
    tagx_test.go:605: task mod: tag if appropriate: done: {mod golang.org/x/mod []  v1.0.0 v1.0.0}
    tagx_test.go:605: task sys: wait for green post-submit: done: 809e1dc4a09ba8203e68d1ece8e097c7e38ecbb0
    tagx_test.go:601: task sys: tag if appropriate: started
    tagx_test.go:623: 2023-09-26 19:45:19.441705 -0700 PDT m=+33.243285100	task sys: tag if appropriate: LOG: Tagging sys at 809e1dc4a09ba8203e68d1ece8e097c7e38ecbb0 as v0.2.0
    tagx_test.go:605: task sys: tag if appropriate: done: {sys golang.org/x/sys []  v0.1.0 v0.2.0}
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:623: 2023-09-26 19:46:02.164881 -0700 PDT m=+75.966460579	task tools: generate go.mod: LOG: task failed, will retry (1 of 3): git command failed: signal: killed, stderr Cloning into '/tmp/buildlet/tmp/relui-git-clone-3463493718'...
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:469: context deadline exceeded
2023-09-27 02:35 darwin-amd64-12_0 build@5d3521b0 go@a15ef1bb x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (79.41s)
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-09-26 19:47:34.300647 -0700 PDT m=+18.494665009	task Select repositories: LOG: Examining repositories [sys mod tools build]
    tagx_test.go:605: task Select repositories: done: [{sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc000544450 0xc000544480 0xc000544498] 1.16 v1.1.5 } {build golang.org/x/build [0xc0005444b0 0xc0005444c8]   }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task build: mail go.mod: started
    tagx_test.go:601: task build: wait for submit: started
...
    tagx_test.go:601: task mod: tag if appropriate: started
    tagx_test.go:605: task mod: tag if appropriate: done: {mod golang.org/x/mod []  v1.0.0 v1.0.0}
    tagx_test.go:605: task sys: wait for green post-submit: done: 475d426cd4f392776f380a4b2b38a6ab7dbef7b6
    tagx_test.go:601: task sys: tag if appropriate: started
    tagx_test.go:623: 2023-09-26 19:48:17.857991 -0700 PDT m=+62.052009153	task sys: tag if appropriate: LOG: Tagging sys at 475d426cd4f392776f380a4b2b38a6ab7dbef7b6 as v0.2.0
    tagx_test.go:605: task sys: tag if appropriate: done: {sys golang.org/x/sys []  v0.1.0 v0.2.0}
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:623: 2023-09-26 19:48:34.45264 -0700 PDT m=+78.646658432	task tools: generate go.mod: LOG: task failed, will retry (1 of 3): git command failed: signal: killed, stderr Cloning into '/tmp/buildlet/tmp/relui-git-clone-3607395922'...
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:469: context deadline exceeded

— watchflakes

@bcmills
Copy link
Contributor

bcmills commented Sep 27, 2023 •
edited
Loading

These are all on darwin/amd64? There is what I suspect to be a platform or runtime bug affecting subprocesses on that platform (#54461 (comment)).

@bcmills bcmills mentioned this issue Sep 27, 2023
Open
@bcmills
Copy link
Contributor

bcmills commented Sep 27, 2023

(That said, that shell script as it stands is probably going to be flaky due to #22315. 😅)

@bcmills
Copy link
Contributor

bcmills commented Sep 27, 2023

To try to narrow it down I would suggest removing the context.WithTimeout and just letting the test time out on its own to dump goroutines. If this is in the same cluster as #54461 (comment) I would expect to see a goroutine stuck in io.copyBuffer via an os/exec.(*Cmd).writerDescriptor closure.

@bcmills bcmills mentioned this issue Sep 27, 2023
Closed
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-09-28 19:51 darwin-amd64-12_0 build@7f885397 go@a15ef1bb x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (106.41s)
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-09-28 13:04:26.217152 -0700 PDT m=+11.151183749	task Select repositories: LOG: Examining repositories [sys mod tools build]
    tagx_test.go:605: task Select repositories: done: [{sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc00058ac90 0xc00058aca8 0xc00058acc0] 1.16 v1.1.5 } {build golang.org/x/build [0xc00058acd8 0xc00058acf0]   }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task tools: mail go.mod: started
    tagx_test.go:601: task tools: tag if appropriate: started
...
    tagx_test.go:601: task mod: tag if appropriate: started
    tagx_test.go:605: task mod: tag if appropriate: done: {mod golang.org/x/mod []  v1.0.0 v1.0.0}
    tagx_test.go:605: task sys: wait for green post-submit: done: e8d03c793fc15f129f6f053fa4bbb1e24a2d78ea
    tagx_test.go:601: task sys: tag if appropriate: started
    tagx_test.go:623: 2023-09-28 13:04:28.199468 -0700 PDT m=+13.133499889	task sys: tag if appropriate: LOG: Tagging sys at e8d03c793fc15f129f6f053fa4bbb1e24a2d78ea as v0.2.0
    tagx_test.go:605: task sys: tag if appropriate: done: {sys golang.org/x/sys []  v0.1.0 v0.2.0}
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:623: 2023-09-28 13:05:26.729534 -0700 PDT m=+71.663565076	task tools: generate go.mod: LOG: task failed, will retry (1 of 3): git command failed: signal: killed, stderr Cloning into '/tmp/buildlet/tmp/relui-git-clone-29127588'...
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:469: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-09-28 19:51 darwin-amd64-12_0 build@7f885397 go@fa4f9510 x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (76.08s)
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-09-29 12:37:00.074804 -0700 PDT m=+13.879835326	task Select repositories: LOG: Examining repositories [sys mod tools build]
    tagx_test.go:605: task Select repositories: done: [{sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc000114e88 0xc000114ea0 0xc000114eb8] 1.16 v1.1.5 } {build golang.org/x/build [0xc000114ed0 0xc000114ee8]   }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task sys: wait for green post-submit: started
    tagx_test.go:601: task mod: read branch head: started
...
    tagx_test.go:601: task mod: tag if appropriate: started
    tagx_test.go:605: task mod: tag if appropriate: done: {mod golang.org/x/mod []  v1.0.0 v1.0.0}
    tagx_test.go:605: task sys: wait for green post-submit: done: ecbcccd5010ff295b9fa481ea074afb948458fce
    tagx_test.go:601: task sys: tag if appropriate: started
    tagx_test.go:623: 2023-09-29 12:37:31.740866 -0700 PDT m=+45.545897929	task sys: tag if appropriate: LOG: Tagging sys at ecbcccd5010ff295b9fa481ea074afb948458fce as v0.2.0
    tagx_test.go:605: task sys: tag if appropriate: done: {sys golang.org/x/sys []  v0.1.0 v0.2.0}
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:623: 2023-09-29 12:38:00.623179 -0700 PDT m=+74.428211368	task tools: generate go.mod: LOG: task failed, will retry (1 of 3): git command failed: signal: killed, stderr Cloning into '/tmp/buildlet/tmp/relui-git-clone-2607998828'...
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:469: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-10-02 13:54 darwin-amd64-12_0 build@39811cbf go@a15ef1bb x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (77.42s)
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-10-02 10:37:56.875648 -0700 PDT m=+13.342045064	task Select repositories: LOG: Examining repositories [build sys mod tools]
    tagx_test.go:605: task Select repositories: done: [{build golang.org/x/build [0xc000ac07c8 0xc000ac07e0]   } {sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc000ac07f8 0xc000ac0810 0xc000ac0828] 1.16 v1.1.5 }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task tools: tag if appropriate: started
    tagx_test.go:601: task sys: read branch head: started
...
        tidied! mod tidy -compat 1.16
         go.sum:
        golang.org/x/mod v1.0.0 h1:asdasd
        golang.org/x/sys v0.2.0 h1:asdasd
         gopls/go.mod:module golang.org/x/tools/gopls
        require golang.org/x/mod v1.0.0
        tidied! mod tidy -compat 1.16
         gopls/go.sum:
        ]
    tagx_test.go:469: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-10-03 21:14 darwin-amd64-12_0 build@821668f7 go@83dce459 x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (63.68s)
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-10-03 17:02:30.707969 -0700 PDT m=+11.176803199	task Select repositories: LOG: Examining repositories [sys mod tools build]
    tagx_test.go:605: task Select repositories: done: [{sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc000528648 0xc000528660 0xc000528678] 1.16 v1.1.5 } {build golang.org/x/build [0xc0005286a8 0xc0005286c0]   }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task build: generate go.mod: started
    tagx_test.go:601: task tools: tag if appropriate: started
...
    tagx_test.go:601: task build: mail go.mod: started
    tagx_test.go:605: task build: mail go.mod: done: cl_2c27e87eaf33295236837707a34e6bd2c9820e7b
    tagx_test.go:601: task build: wait for submit: started
    tagx_test.go:623: 2023-10-03 17:03:30.461998 -0700 PDT m=+70.930832406	task build: wait for submit: LOG: Awaiting review/submit of (unparseable change ID "cl_2c27e87eaf33295236837707a34e6bd2c9820e7b")
    tagx_test.go:605: task build: wait for submit: done: 2c27e87eaf33295236837707a34e6bd2c9820e7b
    tagx_test.go:601: task build: don't tag: started
    tagx_test.go:605: task build: don't tag: done: {build golang.org/x/build [0xc0006cb200 0xc0006cb218]   }
    tagx_test.go:601: task done      : started
    tagx_test.go:605: task done      : done: done!
    tagx_test.go:512: git command failed: context deadline exceeded, stderr

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-10-04 18:06 darwin-amd64-12_0 build@4772d0e4 go@e47cab13 x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (64.67s)
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-10-04 11:29:07.030649 -0700 PDT m=+12.667482300	task Select repositories: LOG: Examining repositories [mod tools build sys]
    tagx_test.go:605: task Select repositories: done: [{mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc0006948e8 0xc000694900 0xc000694918] 1.16 v1.1.5 } {build golang.org/x/build [0xc000694930 0xc000694948]   } {sys golang.org/x/sys []  v0.1.0 }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task tools: tag if appropriate: started
    tagx_test.go:601: task build: mail go.mod: started
...
    tagx_test.go:601: task tools: wait for green post-submit: started
    tagx_test.go:605: task tools: wait for green post-submit: done: 5738e13e33d872b6a93dc18e72a3262929142cd8
    tagx_test.go:601: task tools: tag if appropriate: started
    tagx_test.go:623: 2023-10-04 11:30:06.009587 -0700 PDT m=+71.646420744	task tools: tag if appropriate: LOG: Tagging tools at 5738e13e33d872b6a93dc18e72a3262929142cd8 as v1.2.0
    tagx_test.go:605: task tools: tag if appropriate: done: {tools golang.org/x/tools [0xc000694630 0xc000694648 0xc000694660] 1.16 v1.1.5 v1.2.0}
    tagx_test.go:601: task build: generate go.mod: started
    tagx_test.go:623: 2023-10-04 11:30:07.052786 -0700 PDT m=+72.689619971	task build: generate go.mod: LOG: task failed, will retry (1 of 3): git command failed: signal: killed, stderr Cloning into '/tmp/buildlet/tmp/relui-git-clone-553727786'...
        done.
    tagx_test.go:601: task build: generate go.mod: started
    tagx_test.go:469: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2023-10-03 21:14 darwin-amd64-12_0 build@821668f7 go@a9036396 x/build/internal/task.TestTagXRepos (log) 
--- FAIL: TestTagXRepos (65.49s)
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:601: task Create plan: started
    tagx_test.go:601: task Select repositories: started
    tagx_test.go:623: 2023-10-04 18:08:46.374458 -0700 PDT m=+13.986602872	task Select repositories: LOG: Examining repositories [sys mod tools build]
    tagx_test.go:605: task Select repositories: done: [{sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc000740ed0 0xc000740ee8 0xc000740f00] 1.16 v1.1.5 } {build golang.org/x/build [0xc000740f18 0xc000740f30]   }]
    tagx_test.go:601: task Create plan: started
    tagx_test.go:605: task Create plan: done: <nil>
    tagx_test.go:601: task mod: tag if appropriate: started
    tagx_test.go:601: task sys: wait for green post-submit: started
...
    tagx_test.go:601: task mod: tag if appropriate: started
    tagx_test.go:605: task mod: tag if appropriate: done: {mod golang.org/x/mod []  v1.0.0 v1.0.0}
    tagx_test.go:605: task sys: wait for green post-submit: done: 59b99114bb263517b745cbe8b1a35745134ba7b4
    tagx_test.go:601: task sys: tag if appropriate: started
    tagx_test.go:623: 2023-10-04 18:08:59.348955 -0700 PDT m=+26.961100223	task sys: tag if appropriate: LOG: Tagging sys at 59b99114bb263517b745cbe8b1a35745134ba7b4 as v0.2.0
    tagx_test.go:605: task sys: tag if appropriate: done: {sys golang.org/x/sys []  v0.1.0 v0.2.0}
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:623: 2023-10-04 18:09:46.646396 -0700 PDT m=+74.258541211	task tools: generate go.mod: LOG: task failed, will retry (1 of 3): git command failed: signal: killed, stderr Cloning into '/tmp/buildlet/tmp/relui-git-clone-382914932'...
    tagx_test.go:601: task tools: generate go.mod: started
    tagx_test.go:469: context deadline exceeded

— watchflakes

@gopherbot
Copy link
Contributor Author

Change https://go.dev/cl/533098 mentions this issue: internal/task: remove context timeout

@bcmills bcmills mentioned this issue Oct 25, 2023
Closed
@bcmills bcmills mentioned this issue Nov 3, 2023
Open
@gopherbot gopherbot reopened this Feb 27, 2024
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/build/internal/task" && test == "TestTagXRepos"
2024-02-26 16:54 x_build-go1.21-darwin-amd64_12 build@73351bfb release-branch.go1.21@f38fca30 x/build/internal/task.TestTagXRepos [ABORT] (log) 
=== RUN   TestTagXRepos
    tagx_test.go:464: task Create plan: started
    tagx_test.go:464: task Select repositories: started
    tagx_test.go:464: task Select repositories: started
    tagx_test.go:486: 2024-02-26 09:10:59.151103 -0800 PST m=+56.082244823	task Select repositories: LOG: Examining repositories [sys mod tools build]
    tagx_test.go:468: task Select repositories: done: [{sys golang.org/x/sys []  v0.1.0 } {mod golang.org/x/mod []  v1.0.0 } {tools golang.org/x/tools [0xc00067ede0 0xc00067edf8 0xc00067ee10] 1.16 v1.1.5 } {build golang.org/x/build [0xc00067ee28 0xc00067ee40]   }]
    tagx_test.go:464: task Create plan: started
    tagx_test.go:468: task Create plan: done: <nil>
    tagx_test.go:464: task mod: tag if appropriate: started
    tagx_test.go:464: task tools: mail go.mod: started
...
panic: test timed out after 10m0s
running tests:
	TestTagXRepos (9m26s)

goroutine 399 [running]:
testing.(*M).startAlarm.func1()
	/Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2259 +0x3b9
created by time.goFunc
	/Users/swarming/.swarming/w/ir/x/w/goroot/src/time/sleep.go:176 +0x2d

...
net.(*TCPListener).accept(0xc000634b80)
	/Users/swarming/.swarming/w/ir/x/w/goroot/src/net/tcpsock_posix.go:152 +0x1e
net.(*TCPListener).Accept(0xc000634b80)
	/Users/swarming/.swarming/w/ir/x/w/goroot/src/net/tcpsock.go:315 +0x30
net/http.(*Server).Serve(0xc000678780, {0x1f77030, 0xc000634b80})
	/Users/swarming/.swarming/w/ir/x/w/goroot/src/net/http/server.go:3056 +0x364
net/http/httptest.(*Server).goServe.func1()
	/Users/swarming/.swarming/w/ir/x/w/goroot/src/net/http/httptest/server.go:310 +0x5b
created by net/http/httptest.(*Server).goServe in goroutine 349
	/Users/swarming/.swarming/w/ir/x/w/goroot/src/net/http/httptest/server.go:308 +0x65

— watchflakes

@dmitshur
Copy link
Contributor

/bin/bash: /bin/ls: Device error

Looks like a general instance of #65040 rather than something specific to this test.

@golang golang locked and limited conversation to collaborators Feb 27, 2025
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Go Release
Archived in project
Test Flakes
Archived in project
Milestone
Unreleased
Development

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