From cd5619a05bfa9548e5eedf8ce53fff70bbab8760 Mon Sep 17 00:00:00 2001 From: Cuong Manh Le Date: Mon, 9 Dec 2024 23:17:00 +0700 Subject: [PATCH] cmd/cli: add internal logging So in case of no logging enabled, useful data could be sent to ControlD server for further troubleshooting. --- cmd/cli/cli.go | 5 ++ cmd/cli/commands.go | 88 +++++++++++++++++++++++++++ cmd/cli/control_server.go | 46 ++++++++++++++ cmd/cli/log_writer.go | 120 +++++++++++++++++++++++++++++++++++++ cmd/cli/log_writer_test.go | 49 +++++++++++++++ cmd/cli/prog.go | 32 +++++----- 6 files changed, 326 insertions(+), 14 deletions(-) create mode 100644 cmd/cli/commands.go create mode 100644 cmd/cli/log_writer.go create mode 100644 cmd/cli/log_writer_test.go diff --git a/cmd/cli/cli.go b/cmd/cli/cli.go index 89c79de..7a54367 100644 --- a/cmd/cli/cli.go +++ b/cmd/cli/cli.go @@ -1100,6 +1100,8 @@ NOTE: Uninstalling will set DNS to values provided by DHCP.`, }, } rootCmd.AddCommand(upgradeCmd) + + initLogCmd() } // isMobile reports whether the current OS is a mobile platform. @@ -1231,6 +1233,9 @@ func run(appCallback *AppCallback, stopCh chan struct{}) { // so it's able to log information in processCDFlags. initLogging() + // Initializing internal logging after global logging. + p.initInternalLogging() + mainLog.Load().Info().Msgf("starting ctrld %s", curVersion()) mainLog.Load().Info().Msgf("os: %s", osVersion()) diff --git a/cmd/cli/commands.go b/cmd/cli/commands.go new file mode 100644 index 0000000..a98fbb4 --- /dev/null +++ b/cmd/cli/commands.go @@ -0,0 +1,88 @@ +package cli + +import ( + "encoding/json" + "fmt" + "io" + "net/http" + "path/filepath" + + "github.com/spf13/cobra" +) + +func initLogCmd() { + logSendCmd := &cobra.Command{ + Use: "send", + Short: "Send runtime debug logs to ControlD", + Args: cobra.NoArgs, + Run: func(cmd *cobra.Command, args []string) { + dir, err := socketDir() + if err != nil { + mainLog.Load().Fatal().Err(err).Msg("failed to find ctrld home dir") + } + cc := newControlClient(filepath.Join(dir, ctrldControlUnixSock)) + resp, err := cc.post(sendLogsPath, nil) + if err != nil { + mainLog.Load().Fatal().Err(err).Msg("failed to send logs") + } + defer resp.Body.Close() + switch resp.StatusCode { + case http.StatusOK: + mainLog.Load().Notice().Msg("runtime logs sent successfully") + case http.StatusServiceUnavailable: + mainLog.Load().Warn().Msg("runtime logs could only be sent once per minute") + default: + buf, err := io.ReadAll(resp.Body) + if err != nil { + mainLog.Load().Fatal().Err(err).Msg("failed to read response body") + } + mainLog.Load().Error().Msg("failed to send logs") + mainLog.Load().Error().Msg(string(buf)) + } + }, + } + logViewCmd := &cobra.Command{ + Use: "view", + Short: "View current runtime debug logs", + Args: cobra.NoArgs, + Run: func(cmd *cobra.Command, args []string) { + dir, err := socketDir() + if err != nil { + mainLog.Load().Fatal().Err(err).Msg("failed to find ctrld home dir") + } + cc := newControlClient(filepath.Join(dir, ctrldControlUnixSock)) + resp, err := cc.post(viewLogsPath, nil) + if err != nil { + mainLog.Load().Fatal().Err(err).Msg("failed to get logs") + } + defer resp.Body.Close() + + switch resp.StatusCode { + case http.StatusMovedPermanently: + mainLog.Load().Warn().Msg("runtime debugs log is not enabled") + mainLog.Load().Warn().Msg(`ctrld may be run without "--cd" flag or logging is already enabled`) + return + case http.StatusBadRequest: + mainLog.Load().Warn().Msg("runtime debugs log is not available") + return + case http.StatusOK: + } + var logs logViewResponse + if err := json.NewDecoder(resp.Body).Decode(&logs); err != nil { + mainLog.Load().Fatal().Err(err).Msg("failed to decode view logs result") + } + fmt.Println(logs.Data) + }, + } + logCmd := &cobra.Command{ + Use: "log", + Short: "Manage runtime debug logs", + Args: cobra.OnlyValidArgs, + ValidArgs: []string{ + logSendCmd.Use, + }, + } + logCmd.AddCommand(logSendCmd) + logCmd.AddCommand(logViewCmd) + rootCmd.AddCommand(logCmd) +} diff --git a/cmd/cli/control_server.go b/cmd/cli/control_server.go index c31fd13..b6deed5 100644 --- a/cmd/cli/control_server.go +++ b/cmd/cli/control_server.go @@ -2,6 +2,7 @@ package cli import ( "context" + "encoding/base64" "encoding/json" "net" "net/http" @@ -25,6 +26,8 @@ const ( deactivationPath = "/deactivation" cdPath = "/cd" ifacePath = "/iface" + viewLogsPath = "/logs/view" + sendLogsPath = "/logs/send" ) type controlServer struct { @@ -211,6 +214,49 @@ func (p *prog) registerControlServerHandler() { } w.WriteHeader(http.StatusBadRequest) })) + p.cs.register(viewLogsPath, http.HandlerFunc(func(w http.ResponseWriter, request *http.Request) { + data, err := p.logContent() + if err != nil { + w.WriteHeader(http.StatusBadRequest) + return + } + if len(data) == 0 { + w.WriteHeader(http.StatusMovedPermanently) + return + } + if err := json.NewEncoder(w).Encode(&logViewResponse{Data: string(data)}); err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + })) + p.cs.register(sendLogsPath, http.HandlerFunc(func(w http.ResponseWriter, request *http.Request) { + if time.Since(p.internalLogSent) < logSentInterval { + w.WriteHeader(http.StatusServiceUnavailable) + return + } + data, err := p.logContent() + if err != nil { + w.WriteHeader(http.StatusBadRequest) + return + } + if len(data) == 0 { + w.WriteHeader(http.StatusMovedPermanently) + return + } + logFile := base64.StdEncoding.EncodeToString(data) + req := &controld.LogsRequest{ + UID: cdUID, + LogFile: logFile, + } + mainLog.Load().Debug().Msg("sending log file to ControlD server") + if err := controld.SendLogs(req, cdDev); err != nil { + mainLog.Load().Error().Msgf("could not send log file to ControlD server: %v", err) + http.Error(w, err.Error(), http.StatusInternalServerError) + } else { + mainLog.Load().Debug().Msg("sending log file successfully") + } + p.internalLogSent = time.Now() + })) } func jsonResponse(next http.Handler) http.Handler { diff --git a/cmd/cli/log_writer.go b/cmd/cli/log_writer.go new file mode 100644 index 0000000..f84b231 --- /dev/null +++ b/cmd/cli/log_writer.go @@ -0,0 +1,120 @@ +package cli + +import ( + "bytes" + "errors" + "os" + "sync" + "time" + + "github.com/rs/zerolog" + + "github.com/Control-D-Inc/ctrld" +) + +const ( + logWriterSize = 1024 * 1024 * 5 // 5 MB + logWriterInitialSize = 32 // 32 B + logSentInterval = time.Minute + logTruncatedMarker = "...\n" +) + +type logViewResponse struct { + Data string `json:"data"` +} + +// logWriter is an internal buffer to keep track of runtime log when no logging is enabled. +type logWriter struct { + mu sync.Mutex + buf bytes.Buffer + size int +} + +// newLogWriter creates an internal log writer with a fixed buffer size. +func newLogWriter() *logWriter { + lw := &logWriter{size: logWriterSize} + return lw +} + +func (lw *logWriter) Write(p []byte) (int, error) { + lw.mu.Lock() + defer lw.mu.Unlock() + + // If writing p causes overflows, discard old data. + if lw.buf.Len()+len(p) > lw.size { + buf := lw.buf.Bytes() + buf = buf[:logWriterInitialSize] + if idx := bytes.LastIndex(buf, []byte("\n")); idx != -1 { + buf = buf[:idx] + } + lw.buf.Reset() + lw.buf.Write(buf) + lw.buf.WriteString(logTruncatedMarker) // indicate that the log was truncated. + } + // If p is bigger than buffer size, truncate p by half until its size is smaller. + for len(p)+lw.buf.Len() > lw.size { + p = p[len(p)/2:] + } + return lw.buf.Write(p) +} + +// initInternalLogging performs internal logging if there's no log enabled. +func (p *prog) initInternalLogging() { + if !p.needInternalLogging() { + return + } + p.initInternalLogWriterOnce.Do(func() { + mainLog.Load().Notice().Msg("internal logging enabled") + lw := newLogWriter() + p.internalLogWriter = lw + p.internalLogSent = time.Now().Add(-logSentInterval) + }) + p.mu.Lock() + lw := p.internalLogWriter + p.mu.Unlock() + multi := zerolog.MultiLevelWriter(lw) + l := mainLog.Load().Output(multi).With().Logger() + mainLog.Store(&l) + ctrld.ProxyLogger.Store(&l) + if verbose == 0 { + zerolog.SetGlobalLevel(zerolog.DebugLevel) + } +} + +// needInternalLogging reports whether prog needs to run internal logging. +func (p *prog) needInternalLogging() bool { + // Do not run in non-cd mode. + if cdUID == "" { + return false + } + // Do not run if there's already log file. + if p.cfg.Service.LogPath != "" { + return false + } + return true +} + +func (p *prog) logContent() ([]byte, error) { + var data []byte + if p.needInternalLogging() { + p.mu.Lock() + lw := p.internalLogWriter + p.mu.Unlock() + if lw == nil { + return nil, errors.New("nil internal log writer") + } + lw.mu.Lock() + data = lw.buf.Bytes() + lw.mu.Unlock() + } else { + if p.cfg.Service.LogPath == "" { + return nil, nil + } + buf, err := os.ReadFile(p.cfg.Service.LogPath) + if err != nil { + return nil, err + } + data = buf + } + return data, nil +} diff --git a/cmd/cli/log_writer_test.go b/cmd/cli/log_writer_test.go new file mode 100644 index 0000000..6882ea0 --- /dev/null +++ b/cmd/cli/log_writer_test.go @@ -0,0 +1,49 @@ +package cli + +import ( + "strings" + "sync" + "testing" +) + +func Test_logWriter_Write(t *testing.T) { + size := 64 + lw := &logWriter{size: size} + lw.buf.Grow(lw.size) + data := strings.Repeat("A", size) + lw.Write([]byte(data)) + if lw.buf.String() != data { + t.Fatalf("unexpected buf content: %v", lw.buf.String()) + } + newData := "B" + halfData := strings.Repeat("A", len(data)/2) + logTruncatedMarker + lw.Write([]byte(newData)) + if lw.buf.String() != halfData+newData { + t.Fatalf("unexpected new buf content: %v", lw.buf.String()) + } + + bigData := strings.Repeat("B", 256) + expected := halfData + strings.Repeat("B", 16) + lw.Write([]byte(bigData)) + if lw.buf.String() != expected { + t.Fatalf("unexpected big buf content: %v", lw.buf.String()) + } +} + +func Test_logWriter_ConcurrentWrite(t *testing.T) { + size := 64 + lw := &logWriter{size: size} + n := 10 + var wg sync.WaitGroup + wg.Add(n) + for i := 0; i < n; i++ { + go func() { + defer wg.Done() + lw.Write([]byte(strings.Repeat("A", i))) + }() + } + wg.Wait() + if lw.buf.Len() > lw.size { + t.Fatalf("unexpected buf size: %v, content: %q", lw.buf.Len(), lw.buf.String()) + } +} diff --git a/cmd/cli/prog.go b/cmd/cli/prog.go index 4e7df33..c6146ea 100644 --- a/cmd/cli/prog.go +++ b/cmd/cli/prog.go @@ -85,20 +85,23 @@ type prog struct { dnsWatcherClosedOnce sync.Once dnsWatcherStopCh chan struct{} - cfg *ctrld.Config - localUpstreams []string - ptrNameservers []string - appCallback *AppCallback - cache dnscache.Cacher - cacheFlushDomainsMap map[string]struct{} - sema semaphore - ciTable *clientinfo.Table - um *upstreamMonitor - router router.Router - ptrLoopGuard *loopGuard - lanLoopGuard *loopGuard - metricsQueryStats atomic.Bool - queryFromSelfMap sync.Map + cfg *ctrld.Config + localUpstreams []string + ptrNameservers []string + appCallback *AppCallback + cache dnscache.Cacher + cacheFlushDomainsMap map[string]struct{} + sema semaphore + ciTable *clientinfo.Table + um *upstreamMonitor + router router.Router + ptrLoopGuard *loopGuard + lanLoopGuard *loopGuard + metricsQueryStats atomic.Bool + queryFromSelfMap sync.Map + initInternalLogWriterOnce sync.Once + internalLogWriter *logWriter + internalLogSent time.Time selfUninstallMu sync.Mutex refusedQueryCount int @@ -517,6 +520,7 @@ func (p *prog) run(reload bool, reloadCh chan struct{}) { } go p.apiConfigReload() p.postRun() + p.initInternalLogging() } wg.Wait() }