x/build/internal/task: TestTagSingleRepo failures with `context deadline exceeded` on `darwin`

[gopherbot]

#!watchflakes
post <- goos == "darwin" && pkg == "golang.org/x/build/internal/task" && test == "TestTagSingleRepo" && `context deadline exceeded`

Issue created automatically to collect these failures.

Example (log):

--- FAIL: TestTagSingleRepo (75.05s)
    --- FAIL: TestTagSingleRepo/with_post-submit_check (67.83s)
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-10-13 14:32:57.943484 -0400 EDT m=+33.101469599	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc000134be8]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:600: task foo: wait for green post-submit: started
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:604: task foo: generate go.mod: done: map[go.mod:module golang.org/x/foo
            require golang.org/x/mod v1.0.0
            // pretend we've upgraded to golang.org/x/mod@v1.1.0
            tidied! mod tidy
             go.sum:
            golang.org/x/mod v1.1.0 h1:asdasd
            ]
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:604: task foo: mail go.mod: done: cl_47cda033de1c1ecb1e1bdfbf79caec0ba063adfe
        tagx_test.go:565: context deadline exceeded

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2023-10-13 18:22 darwin-amd64-13 build@f5e0fb4e go@d4863909 x/build/internal/task.TestTagSingleRepo (log)

--- FAIL: TestTagSingleRepo (75.05s)
    --- FAIL: TestTagSingleRepo/with_post-submit_check (67.83s)
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-10-13 14:32:57.943484 -0400 EDT m=+33.101469599	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc000134be8]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:600: task foo: wait for green post-submit: started
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:604: task foo: generate go.mod: done: map[go.mod:module golang.org/x/foo
            require golang.org/x/mod v1.0.0
            // pretend we've upgraded to golang.org/x/mod@v1.1.0
            tidied! mod tidy
             go.sum:
            golang.org/x/mod v1.1.0 h1:asdasd
            ]
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:604: task foo: mail go.mod: done: cl_47cda033de1c1ecb1e1bdfbf79caec0ba063adfe
        tagx_test.go:565: context deadline exceeded

2023-10-14 00:37 darwin-amd64-12_0 build@49880869 go@c75a617a x/build/internal/task.TestTagSingleRepo (log)

--- FAIL: TestTagSingleRepo (91.35s)
    --- FAIL: TestTagSingleRepo/without_post-submit_check (86.74s)
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-10-20 17:53:58.15064 -0700 PDT m=+61.019222299	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc00064b2f0]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:604: task foo: generate go.mod: done: map[go.mod:module golang.org/x/foo
            require golang.org/x/mod v1.0.0
            // pretend we've upgraded to golang.org/x/mod@v1.1.0
            tidied! mod tidy
             go.sum:
            golang.org/x/mod v1.1.0 h1:asdasd
            ]
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:604: task foo: mail go.mod: done: cl_d84b81ea96b5b6d6776d505ae8040565a027fde5
        tagx_test.go:565: context deadline exceeded

2023-10-14 00:37 darwin-amd64-12_0 build@49880869 go@d580460f x/build/internal/task.TestTagSingleRepo (log)

--- FAIL: TestTagSingleRepo (100.26s)
    --- FAIL: TestTagSingleRepo/without_post-submit_check (95.01s)
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-10-18 12:23:56.747321 -0700 PDT m=+107.656931551	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc00077e120]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:604: task foo: generate go.mod: done: map[go.mod:module golang.org/x/foo
            require golang.org/x/mod v1.0.0
            // pretend we've upgraded to golang.org/x/mod@v1.1.0
            tidied! mod tidy
             go.sum:
            golang.org/x/mod v1.1.0 h1:asdasd
            ]
        tagx_test.go:565: context deadline exceeded

2023-10-14 00:37 darwin-amd64-13 build@49880869 go@566d94fe x/build/internal/task.TestTagSingleRepo (log)

--- FAIL: TestTagSingleRepo (79.21s)
    --- FAIL: TestTagSingleRepo/without_post-submit_check (74.21s)
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-10-20 17:04:22.78323 -0400 EDT m=+44.808534174	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc0003c30c8]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:604: task foo: generate go.mod: done: map[go.mod:module golang.org/x/foo
            require golang.org/x/mod v1.0.0
            // pretend we've upgraded to golang.org/x/mod@v1.1.0
            tidied! mod tidy
             go.sum:
            golang.org/x/mod v1.1.0 h1:asdasd
            ]
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:604: task foo: mail go.mod: done: cl_5bd9cf78d42e1fbc180f05f686da064fb93c310b
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:622: 2023-10-20 17:05:18.361834 -0400 EDT m=+100.387139544	task foo: wait for submit: LOG: Awaiting review/submit of (unparseable change ID "cl_5bd9cf78d42e1fbc180f05f686da064fb93c310b")
        tagx_test.go:604: task foo: wait for submit: done: 5bd9cf78d42e1fbc180f05f686da064fb93c310b
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:622: 2023-10-20 17:05:21.827831 -0400 EDT m=+103.853136475	task foo: tag if appropriate: LOG: Tagging foo at 5bd9cf78d42e1fbc180f05f686da064fb93c310b as v1.2.0
        tagx_test.go:604: task foo: tag if appropriate: done: {foo golang.org/x/foo [0xc00011cb28]  v1.1.5 v1.2.0}
        tagx_test.go:570: foo should have been tagged with v1.2.0: git command failed: context deadline exceeded, stderr 

