cmd/cigocacher,go.mod: add logging for canceled PUTs (#20584)

Pulls in bradfitz/go-tool-cache#43 and:

* Add logging for canceled PUTs to ensure we have some visibility.
* Scale PUT timeouts with object size.
* Control the Shutdown timeout separately from the PUT timeout.

Updates tailscale/corp#45334

Signed-off-by: Tom Proctor <tomhjp@users.noreply.github.com>

cmd/cigocacher/cigocacher.go

@@ -149,7 +149,7 @@ func main() {
 			AccessToken:           *token,
 			Verbose:               *verbose,
 			BestEffortHTTP:        true,
-			AsyncPutTimeout:       10 * time.Second, // Generous enough to allow for big objects ~100MiB.
+			AsyncPutTimeout:       asyncPutTimeout,
 			AsyncPutMaxConcurrent: 10,
 		}
 	}
@@ -157,9 +157,15 @@ func main() {
 	p = &cacheproc.Process{
 		Close: func() error {
 			if c.remote != nil {
-				if !c.remote.Shutdown() {
+				ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+				defer cancel()
+				if !c.remote.Shutdown(ctx) {
 					log.Printf("cigocacher: timed out waiting for background PUTs to drain")
 				}
+				// Always surface dropped PUTs.
+				if timedOut, canceled := c.remote.PutsTimedOut.Load(), c.remote.PutsCanceled.Load(); timedOut+canceled > 0 {
+					log.Printf("cigocacher: %d background PUTs timed out, %d canceled", timedOut, canceled)
+				}
 			}
 			if c.verbose {
 				log.Printf("cigocacher: closing; %d gets (%d hits, %d misses, %d errors); %d puts (%d errors)",
@@ -345,3 +351,23 @@ func fetchStats(cl *http.Client, baseURL, accessToken string) (string, error) {
 	}
 	return string(b), nil
 }
+
+const (
+	// minPutTimeout is the floor we clamp to for small objects where the time is
+	// dominated by fixed overheads like connection establishment, waiting for a
+	// busy server to service the request etc.
+	minPutTimeout = 5 * time.Second
+	// maxPutTimeout is the ceiling we clamp to for large objects.
+	maxPutTimeout = 30 * time.Second
+	// minAverageBandwidth is the minimum average bandwidth (2MiB/s) we require
+	// for PUTs to complete within the timeout in its linear scaling region.
+	minAverageBandwidth = 2 * 1 << 20 / float64(time.Second)
+)
+
+// asyncPutTimeout returns a size-dependent timeout for async PUTs to the remote
+// gocached server. It returns 5s for size <= 10MiB, 30s for size >= 60MiB and
+// scales linearly in between.
+func asyncPutTimeout(size int64) time.Duration {
+	timeout := time.Duration(float64(size) / minAverageBandwidth)
+	return min(max(minPutTimeout, timeout), maxPutTimeout)
+}

cmd/cigocacher/cigocacher_test.go

@@ -0,0 +1,25 @@
+// Copyright (c) Tailscale Inc & contributors
+// SPDX-License-Identifier: BSD-3-Clause
+
+package main
+
+import (
+	"testing"
+	"time"
+)
+
+func TestAsyncPutTimeout(t *testing.T) {
+	for size, expected := range map[int64]time.Duration{
+		0:            5 * time.Second,
+		10:           5 * time.Second,
+		10 * 1 << 20: 5 * time.Second,
+		20 * 1 << 20: 10 * time.Second,
+		40 * 1 << 20: 20 * time.Second,
+		60 * 1 << 20: 30 * time.Second,
+		10 * 1 << 30: 30 * time.Second,
+	} {
+		if actual := asyncPutTimeout(size); actual != expected {
+			t.Errorf("for size %d, expected %v, but got %v", size, expected, actual)
+		}
+	}
+}

flake.nix

@@ -173,4 +173,4 @@
     });
   };
 }
-# nix-direnv cache busting line: sha256-amKkUPszyhG4N5ZtrB01swBACYq76raSS+SQRneLmwc=
+# nix-direnv cache busting line: sha256-5ClQ5fSyEHUlhPtZI0ir8ddQRXSnqOG5VIJ3KjWtXmw=

flakehashes.json

@@ -4,7 +4,7 @@
     "sri": "sha256-TwIaPmGVHO9ZwdaO/jDStgWGQtKa4smS3er1i5aTNTw="
   },
   "vendor": {
-    "goModSum": "sha256-AbvfXWjfcRZHLJOp2Vuslvie8ROmm2pGvhxYIs07aNY=",
+    "goModSum": "sha256-7j0GzgLJIFwoNkWuJaxiujq+cCnIJVs/z0cvhNek66U=",
-    "sri": "sha256-amKkUPszyhG4N5ZtrB01swBACYq76raSS+SQRneLmwc="
+    "sri": "sha256-5ClQ5fSyEHUlhPtZI0ir8ddQRXSnqOG5VIJ3KjWtXmw="
   }
 }

