cmd/tailscale, ipn: enable debug logs when --report flag is passed to bugreport (#5830)

Change-Id: Id22e9f4a2dcf35cecb9cd19dd844389e38c922ec
Signed-off-by: Andrew Dunham <andrew@tailscale.com>

client/tailscale/localclient.go

@@ -276,6 +276,12 @@ type BugReportOpts struct {
 	// Diagnose specifies whether to print additional diagnostic information to
 	// the logs when generating this bugreport.
 	Diagnose bool
+
+	// Record specifies, if non-nil, whether to perform a bugreport
+	// "recording"–generating an initial log marker, then waiting for
+	// this channel to be closed before finishing the request, which
+	// generates another log marker.
+	Record <-chan struct{}
 }
 
 // BugReportWithOpts logs and returns a log marker that can be shared by the
@@ -284,16 +290,40 @@ type BugReportOpts struct {
 // The opts type specifies options to pass to the Tailscale daemon when
 // generating this bug report.
 func (lc *LocalClient) BugReportWithOpts(ctx context.Context, opts BugReportOpts) (string, error) {
-	var qparams url.Values
+	qparams := make(url.Values)
 	if opts.Note != "" {
 		qparams.Set("note", opts.Note)
 	}
 	if opts.Diagnose {
 		qparams.Set("diagnose", "true")
 	}
+	if opts.Record != nil {
+		qparams.Set("record", "true")
+	}
 
+	ctx, cancel := context.WithCancel(ctx)
+	defer cancel()
+
+	var requestBody io.Reader
+	if opts.Record != nil {
+		pr, pw := io.Pipe()
+		requestBody = pr
+
+		// This goroutine waits for the 'Record' channel to be closed,
+		// and then closes the write end of our pipe to unblock the
+		// reader.
+		go func() {
+			defer pw.Close()
+			select {
+			case <-opts.Record:
+			case <-ctx.Done():
+			}
+		}()
+	}
+
+	// lc.send might block if opts.Record != nil; see above.
 	uri := fmt.Sprintf("/localapi/v0/bugreport?%s", qparams.Encode())
-	body, err := lc.send(ctx, "POST", uri, 200, nil)
+	body, err := lc.send(ctx, "POST", uri, 200, requestBody)
 	if err != nil {
 		return "", err
 	}

cmd/tailscale/cli/bugreport.go

@@ -41,29 +41,44 @@ func runBugReport(ctx context.Context, args []string) error {
 	default:
 		return errors.New("unknown arguments")
 	}
-	logMarker, err := localClient.BugReportWithOpts(ctx, tailscale.BugReportOpts{
+	opts := tailscale.BugReportOpts{
 		Note:     note,
 		Diagnose: bugReportArgs.diagnose,
-	})
+	}
+	if !bugReportArgs.record {
+		// Simple, non-record case
+		logMarker, err := localClient.BugReportWithOpts(ctx, opts)
 		if err != nil {
 			return err
 		}
-
+		outln(logMarker)
-	if bugReportArgs.record {
+		return nil
-		outln("The initial bugreport is below; please reproduce your issue and then press Enter...")
 	}
 
-	outln(logMarker)
+	// Recording; run the request in the background
+	done := make(chan struct{})
+	opts.Record = done
 
-	if bugReportArgs.record {
+	type bugReportResp struct {
+		marker string
+		err    error
+	}
+	resCh := make(chan bugReportResp, 1)
+	go func() {
+		m, err := localClient.BugReportWithOpts(ctx, opts)
+		resCh <- bugReportResp{m, err}
+	}()
+
+	outln("Recording started; please reproduce your issue and then press Enter...")
 	fmt.Scanln()
+	close(done)
+	res := <-resCh
 
-		logMarker, err := localClient.BugReportWithOpts(ctx, tailscale.BugReportOpts{})
+	if res.err != nil {
-		if err != nil {
+		return res.err
-			return err
 	}
-		outln(logMarker)
+
+	outln(res.marker)
 	outln("Please provide both bugreport markers above to the support team or GitHub issue.")
-	}
 	return nil
 }

ipn/ipnlocal/local.go

@@ -363,6 +363,21 @@ func (b *LocalBackend) SetComponentDebugLogging(component string, until time.Tim
 	return nil
 }
 
+// GetComponentDebugLogging gets the time that component's debug logging is
+// enabled until, or the zero time if component's time is not currently
+// enabled.
+func (b *LocalBackend) GetComponentDebugLogging(component string) time.Time {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+
+	now := time.Now()
+	ls := b.componentLogUntil[component]
+	if ls.until.IsZero() || ls.until.Before(now) {
+		return time.Time{}
+	}
+	return ls.until
+}
+
 // Dialer returns the backend's dialer.
 func (b *LocalBackend) Dialer() *tsdial.Dialer {
 	return b.dialer

ipn/localapi/localapi.go

@@ -232,12 +232,16 @@ func (h *Handler) serveBugReport(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	logMarker := fmt.Sprintf("BUG-%v-%v-%v", h.backendLogID, time.Now().UTC().Format("20060102150405Z"), randHex(8))
+	logMarker := func() string {
-	if envknob.NoLogsNoSupport() {
+		return fmt.Sprintf("BUG-%v-%v-%v", h.backendLogID, time.Now().UTC().Format("20060102150405Z"), randHex(8))
-		logMarker = "BUG-NO-LOGS-NO-SUPPORT-this-node-has-had-its-logging-disabled"
 	}
-	h.logf("user bugreport: %s", logMarker)
+	if envknob.NoLogsNoSupport() {
-	if note := r.FormValue("note"); len(note) > 0 {
+		logMarker = func() string { return "BUG-NO-LOGS-NO-SUPPORT-this-node-has-had-its-logging-disabled" }
+	}
+
+	startMarker := logMarker()
+	h.logf("user bugreport: %s", startMarker)
+	if note := r.URL.Query().Get("note"); len(note) > 0 {
 		h.logf("user bugreport note: %s", note)
 	}
 	hi, _ := json.Marshal(hostinfo.New())
@@ -247,11 +251,62 @@ func (h *Handler) serveBugReport(w http.ResponseWriter, r *http.Request) {
 	} else {
 		h.logf("user bugreport health: ok")
 	}
-	if defBool(r.FormValue("diagnose"), false) {
+	if defBool(r.URL.Query().Get("diagnose"), false) {
 		h.b.Doctor(r.Context(), logger.WithPrefix(h.logf, "diag: "))
 	}
 	w.Header().Set("Content-Type", "text/plain")
-	fmt.Fprintln(w, logMarker)
+	fmt.Fprintln(w, startMarker)
+
+	// Nothing else to do if we're not in record mode; we wrote the marker
+	// above, so we can just finish our response now.
+	if !defBool(r.URL.Query().Get("record"), false) {
+		return
+	}
+
+	until := time.Now().Add(12 * time.Hour)
+
+	var changed map[string]bool
+	for _, component := range []string{"magicsock"} {
+		if h.b.GetComponentDebugLogging(component).IsZero() {
+			if err := h.b.SetComponentDebugLogging(component, until); err != nil {
+				h.logf("bugreport: error setting component %q logging: %v", component, err)
+				continue
+			}
+
+			mak.Set(&changed, component, true)
+		}
+	}
+	defer func() {
+		for component := range changed {
+			h.b.SetComponentDebugLogging(component, time.Time{})
+		}
+	}()
+
+	// NOTE(andrew): if we have anything else we want to do while recording
+	// a bugreport, we can add it here.
+
+	// Read from the client; this will also return when the client closes
+	// the connection.
+	var buf [1]byte
+	_, err := r.Body.Read(buf[:])
+
+	switch {
+	case err == nil:
+		// good
+	case errors.Is(err, io.EOF):
+		// good
+	case errors.Is(err, io.ErrUnexpectedEOF):
+		// this happens when Ctrl-C'ing the tailscale client; don't
+		// bother logging an error
+	default:
+		// Log but continue anyway.
+		h.logf("user bugreport: error reading body: %v", err)
+	}
+
+	// Generate another log marker and return it to the client.
+	endMarker := logMarker()
+	h.logf("user bugreport end: %s", endMarker)
+	fmt.Fprintln(w, endMarker)
 }
 
 func (h *Handler) serveWhoIs(w http.ResponseWriter, r *http.Request) {