From c32f9f58654ef911b2ce0fc1aaa90a4f1fed0713 Mon Sep 17 00:00:00 2001 From: Andrew Dunham Date: Sat, 15 Oct 2022 19:31:35 +0200 Subject: [PATCH] cmd/tailscale, ipn: enable debug logs when --report flag is passed to bugreport (#5830) Change-Id: Id22e9f4a2dcf35cecb9cd19dd844389e38c922ec Signed-off-by: Andrew Dunham --- client/tailscale/localclient.go | 34 +++++++++++++++- cmd/tailscale/cli/bugreport.go | 47 ++++++++++++++-------- ipn/ipnlocal/local.go | 15 +++++++ ipn/localapi/localapi.go | 69 +++++++++++++++++++++++++++++---- 4 files changed, 140 insertions(+), 25 deletions(-) diff --git a/client/tailscale/localclient.go b/client/tailscale/localclient.go index 01b7a08fd..07319e277 100644 --- a/client/tailscale/localclient.go +++ b/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 } diff --git a/cmd/tailscale/cli/bugreport.go b/cmd/tailscale/cli/bugreport.go index 312aadd51..d0c6ff560 100644 --- a/cmd/tailscale/cli/bugreport.go +++ b/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 err != nil { - return err } - - if bugReportArgs.record { - outln("The initial bugreport is below; please reproduce your issue and then press Enter...") - } - - outln(logMarker) - - if bugReportArgs.record { - fmt.Scanln() - - logMarker, err := localClient.BugReportWithOpts(ctx, tailscale.BugReportOpts{}) + if !bugReportArgs.record { + // Simple, non-record case + logMarker, err := localClient.BugReportWithOpts(ctx, opts) if err != nil { return err } outln(logMarker) - outln("Please provide both bugreport markers above to the support team or GitHub issue.") + return nil } + + // Recording; run the request in the background + done := make(chan struct{}) + opts.Record = done + + 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 + + if res.err != nil { + return res.err + } + + outln(res.marker) + outln("Please provide both bugreport markers above to the support team or GitHub issue.") return nil } diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go index 4cefde066..6509a5bb7 100644 --- a/ipn/ipnlocal/local.go +++ b/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 diff --git a/ipn/localapi/localapi.go b/ipn/localapi/localapi.go index 3ebd109f8..bfdd6a15a 100644 --- a/ipn/localapi/localapi.go +++ b/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)) - if envknob.NoLogsNoSupport() { - logMarker = "BUG-NO-LOGS-NO-SUPPORT-this-node-has-had-its-logging-disabled" + logMarker := func() string { + return fmt.Sprintf("BUG-%v-%v-%v", h.backendLogID, time.Now().UTC().Format("20060102150405Z"), randHex(8)) } - h.logf("user bugreport: %s", logMarker) - if note := r.FormValue("note"); len(note) > 0 { + if envknob.NoLogsNoSupport() { + 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) {