ipn/localipn: introduce logs for tailfs (#11496)

This change introduces some basic logging into the access and share
pathways for tailfs.

Updates tailscale/corp#17818

Signed-off-by: Charlotte Brandhorst-Satzkorn <charlotte@tailscale.com>

ipn/ipnlocal/local.go

@@ -13,6 +13,7 @@
 	"io"
 	"log"
 	"maps"
+	"math"
 	"net"
 	"net/http"
 	"net/netip"
@@ -86,6 +87,7 @@
 	"tailscale.com/types/views"
 	"tailscale.com/util/deephash"
 	"tailscale.com/util/dnsname"
+	"tailscale.com/util/httpm"
 	"tailscale.com/util/mak"
 	"tailscale.com/util/multierr"
 	"tailscale.com/util/osshare"
@@ -4751,7 +4753,102 @@ type tailFSTransport struct {
 	b *LocalBackend
 }
 
-func (t *tailFSTransport) RoundTrip(req *http.Request) (*http.Response, error) {
+// responseBodyWrapper wraps an io.ReadCloser and stores
+// the number of bytesRead.
+type responseBodyWrapper struct {
+	io.ReadCloser
+	bytesRx       int64
+	bytesTx       int64
+	log           logger.Logf
+	method        string
+	statusCode    int
+	contentType   string
+	fileExtension string
+	shareNodeKey  string
+	selfNodeKey   string
+	contentLength int64
+}
+
+// logAccess logs the tailfs: access: log line. If the logger is nil,
+// the log will not be written.
+func (rbw *responseBodyWrapper) logAccess(err string) {
+	if rbw.log == nil {
+		return
+	}
+
+	rbw.log("tailfs: 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)
+}
+
+// Read implements the io.Reader interface.
+func (rbw *responseBodyWrapper) Read(b []byte) (int, error) {
+	n, err := rbw.ReadCloser.Read(b)
+	rbw.bytesRx += int64(n)
+	if err != nil && !errors.Is(err, io.EOF) {
+		rbw.logAccess(err.Error())
+	}
+
+	return n, err
+}
+
+// Close implements the io.Close interface.
+func (rbw *responseBodyWrapper) Close() error {
+	err := rbw.ReadCloser.Close()
+	var errStr string
+	if err != nil {
+		errStr = err.Error()
+	}
+	rbw.logAccess(errStr)
+
+	return err
+}
+
+func (t *tailFSTransport) RoundTrip(req *http.Request) (resp *http.Response, err error) {
+	bw := &requestBodyWrapper{}
+	if req.Body != nil {
+		bw.ReadCloser = req.Body
+		req.Body = bw
+	}
+
+	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
+		}
+
+		t.b.mu.Lock()
+		selfNodeKey := t.b.netMap.SelfNode.Key().ShortString()
+		t.b.mu.Unlock()
+		n, _, ok := t.b.WhoIs(netip.MustParseAddrPort(req.URL.Host))
+		shareNodeKey := "unknown"
+		if ok {
+			shareNodeKey = string(n.Key().ShortString())
+		}
+
+		rbw := responseBodyWrapper{
+			log:           t.b.logf,
+			method:        req.Method,
+			bytesTx:       int64(bw.bytesRead),
+			selfNodeKey:   selfNodeKey,
+			shareNodeKey:  shareNodeKey,
+			contentType:   contentType,
+			contentLength: resp.ContentLength,
+			fileExtension: parseTailFSFileExtensionForLog(req.URL.Path),
+			statusCode:    resp.StatusCode,
+			ReadCloser:    resp.Body,
+		}
+
+		resp.Body = &rbw
+	}()
+
 	// dialTimeout is fairly aggressive to avoid hangs on contacting offline or
 	// unreachable hosts.
 	dialTimeout := 1 * time.Second // TODO(oxtoacart): tune this
@@ -4766,6 +4863,32 @@ func (t *tailFSTransport) RoundTrip(req *http.Request) (*http.Response, error) {
 	return tr.RoundTrip(req)
 }
 
+// roundTraffic rounds bytes. This is used to preserve user privacy within logs.
+func roundTraffic(bytes int64) float64 {
+	var x float64
+	switch {
+	case bytes <= 5:
+		return float64(bytes)
+	case bytes < 1000:
+		x = 10
+	case bytes < 10_000:
+		x = 100
+	case bytes < 100_000:
+		x = 1000
+	case bytes < 1_000_000:
+		x = 10_000
+	case bytes < 10_000_000:
+		x = 100_000
+	case bytes < 100_000_000:
+		x = 1_000_000
+	case bytes < 1_000_000_000:
+		x = 10_000_000
+	default:
+		x = 100_000_000
+	}
+	return math.Round(float64(bytes)/x) * x
+}
+
 // setDebugLogsByCapabilityLocked sets debug logging based on the self node's
 // capabilities in the provided NetMap.
 func (b *LocalBackend) setDebugLogsByCapabilityLocked(nm *netmap.NetworkMap) {

ipn/ipnlocal/local_test.go

@@ -2507,3 +2507,29 @@ func TestValidPopBrowserURL(t *testing.T) {
 		})
 	}
 }
+
+func TestRoundTraffic(t *testing.T) {
+	tests := []struct {
+		name  string
+		bytes int64
+		want  float64
+	}{
+		{name: "under 5 bytes", bytes: 4, want: 4},
+		{name: "under 1000 bytes", bytes: 987, want: 990},
+		{name: "under 10_000 bytes", bytes: 8875, want: 8900},
+		{name: "under 100_000 bytes", bytes: 77777, want: 78000},
+		{name: "under 1_000_000 bytes", bytes: 666523, want: 670000},
+		{name: "under 10_000_000 bytes", bytes: 22556677, want: 23000000},
+		{name: "under 1_000_000_000 bytes", bytes: 1234234234, want: 1200000000},
+		{name: "under 1_000_000_000 bytes", bytes: 123423423499, want: 123400000000},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			if result := roundTraffic(tt.bytes); result != tt.want {
+				t.Errorf("unexpected rounding got %v want %v", result, tt.want)
+			}
+		})
+
+	}
+}

