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

@@ -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())
 

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)
+}

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 {

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
+}

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())
+	}
+}

cmd/cli/prog.go

@@ -85,20 +85,23 @@ type prog struct {
 	dnsWatcherClosedOnce sync.Once
 	dnsWatcherStopCh     chan struct{}
 
-	cfg                  *ctrld.Config
+	cfg                       *ctrld.Config
-	localUpstreams       []string
+	localUpstreams            []string
-	ptrNameservers       []string
+	ptrNameservers            []string
-	appCallback          *AppCallback
+	appCallback               *AppCallback
-	cache                dnscache.Cacher
+	cache                     dnscache.Cacher
-	cacheFlushDomainsMap map[string]struct{}
+	cacheFlushDomainsMap      map[string]struct{}
-	sema                 semaphore
+	sema                      semaphore
-	ciTable              *clientinfo.Table
+	ciTable                   *clientinfo.Table
-	um                   *upstreamMonitor
+	um                        *upstreamMonitor
-	router               router.Router
+	router                    router.Router
-	ptrLoopGuard         *loopGuard
+	ptrLoopGuard              *loopGuard
-	lanLoopGuard         *loopGuard
+	lanLoopGuard              *loopGuard
-	metricsQueryStats    atomic.Bool
+	metricsQueryStats         atomic.Bool
-	queryFromSelfMap     sync.Map
+	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()
 }