Add basic debug api endpoints

api/endpoints_debug.go

@@ -0,0 +1,80 @@
+package api
+
+import (
+	"bytes"
+	"fmt"
+	"os"
+	"runtime/pprof"
+
+	"github.com/safing/portbase/utils/osdetail"
+)
+
+func registerDebugEndpoints() error {
+	if err := RegisterEndpoint(Endpoint{
+		Path:   "debug/stack",
+		Read:   PermitAnyone,
+		DataFn: getStack,
+	}); err != nil {
+		return err
+	}
+
+	if err := RegisterEndpoint(Endpoint{
+		Path:     "debug/stack/print",
+		Read:     PermitAnyone,
+		ActionFn: printStack,
+	}); err != nil {
+		return err
+	}
+
+	if err := RegisterEndpoint(Endpoint{
+		Path:   "debug/info",
+		Read:   PermitAnyone,
+		DataFn: debugInfo,
+	}); err != nil {
+		return err
+	}
+
+	return nil
+}
+
+// getStack returns the current goroutine stack.
+func getStack(_ *Request) (data []byte, err error) {
+	buf := &bytes.Buffer{}
+	err = pprof.Lookup("goroutine").WriteTo(buf, 1)
+	if err != nil {
+		return nil, err
+	}
+	return buf.Bytes(), nil
+}
+
+// printStack prints the current goroutine stack to stderr.
+func printStack(_ *Request) (msg string, err error) {
+	_, err = fmt.Fprint(os.Stderr, "===== PRINTING STACK =====\n")
+	if err == nil {
+		err = pprof.Lookup("goroutine").WriteTo(os.Stderr, 1)
+	}
+	if err == nil {
+		_, err = fmt.Fprint(os.Stderr, "===== END OF STACK =====\n")
+	}
+	if err != nil {
+		return "", err
+	}
+	return "stack printed to stdout", nil
+}
+
+// debugInfo returns the debugging information for support requests.
+func debugInfo(ar *Request) (data []byte, err error) {
+	// Create debug information helper.
+	di := new(osdetail.DebugInfo)
+	di.Style = ar.Request.URL.Query().Get("style")
+
+	// Add debug information.
+	di.AddVersionInfo()
+	di.AddPlatformInfo(ar.Ctx())
+	di.AddLastReportedModuleError()
+	di.AddLastUnexpectedLogs()
+	di.AddGoroutineStack()
+
+	// Return data.
+	return di.Bytes(), nil
+}

api/main.go

@@ -31,6 +31,10 @@ func prep() error {
 		return err
 	}
 
+	if err := registerDebugEndpoints(); err != nil {
+		return err
+	}
+
 	return registerMetaEndpoints()
 }
 

log/output.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"os"
 	"runtime/debug"
+	"sync"
 	"time"
 )
 
@@ -191,6 +192,8 @@ StackTrace:
 
 				// if currentLine and line are _not_ equal, output currentLine
 				adapter.Write(currentLine, duplicates)
+				// add to unexpected logs
+				addUnexpectedLogs(currentLine)
 				// reset duplicate counter
 				duplicates = 0
 				// set new currentLine
@@ -203,6 +206,8 @@ StackTrace:
 		// write final line
 		if currentLine != nil {
 			adapter.Write(currentLine, duplicates)
+			// add to unexpected logs
+			addUnexpectedLogs(currentLine)
 		}
 		// reset state
 		currentLine = nil //nolint:ineffassign
@@ -231,3 +236,60 @@ func finalizeWriting() {
 		}
 	}
 }
+
+// Last Unexpected Logs
+
+var (
+	lastUnexpectedLogs      = make([]string, 10)
+	lastUnexpectedLogsIndex int
+	lastUnexpectedLogsLock  sync.Mutex
+)
+
+func addUnexpectedLogs(line *logLine) {
+	// Add main line.
+	if line.level >= WarningLevel {
+		addUnexpectedLogLine(line)
+		return
+	}
+
+	// Check for unexpected lines in the tracer.
+	if line.tracer != nil {
+		for _, traceLine := range line.tracer.logs {
+			if traceLine.level >= WarningLevel {
+				// Add full trace.
+				addUnexpectedLogLine(line)
+				return
+			}
+		}
+	}
+}
+
+func addUnexpectedLogLine(line *logLine) {
+	lastUnexpectedLogsLock.Lock()
+	defer lastUnexpectedLogsLock.Unlock()
+
+	// Format line and add to logs.
+	lastUnexpectedLogs[lastUnexpectedLogsIndex] = formatLine(line, 0, false)
+
+	// Increase index and wrap back to start.
+	lastUnexpectedLogsIndex = (lastUnexpectedLogsIndex + 1) % len(lastUnexpectedLogs)
+}
+
+// GetLastUnexpectedLogs returns the last 10 log lines of level Warning an up.
+func GetLastUnexpectedLogs() []string {
+	lastUnexpectedLogsLock.Lock()
+	defer lastUnexpectedLogsLock.Unlock()
+
+	// Make a copy and return.
+	len := len(lastUnexpectedLogs)
+	start := lastUnexpectedLogsIndex
+	logsCopy := make([]string, 0, len)
+	// Loop from mid-to-mid.
+	for i := start; i < start+len; i++ {
+		if lastUnexpectedLogs[i%len] != "" {
+			logsCopy = append(logsCopy, lastUnexpectedLogs[i%len])
+		}
+	}
+
+	return logsCopy
+}