go.mod

@@ -17,7 +17,7 @@ require (
 	github.com/aws/aws-sdk-go-v2/service/s3 v1.75.3
 	github.com/aws/aws-sdk-go-v2/service/ssm v1.45.0
 	github.com/axiomhq/hyperloglog v0.0.0-20240319100328-84253e514e02
-	github.com/bradfitz/go-tool-cache v0.0.0-20260722201841-0bb331e19f64
+	github.com/bradfitz/go-tool-cache v0.0.0-20260723163732-0b25549eea9b
 	github.com/bradfitz/monogok v0.0.0-20260630033929-b1eef977b41f
 	github.com/bradfitz/qemu-guest-kragent v0.0.0-20240513123539-55a43ea02a03
 	github.com/bramvdbogaerde/go-scp v1.4.0

go.sum

@@ -211,8 +211,8 @@ github.com/boltdb/bolt v1.3.1 h1:JQmyP4ZBrce+ZQu0dY660FMfatumYDLun9hBCUVIkF4=
 github.com/boltdb/bolt v1.3.1/go.mod h1:clJnj/oiGkjum5o1McbSZDSLxVThjynRyGBgiAx27Ps=
 github.com/bombsimon/wsl/v4 v4.2.1 h1:Cxg6u+XDWff75SIFFmNsqnIOgob+Q9hG6y/ioKbRFiM=
 github.com/bombsimon/wsl/v4 v4.2.1/go.mod h1:Xu/kDxGZTofQcDGCtQe9KCzhHphIe0fDuyWTxER9Feo=
-github.com/bradfitz/go-tool-cache v0.0.0-20260722201841-0bb331e19f64 h1:4FMo2ozvaa8GQNXf66C+jXzLh6gNudUtT84uuHGm09k=
+github.com/bradfitz/go-tool-cache v0.0.0-20260723163732-0b25549eea9b h1:XA4KY49pmsDGMUQT1P6mO7Oc5RxUWFo4PvGVZFhN3iU=
-github.com/bradfitz/go-tool-cache v0.0.0-20260722201841-0bb331e19f64/go.mod h1:n1IcQ3NLdg7hL0XnSuQpkbHG0W+gYAgKoru/Y/WZaEY=
+github.com/bradfitz/go-tool-cache v0.0.0-20260723163732-0b25549eea9b/go.mod h1:w9nUVumXlQBRZtGUdvzCzjcMtL7MotWr2mKalwFZXhg=
 github.com/bradfitz/monogok v0.0.0-20260630033929-b1eef977b41f h1:voy0korWbg2e1gsJpBZ8/OBhVL8evXeUwbCZcA1PWv8=
 github.com/bradfitz/monogok v0.0.0-20260630033929-b1eef977b41f/go.mod h1:TG1HbU9fRVDnNgXncVkKz9GdvjIvqquXjH6QZSEVmY4=
 github.com/bradfitz/qemu-guest-kragent v0.0.0-20240513123539-55a43ea02a03 h1:V1gD/xbQZtimHXZ0y19oMgTVBIXQyazG/mG9JIflrIY=

shell.nix

@@ -16,4 +16,4 @@
 ) {
   src =  ./.;
 }).shellNix
-# nix-direnv cache busting line: sha256-amKkUPszyhG4N5ZtrB01swBACYq76raSS+SQRneLmwc=
+# nix-direnv cache busting line: sha256-5ClQ5fSyEHUlhPtZI0ir8ddQRXSnqOG5VIJ3KjWtXmw=