From b657187a69a34993999cc9fa48e4d28dd914c266 Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Fri, 23 Dec 2022 20:54:30 -0800 Subject: [PATCH] cmd/tailscale, logtail: add 'tailscale debug daemon-logs' logtail mechanism Fixes #6836 Change-Id: Ia6eb39ff8972e1aa149aeeb63844a97497c2cf04 Signed-off-by: Brad Fitzpatrick --- client/tailscale/localclient.go | 17 ++++++++++++ cmd/tailscale/cli/debug.go | 44 ++++++++++++++++++++++++++++++ ipn/localapi/localapi.go | 41 ++++++++++++++++++++++++++++ logtail/logtail.go | 47 +++++++++++++++++++++++++++++++++ 4 files changed, 149 insertions(+) diff --git a/client/tailscale/localclient.go b/client/tailscale/localclient.go index 04359960b..59b047c66 100644 --- a/client/tailscale/localclient.go +++ b/client/tailscale/localclient.go @@ -257,6 +257,23 @@ func (lc *LocalClient) DaemonMetrics(ctx context.Context) ([]byte, error) { return lc.get200(ctx, "/localapi/v0/metrics") } +// TailDaemonLogs returns a stream the Tailscale daemon's logs as they arrive. +// Close the context to stop the stream. +func (lc *LocalClient) TailDaemonLogs(ctx context.Context) (io.Reader, error) { + req, err := http.NewRequestWithContext(ctx, "GET", "http://"+apitype.LocalAPIHost+"/localapi/v0/logtap", nil) + if err != nil { + return nil, err + } + res, err := lc.doLocalRequestNiceError(req) + if err != nil { + return nil, err + } + if res.StatusCode != 200 { + return nil, errors.New(res.Status) + } + return res.Body, nil +} + // Pprof returns a pprof profile of the Tailscale daemon. func (lc *LocalClient) Pprof(ctx context.Context, pprofType string, sec int) ([]byte, error) { var secArg string diff --git a/cmd/tailscale/cli/debug.go b/cmd/tailscale/cli/debug.go index b73578f55..4e22a0688 100644 --- a/cmd/tailscale/cli/debug.go +++ b/cmd/tailscale/cli/debug.go @@ -76,6 +76,17 @@ var debugCmd = &ffcli.Command{ Exec: runDaemonGoroutines, ShortHelp: "print tailscaled's goroutines", }, + { + Name: "daemon-logs", + Exec: runDaemonLogs, + ShortHelp: "watch tailscaled's server logs", + FlagSet: (func() *flag.FlagSet { + fs := newFlagSet("daemon-logs") + fs.IntVar(&daemonLogsArgs.verbose, "verbose", 0, "verbosity level") + fs.BoolVar(&daemonLogsArgs.time, "time", false, "include client time") + return fs + })(), + }, { Name: "metrics", Exec: runDaemonMetrics, @@ -419,6 +430,39 @@ func runDaemonGoroutines(ctx context.Context, args []string) error { return nil } +var daemonLogsArgs struct { + verbose int + time bool +} + +func runDaemonLogs(ctx context.Context, args []string) error { + logs, err := localClient.TailDaemonLogs(ctx) + if err != nil { + return err + } + d := json.NewDecoder(logs) + for { + var line struct { + Text string `json:"text"` + Verbose int `json:"v"` + Time string `json:"client_time"` + } + err := d.Decode(&line) + if err != nil { + return err + } + line.Text = strings.TrimSpace(line.Text) + if line.Text == "" || line.Verbose > daemonLogsArgs.verbose { + continue + } + if daemonLogsArgs.time { + fmt.Printf("%s %s\n", line.Time, line.Text) + } else { + fmt.Println(line.Text) + } + } +} + var metricsArgs struct { watch bool } diff --git a/ipn/localapi/localapi.go b/ipn/localapi/localapi.go index fa5583c49..9cefb1728 100644 --- a/ipn/localapi/localapi.go +++ b/ipn/localapi/localapi.go @@ -34,6 +34,7 @@ import ( "tailscale.com/ipn" "tailscale.com/ipn/ipnlocal" "tailscale.com/ipn/ipnstate" + "tailscale.com/logtail" "tailscale.com/net/netutil" "tailscale.com/safesocket" "tailscale.com/tailcfg" @@ -77,6 +78,7 @@ var handler = map[string]localAPIHandler{ "id-token": (*Handler).serveIDToken, "login-interactive": (*Handler).serveLoginInteractive, "logout": (*Handler).serveLogout, + "logtap": (*Handler).serveLogTap, "metrics": (*Handler).serveMetrics, "ping": (*Handler).servePing, "prefs": (*Handler).servePrefs, @@ -421,6 +423,45 @@ func (h *Handler) serveGoroutines(w http.ResponseWriter, r *http.Request) { w.Write(buf) } +// serveLogTap taps into the tailscaled/logtail server output and streams +// it to the client. +func (h *Handler) serveLogTap(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() + + // Require write access (~root) as the logs could contain something + // sensitive. + if !h.PermitWrite { + http.Error(w, "logtap access denied", http.StatusForbidden) + return + } + if r.Method != "GET" { + http.Error(w, "GET required", http.StatusMethodNotAllowed) + return + } + f, ok := w.(http.Flusher) + if !ok { + http.Error(w, "streaming unsupported", http.StatusInternalServerError) + return + } + + io.WriteString(w, `{"text":"[logtap connected]\n"}`+"\n") + f.Flush() + + msgc := make(chan string, 16) + unreg := logtail.RegisterLogTap(msgc) + defer unreg() + + for { + select { + case <-ctx.Done(): + return + case msg := <-msgc: + io.WriteString(w, msg) + f.Flush() + } + } +} + func (h *Handler) serveMetrics(w http.ResponseWriter, r *http.Request) { // Require write access out of paranoia that the metrics // might contain something sensitive. diff --git a/logtail/logtail.go b/logtail/logtail.go index aa6d2dddf..85874304c 100644 --- a/logtail/logtail.go +++ b/logtail/logtail.go @@ -26,6 +26,7 @@ import ( "tailscale.com/logtail/backoff" "tailscale.com/net/interfaces" tslogger "tailscale.com/types/logger" + "tailscale.com/util/set" "tailscale.com/wgengine/monitor" ) @@ -505,6 +506,7 @@ func (l *Logger) tryDrainWake() { } func (l *Logger) sendLocked(jsonBlob []byte) (int, error) { + tapSend(jsonBlob) if logtailDisabled.Load() { return len(jsonBlob), nil } @@ -758,3 +760,48 @@ func parseAndRemoveLogLevel(buf []byte) (level int, cleanBuf []byte) { } return 0, buf } + +var ( + tapSetSize atomic.Int32 + tapMu sync.Mutex + tapSet set.HandleSet[chan<- string] +) + +// RegisterLogTap registers dst to get a copy of every log write. The caller +// must call unregister when done watching. +// +// This would ideally be a method on Logger, but Logger isn't really available +// in most places; many writes go via stderr which filch redirects to the +// singleton Logger set up early. For better or worse, there's basically only +// one Logger within the program. This mechanism at least works well for +// tailscaled. It works less well for a binary with multiple tsnet.Servers. Oh +// well. This then subscribes to all of them. +func RegisterLogTap(dst chan<- string) (unregister func()) { + tapMu.Lock() + defer tapMu.Unlock() + h := tapSet.Add(dst) + tapSetSize.Store(int32(len(tapSet))) + return func() { + tapMu.Lock() + defer tapMu.Unlock() + delete(tapSet, h) + tapSetSize.Store(int32(len(tapSet))) + } +} + +// tapSend relays the JSON blob to any/all registered local debug log watchers +// (somebody running "tailscale debug daemon-logs"). +func tapSend(jsonBlob []byte) { + if tapSetSize.Load() == 0 { + return + } + s := string(jsonBlob) + tapMu.Lock() + defer tapMu.Unlock() + for _, dst := range tapSet { + select { + case dst <- s: + default: + } + } +}