modules/error.go

@@ -11,7 +11,8 @@ import (
 var (
 	errorReportingChannel chan *ModuleError
 	reportToStdErr        = true
-	reportingLock         sync.RWMutex
+	lastReportedError     *ModuleError
+	reportingLock         sync.Mutex
 )
 
 // ModuleError wraps a panic, error or message into an error that can be reported.
@@ -67,10 +68,37 @@ func (me *ModuleError) Error() string {
 	return me.Message
 }
 
+// Format returns the error formatted in key/value form.
+func (me *ModuleError) Format() string {
+	return fmt.Sprintf(
+		`Message: %s
+Timestamp: %s
+ModuleName: %s
+TaskName: %s
+TaskType: %s
+Severity: %s
+PanicValue: %s
+StackTrace:
+
+%s
+`,
+		me.Message,
+		time.Now(),
+		me.ModuleName,
+		me.TaskName,
+		me.TaskType,
+		me.Severity,
+		me.PanicValue,
+		me.StackTrace,
+	)
+}
+
 // Report reports the error through the configured reporting channel.
 func (me *ModuleError) Report() {
-	reportingLock.RLock()
+	reportingLock.Lock()
-	defer reportingLock.RUnlock()
+	defer reportingLock.Unlock()
+
+	lastReportedError = me
 
 	if errorReportingChannel != nil {
 		select {
@@ -83,27 +111,8 @@ func (me *ModuleError) Report() {
 		// default to writing to stderr
 		fmt.Fprintf(
 			os.Stderr,
-			`===== Error Report =====
+			"===== Error Report =====\n%s\n===== End of Report =====\n",
-Message: %s
+			me.Format(),
-Timestamp: %s
-ModuleName: %s
-TaskName: %s
-TaskType: %s
-Severity: %s
-PanicValue: %s
-StackTrace:
-
-%s
-===== End of Report =====
-`,
-			me.Message,
-			time.Now(),
-			me.ModuleName,
-			me.TaskName,
-			me.TaskType,
-			me.Severity,
-			me.PanicValue,
-			me.StackTrace,
 		)
 	}
 }
@@ -133,3 +142,11 @@ func SetStdErrReporting(on bool) {
 
 	reportToStdErr = on
 }
+
+// GetLastReportedError returns the last reported module error.
+func GetLastReportedError() *ModuleError {
+	reportingLock.Lock()
+	defer reportingLock.Unlock()
+
+	return lastReportedError
+}

utils/osdetail/debug.go

@@ -0,0 +1,183 @@
+package osdetail
+
+import (
+	"bytes"
+	"context"
+	"fmt"
+	"runtime/pprof"
+	"time"
+
+	"github.com/safing/portbase/log"
+
+	"github.com/safing/portbase/info"
+	"github.com/safing/portbase/modules"
+	"github.com/shirou/gopsutil/host"
+)
+
+// DebugInfo gathers debugging information and stores everything in a buffer in
+// order to write it to somewhere later. It directly inherits a bytes.Buffer,
+// so you can also use all these functions too.
+type DebugInfo struct {
+	bytes.Buffer
+	Style string
+}
+
+// DebugInfoFlag defines possible options for adding sections to a DebugInfo.
+type DebugInfoFlag int
+
+const (
+	// NoFlags does nothing.
+	NoFlags DebugInfoFlag = 0
+
+	// UseCodeSection wraps the section content in a markdown code section.
+	UseCodeSection DebugInfoFlag = 1
+
+	// AddContentLineBreaks adds a line breaks after each line of content,
+	// except for the last.
+	AddContentLineBreaks DebugInfoFlag = 2
+)
+
+func useCodeSection(flags DebugInfoFlag) bool {
+	return flags&UseCodeSection > 0
+}
+
+func addContentLineBreaks(flags DebugInfoFlag) bool {
+	return flags&AddContentLineBreaks > 0
+}
+
+// AddSection adds a debug section to the DebugInfo. The result is directly
+// written into the buffer.
+func (di *DebugInfo) AddSection(name string, flags DebugInfoFlag, content ...string) {
+	// Check if we need a spacer.
+	if di.Len() > 0 {
+		di.WriteString("\n\n")
+	}
+
+	// Write section to buffer.
+
+	// Write section header.
+	if di.Style == "github" {
+		di.WriteString(fmt.Sprintf("<details>\n<summary>%s</summary>\n\n", name))
+	} else {
+		di.WriteString(fmt.Sprintf("**%s**:\n\n", name))
+	}
+
+	// Write section content.
+	if useCodeSection(flags) {
+		// Write code header: Needs one empty line between previous data.
+		di.WriteString("```\n")
+	}
+	for i, part := range content {
+		di.WriteString(part)
+		if addContentLineBreaks(flags) && i < len(content)-1 {
+			di.WriteString("\n")
+		}
+	}
+	if useCodeSection(flags) {
+		// Write code footer: Needs one empty line between next data.
+		di.WriteString("\n```\n")
+	}
+
+	// Write section header.
+	if di.Style == "github" {
+		di.WriteString("\n</details>")
+	}
+}
+
+// AddVersionInfo adds version information from the info pkg.
+func (di *DebugInfo) AddVersionInfo() {
+	di.AddSection(
+		"Version "+info.Version(),
+		UseCodeSection,
+		info.FullVersion(),
+	)
+}
+
+// AddPlatformInfo adds OS and platform information.
+func (di *DebugInfo) AddPlatformInfo(ctx context.Context) {
+	// Get information from the system.
+	info, err := host.InfoWithContext(ctx)
+	if err != nil {
+		di.AddSection(
+			"Platform Information",
+			NoFlags,
+			fmt.Sprintf("Failed to get: %s", err),
+		)
+		return
+	}
+
+	// Check if we want to add virtulization information.
+	var virtInfo string
+	if info.VirtualizationRole == "guest" {
+		if info.VirtualizationSystem != "" {
+			virtInfo = fmt.Sprintf("VM: %s", info.VirtualizationSystem)
+		} else {
+			virtInfo = "VM: unidentified"
+		}
+	}
+
+	// Add section.
+	di.AddSection(
+		fmt.Sprintf("Platform: %s %s", info.Platform, info.PlatformVersion),
+		UseCodeSection|AddContentLineBreaks,
+		fmt.Sprintf("System: %s %s (%s) %s", info.Platform, info.OS, info.PlatformFamily, info.PlatformVersion),
+		fmt.Sprintf("Kernel: %s %s", info.KernelVersion, info.KernelArch),
+		virtInfo,
+	)
+}
+
+// AddGoroutineStack adds the current goroutine stack.
+func (di *DebugInfo) AddGoroutineStack() {
+	buf := new(bytes.Buffer)
+	err := pprof.Lookup("goroutine").WriteTo(buf, 1)
+	if err != nil {
+		di.AddSection(
+			"Goroutine Stack",
+			NoFlags,
+			fmt.Sprintf("Failed to get: %s", err),
+		)
+		return
+	}
+
+	// Add section.
+	di.AddSection(
+		"Goroutine Stack",
+		UseCodeSection,
+		buf.String(),
+	)
+}
+
+// AddLastReportedModuleError adds the last reported module error, if one exists.
+func (di *DebugInfo) AddLastReportedModuleError() {
+	me := modules.GetLastReportedError()
+	if me == nil {
+		di.AddSection("No Module Error", NoFlags)
+		return
+	}
+
+	di.AddSection(
+		"Module Error",
+		UseCodeSection,
+		me.Format(),
+	)
+}
+
+// AddLastUnexpectedLogs adds the last 10 unexpected log lines, if any.
+func (di *DebugInfo) AddLastUnexpectedLogs() {
+	lines := log.GetLastUnexpectedLogs()
+
+	// Check if there is anything at all.
+	if len(lines) == 0 {
+		di.AddSection("No Unexpected Logs", NoFlags)
+		return
+	}
+
+	di.AddSection(
+		"Unexpected Logs",
+		UseCodeSection|AddContentLineBreaks,
+		append(
+			lines,
+			fmt.Sprintf("%s CURRENT TIME", time.Now().Format("060102 15:04:05.000")),
+		)...,
+	)
+}