diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go index 83358c088..b2c5a8be1 100644 --- a/ipn/ipnlocal/local.go +++ b/ipn/ipnlocal/local.go @@ -13,6 +13,7 @@ import ( "io" "log" "maps" + "math" "net" "net/http" "net/netip" @@ -86,6 +87,7 @@ import ( "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) { diff --git a/ipn/ipnlocal/local_test.go b/ipn/ipnlocal/local_test.go index 6f840a898..8906bf939 100644 --- a/ipn/ipnlocal/local_test.go +++ b/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) + } + }) + + } +} diff --git a/ipn/ipnlocal/peerapi.go b/ipn/ipnlocal/peerapi.go index 78d448bbe..6843292b2 100644 --- a/ipn/ipnlocal/peerapi.go +++ b/ipn/ipnlocal/peerapi.go @@ -17,6 +17,7 @@ import ( "net/netip" "net/url" "os" + "path/filepath" "runtime" "slices" "sort" @@ -42,6 +43,7 @@ import ( "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