From 6a9bf9172b6fa6dc645b5ea960b98014f389533d Mon Sep 17 00:00:00 2001
From: Percy Wegmann <percy@tailscale.com>
Date: Mon, 30 Jun 2025 13:43:16 -0500
Subject: [PATCH] ipn/ipnlocal: add verbose Taildrive logging on client side

This allows logging the following Taildrive behavior from the client's perspective
when --verbose=1:

- Initialization of Taildrive remotes for every peer
- Peer availability checks
- All HTTP requests to peers (not just GET and PUT)

Updates tailscale/corp#29702

Signed-off-by: Percy Wegmann <percy@tailscale.com>
---
 ipn/ipnlocal/drive.go |  6 ++++++
 ipn/ipnlocal/local.go | 35 +++++++++++++++++++++--------------
 2 files changed, 27 insertions(+), 14 deletions(-)

diff --git a/ipn/ipnlocal/drive.go b/ipn/ipnlocal/drive.go
index 6a6f9bcd2..8c2f339bb 100644
--- a/ipn/ipnlocal/drive.go
+++ b/ipn/ipnlocal/drive.go
@@ -306,10 +306,12 @@ func (b *LocalBackend) updateDrivePeersLocked(nm *netmap.NetworkMap) {
 }
 
 func (b *LocalBackend) driveRemotesFromPeers(nm *netmap.NetworkMap) []*drive.Remote {
+	b.logf("[v1] taildrive: setting up drive remotes from peers")
 	driveRemotes := make([]*drive.Remote, 0, len(nm.Peers))
 	for _, p := range nm.Peers {
 		peerID := p.ID()
 		url := fmt.Sprintf("%s/%s", peerAPIBase(nm, p), taildrivePrefix[1:])
+		b.logf("[v1] taildrive: appending remote for peer %d: %s", peerID, url)
 		driveRemotes = append(driveRemotes, &drive.Remote{
 			Name: p.DisplayName(false),
 			URL:  url,
@@ -320,6 +322,7 @@ func (b *LocalBackend) driveRemotesFromPeers(nm *netmap.NetworkMap) []*drive.Rem
 				cn := b.currentNode()
 				peer, ok := cn.NodeByID(peerID)
 				if !ok {
+					b.logf("[v1] taildrive: Available(): peer %d not found", peerID)
 					return false
 				}
 
@@ -332,14 +335,17 @@ func (b *LocalBackend) driveRemotesFromPeers(nm *netmap.NetworkMap) []*drive.Rem
 				// The netmap.Peers slice is not updated in all cases.
 				// It should be fixed now that we use PeerByIDOk.
 				if !peer.Online().Get() {
+					b.logf("[v1] taildrive: Available(): peer %d offline", peerID)
 					return false
 				}
 
 				// Check that the peer is allowed to share with us.
 				if cn.PeerHasCap(peer, tailcfg.PeerCapabilityTaildriveSharer) {
+					b.logf("[v1] taildrive: Available(): peer %d available", peerID)
 					return true
 				}
 
+				b.logf("[v1] taildrive: Available(): peer %d not allowed to share", peerID)
 				return false
 			},
 		})
diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go
index 9cec088f1..29d09400b 100644
--- a/ipn/ipnlocal/local.go
+++ b/ipn/ipnlocal/local.go
@@ -1459,7 +1459,7 @@ func (b *LocalBackend) WhoIs(proto string, ipp netip.AddrPort) (n tailcfg.NodeVi
 	}
 	n, ok = cn.NodeByID(nid)
 	if !ok {
-	    return zero, u, false
+		return zero, u, false
 	}
 	up, ok := cn.UserByID(n.User())
 	if !ok {
@@ -5960,6 +5960,7 @@ func (b *LocalBackend) setNetMapLocked(nm *netmap.NetworkMap) {
 // the number of bytesRead.
 type responseBodyWrapper struct {
 	io.ReadCloser
+	logVerbose    bool
 	bytesRx       int64
 	bytesTx       int64
 	log           logger.Logf
@@ -5981,8 +5982,22 @@ func (rbw *responseBodyWrapper) logAccess(err string) {
 
 	// Some operating systems create and copy lots of 0 length hidden files for
 	// tracking various states. Omit these to keep logs from being too verbose.
-	if rbw.contentLength > 0 {
-		rbw.log("taildrive: access: %s from %s to %s: status-code=%d ext=%q content-type=%q content-length=%.f tx=%.f rx=%.f err=%q", rbw.method, rbw.selfNodeKey, rbw.shareNodeKey, rbw.statusCode, rbw.fileExtension, rbw.contentType, roundTraffic(rbw.contentLength), roundTraffic(rbw.bytesTx), roundTraffic(rbw.bytesRx), err)
+	if rbw.logVerbose || rbw.contentLength > 0 {
+		levelPrefix := ""
+		if rbw.logVerbose {
+			levelPrefix = "[v1] "
+		}
+		rbw.log(
+			"%staildrive: access: %s from %s to %s: status-code=%d ext=%q content-type=%q content-length=%.f tx=%.f rx=%.f err=%q",
+			levelPrefix,
+			rbw.method,
+			rbw.selfNodeKey,
+			rbw.shareNodeKey,
+			rbw.statusCode,
+			rbw.fileExtension,
+			rbw.contentType,
+			roundTraffic(rbw.contentLength),
+			roundTraffic(rbw.bytesTx), roundTraffic(rbw.bytesRx), err)
 	}
 }
 
@@ -6037,17 +6052,8 @@ func (dt *driveTransport) RoundTrip(req *http.Request) (resp *http.Response, err
 
 	defer func() {
 		contentType := "unknown"
-		switch req.Method {
-		case httpm.PUT:
-			if ct := req.Header.Get("Content-Type"); ct != "" {
-				contentType = ct
-			}
-		case httpm.GET:
-			if ct := resp.Header.Get("Content-Type"); ct != "" {
-				contentType = ct
-			}
-		default:
-			return
+		if ct := req.Header.Get("Content-Type"); ct != "" {
+			contentType = ct
 		}
 
 		dt.b.mu.Lock()
@@ -6061,6 +6067,7 @@ func (dt *driveTransport) RoundTrip(req *http.Request) (resp *http.Response, err
 
 		rbw := responseBodyWrapper{
 			log:           dt.b.logf,
+			logVerbose:    req.Method != httpm.GET && req.Method != httpm.PUT, // other requests like PROPFIND are quite chatty, so we log those at verbose level
 			method:        req.Method,
 			bytesTx:       int64(bw.bytesRead),
 			selfNodeKey:   selfNodeKey,