2023-10-14 00:37 darwin-amd64-13 build@49880869 go@144252d2 x/build/internal/task.TestTagSingleRepo (log)

--- FAIL: TestTagSingleRepo (69.34s)
    --- FAIL: TestTagSingleRepo/with_post-submit_check (63.44s)
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-10-18 11:43:22.910383 -0400 EDT m=+63.327431755	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc0007aa7f8]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:600: task foo: wait for green post-submit: started
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:604: task foo: generate go.mod: done: map[go.mod:module golang.org/x/foo
            require golang.org/x/mod v1.0.0
            // pretend we've upgraded to golang.org/x/mod@v1.1.0
            tidied! mod tidy
             go.sum:
            golang.org/x/mod v1.1.0 h1:asdasd
            ]
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:604: task foo: mail go.mod: done: cl_be6a00fe7e0fa5c224ce8146ce9f4df77afb7c9d
        tagx_test.go:565: context deadline exceeded

2023-10-14 00:37 darwin-amd64-13 build@49880869 go@fb726698 x/build/internal/task.TestTagSingleRepo (log)

--- FAIL: TestTagSingleRepo (70.62s)
    --- FAIL: TestTagSingleRepo/without_post-submit_check (66.24s)
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-10-17 23:16:07.676382 -0400 EDT m=+64.729840059	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc000b1a5a0]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:604: task foo: generate go.mod: done: map[go.mod:module golang.org/x/foo
            require golang.org/x/mod v1.0.0
            // pretend we've upgraded to golang.org/x/mod@v1.1.0
            tidied! mod tidy
             go.sum:
            golang.org/x/mod v1.1.0 h1:asdasd
            ]
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:604: task foo: mail go.mod: done: cl_e635514d8021171b268e3b990d163d0cbd6e7e95
        tagx_test.go:565: context deadline exceeded

2023-10-24 17:53 darwin-amd64-13 build@a966970d go@f9a31cda x/build/internal/task.TestTagSingleRepo (log)

--- FAIL: TestTagSingleRepo (89.14s)
    --- FAIL: TestTagSingleRepo/with_post-submit_check (82.63s)
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-10-24 14:01:42.887343 -0400 EDT m=+69.593814980	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc0005b9128]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: mail go.mod: started
...
            ]
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:604: task foo: mail go.mod: done: cl_7980548793978b0973e5233cd7a6b23e902b52cb
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:622: 2023-10-24 14:02:33.211424 -0400 EDT m=+119.917896620	task foo: wait for submit: LOG: Awaiting review/submit of (unparseable change ID "cl_7980548793978b0973e5233cd7a6b23e902b52cb")
        tagx_test.go:604: task foo: wait for submit: done: 7980548793978b0973e5233cd7a6b23e902b52cb
        tagx_test.go:600: task foo: wait for green post-submit: started
        tagx_test.go:622: 2023-10-24 14:02:43.317282 -0400 EDT m=+130.023754115	task foo: wait for green post-submit: LOG: task failed, will retry (1 of 3): git command failed: signal: killed, stderr 
        tagx_test.go:600: task foo: wait for green post-submit: started
        tagx_test.go:565: context deadline exceeded

— watchflakes

[bcmills]

See previously #56231, #63258.

As noted in #56231 (comment), this may be part of a cluster of failures specific to macOS (see #54461 (comment)).

[bcmills]

Looks like this particular timeout comes from here:
https://cs.opensource.google/go/x/build/+/master:internal/task/tagx_test.go;l=548;drc=96b29b7b0576775bbb2848637290d4e03aae1022

(I guess we missed one in https://go.dev/cl/533098? CC @heschi @dmitshur)

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- goos == "darwin" && pkg == "golang.org/x/build/internal/task" && test == "TestTagSingleRepo" && `context deadline exceeded`

2023-10-31 15:30 darwin-amd64-13 build@3403d10e go@23711f8e x/build/internal/task.TestTagSingleRepo (log)

--- FAIL: TestTagSingleRepo (72.62s)
    --- FAIL: TestTagSingleRepo/without_post-submit_check (65.84s)
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:600: task Load all repositories: started
        tagx_test.go:622: 2023-11-01 16:07:48.336748 -0400 EDT m=+49.947276402	task Load all repositories: LOG: Examining repositories [mod foo]
        tagx_test.go:604: task Load all repositories: done: [{mod golang.org/x/mod []  v1.1.0 } {foo golang.org/x/foo [0xc000114708]  v1.1.5 }]
        tagx_test.go:600: task Create single-repo plan: started
        tagx_test.go:604: task Create single-repo plan: done: <nil>
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:600: task foo: wait for submit: started
        tagx_test.go:600: task foo: tag if appropriate: started
        tagx_test.go:600: task foo: generate go.mod: started
        tagx_test.go:604: task foo: generate go.mod: done: map[go.mod:module golang.org/x/foo
            require golang.org/x/mod v1.0.0
            // pretend we've upgraded to golang.org/x/mod@v1.1.0
            tidied! mod tidy
             go.sum:
            golang.org/x/mod v1.1.0 h1:asdasd
            ]
        tagx_test.go:600: task foo: mail go.mod: started
        tagx_test.go:604: task foo: mail go.mod: done: cl_1d3c9cbcc5f001de2fb316d3b0bca4bd91f39842
        tagx_test.go:565: context deadline exceeded

— watchflakes

[dmitshur]

It does seem that way, thanks for looking at this. I can send a CL.