ipn/ipnlocal/peerapi.go

@@ -17,6 +17,7 @@
 	"net/netip"
 	"net/url"
 	"os"
+	"path/filepath"
 	"runtime"
 	"slices"
 	"sort"
@@ -42,6 +43,7 @@
 	"tailscale.com/types/views"
 	"tailscale.com/util/clientmetric"
 	"tailscale.com/util/httphdr"
+	"tailscale.com/util/httpm"
 	"tailscale.com/wgengine/filter"
 )
 
@@ -1104,8 +1106,44 @@ func writePrettyDNSReply(w io.Writer, res []byte) (err error) {
 	return nil
 }
 
+// httpResponseWrapper wraps an http.ResponseWrite and
+// stores the status code and content length.
+type httpResponseWrapper struct {
+	http.ResponseWriter
+	statusCode    int
+	contentLength int64
+}
+
+// WriteHeader implements the WriteHeader interface.
+func (hrw *httpResponseWrapper) WriteHeader(status int) {
+	hrw.statusCode = status
+	hrw.ResponseWriter.WriteHeader(status)
+}
+
+// Write implements the Write interface.
+func (hrw *httpResponseWrapper) Write(b []byte) (int, error) {
+	n, err := hrw.ResponseWriter.Write(b)
+	hrw.contentLength += int64(n)
+	return n, err
+}
+
+// requestBodyWrapper wraps an io.ReadCloser and stores
+// the number of bytesRead.
+type requestBodyWrapper struct {
+	io.ReadCloser
+	bytesRead int64
+}
+
+// Read implements the io.Reader interface.
+func (rbw *requestBodyWrapper) Read(b []byte) (int, error) {
+	n, err := rbw.ReadCloser.Read(b)
+	rbw.bytesRead += int64(n)
+	return n, err
+}
+
 func (h *peerAPIHandler) handleServeTailFS(w http.ResponseWriter, r *http.Request) {
 	if !h.ps.b.TailFSSharingEnabled() {
+		h.logf("tailfs: not enabled")
 		http.Error(w, "tailfs not enabled", http.StatusNotFound)
 		return
 	}
@@ -1113,6 +1151,7 @@ func (h *peerAPIHandler) handleServeTailFS(w http.ResponseWriter, r *http.Reques
 	capsMap := h.peerCaps()
 	tailfsCaps, ok := capsMap[tailcfg.PeerCapabilityTailFS]
 	if !ok {
+		h.logf("tailfs: not permitted")
 		http.Error(w, "tailfs not permitted", http.StatusForbidden)
 		return
 	}
@@ -1124,17 +1163,63 @@ func (h *peerAPIHandler) handleServeTailFS(w http.ResponseWriter, r *http.Reques
 
 	p, err := tailfs.ParsePermissions(rawPerms)
 	if err != nil {
+		h.logf("tailfs: error parsing permissions: %w", err.Error())
 		http.Error(w, err.Error(), http.StatusInternalServerError)
 		return
 	}
 
 	fs, ok := h.ps.b.sys.TailFSForRemote.GetOK()
 	if !ok {
-		http.Error(w, "tailfs not enabled", http.StatusNotFound)
+		h.logf("tailfs: not supported on platform")
+		http.Error(w, "tailfs not supported on platform", http.StatusNotFound)
 		return
 	}
+	wr := &httpResponseWrapper{
+		ResponseWriter: w,
+	}
+	bw := &requestBodyWrapper{
+		ReadCloser: r.Body,
+	}
+	r.Body = bw
+
+	if r.Method == httpm.PUT || r.Method == httpm.GET {
+		defer func() {
+			switch wr.statusCode {
+			case 304:
+				// 304s are particularly chatty so skip logging.
+			default:
+				contentType := "unknown"
+				if ct := wr.Header().Get("Content-Type"); ct != "" {
+					contentType = ct
+				}
+
+				h.logf("tailfs: share: %s from %s to %s: status-code=%d ext=%q content-type=%q tx=%.f rx=%.f", r.Method, h.peerNode.Key().ShortString(), h.selfNode.Key().ShortString(), wr.statusCode, parseTailFSFileExtensionForLog(r.URL.Path), contentType, roundTraffic(wr.contentLength), roundTraffic(bw.bytesRead))
+			}
+		}()
+	}
+
 	r.URL.Path = strings.TrimPrefix(r.URL.Path, tailFSPrefix)
-	fs.ServeHTTPWithPerms(p, w, r)
+	fs.ServeHTTPWithPerms(p, wr, r)
+}
+
+// parseTailFSFileExtensionForLog parses the file extension, if available.
+// If a file extension is not present or parsable, the file extension is
+// set to "unknown". If the file extension contains a double quote, it is
+// replaced with "removed".
+// All whitespace is removed from a parsed file extension.
+// File extensions including the leading ., e.g. ".gif".
+func parseTailFSFileExtensionForLog(path string) string {
+	fileExt := "unknown"
+	if fe := filepath.Ext(path); fe != "" {
+		if strings.Contains(fe, "\"") {
+			// Do not log include file extensions with quotes within them.
+			return "removed"
+		}
+		// Remove white space from user defined inputs.
+		fileExt = strings.ReplaceAll(fe, " ", "")
+	}
+
+	return fileExt
 }
 
 // newFakePeerAPIListener creates a new net.Listener that acts like