safing-portmaster/base/log/output.go

package log

import (
	"fmt"
	"runtime/debug"
	"sync"
	"time"

	"github.com/safing/portmaster/base/info"
)

// Adapter is used to write logs.
type Adapter interface {
	// Write is called for each log message.
	WriteMessage(msg Message, duplicates uint64)
}

var (
	schedulingEnabled = false
	writeTrigger      = make(chan struct{})
)

// EnableScheduling enables external scheduling of the logger. This will require to manually trigger writes via TriggerWrite whenever logs should be written. Please note that full buffers will also trigger writing. Must be called before Start() to have an effect.
func EnableScheduling() {
	if !initializing.IsSet() {
		schedulingEnabled = true
	}
}

// TriggerWriter triggers log output writing.
func TriggerWriter() {
	if started.IsSet() && schedulingEnabled {
		select {
		case writeTrigger <- struct{}{}:
		default:
		}
	}
}

// TriggerWriterChannel returns the channel to trigger log writing. Returned channel will close if EnableScheduling() is not called correctly.
func TriggerWriterChannel() chan struct{} {
	return writeTrigger
}

func startWriter() {
	if GlobalWriter.isStdout {
		fmt.Fprintf(GlobalWriter,
			"%s%s%s %sBOF %s%s\n",

			dimColor(),
			time.Now().Format(timeFormat),
			endDimColor(),

			blueColor(),
			rightArrow,
			endColor(),
		)
	} else {
		fmt.Fprintf(GlobalWriter,
			"%s BOF %s\n",
			time.Now().Format(timeFormat),
			rightArrow,
		)
	}
	writeVersion()

	shutdownWaitGroup.Add(1)
	go writerManager()
}

func writeVersion() {
	if GlobalWriter.isStdout {
		fmt.Fprintf(GlobalWriter, "%s%s%s running %s%s%s\n",
			dimColor(),
			time.Now().Format(timeFormat),
			endDimColor(),

			blueColor(),
			info.CondensedVersion(),
			endColor())
	} else {
		fmt.Fprintf(GlobalWriter, "%s running %s\n", time.Now().Format(timeFormat), info.CondensedVersion())
	}
}

func writerManager() {
	defer shutdownWaitGroup.Done()

	for {
		err := writer()
		if err != nil {
			Errorf("log: writer failed: %s", err)
		} else {
			return
		}
	}
}

func writer() error {
	var err error
	defer func() {
		// recover from panic
		panicVal := recover()
		if panicVal != nil {
			_, err = fmt.Fprintf(GlobalWriter, "%s", panicVal)

			// write stack to stderr
			fmt.Fprintf(
				GlobalWriter,
				`===== Error Report =====
Message: %s
StackTrace:

%s
===== End of Report =====
`,
				err,
				string(debug.Stack()),
			)
		}
	}()

	var currentLine *logLine
	var duplicates uint64

	for {
		// reset
		currentLine = nil
		duplicates = 0

		// wait until logs need to be processed
		select {
		case <-logsWaiting: // normal process
			logsWaitingFlag.UnSet()
		case <-forceEmptyingOfBuffer: // log buffer is full!
		case <-shutdownSignal: // shutting down
			finalizeWriting()
			return err
		}

		// wait for timeslot to log
		select {
		case <-writeTrigger: // normal process
		case <-forceEmptyingOfBuffer: // log buffer is full!
		case <-shutdownSignal: // shutting down
			finalizeWriting()
			return err
		}

		// write all the logs!
	writeLoop:
		for {
			select {
			case nextLine := <-logBuffer:
				// first line we process, just assign to currentLine
				if currentLine == nil {
					currentLine = nextLine
					continue writeLoop
				}

				// we now have currentLine and nextLine

				// if currentLine and nextLine are equal, do not print, just increase counter and continue
				if nextLine.Equal(currentLine) {
					duplicates++
					continue writeLoop
				}

				// if currentLine and line are _not_ equal, output currentLine
				GlobalWriter.WriteMessage(currentLine, duplicates)
				// add to unexpected logs
				addUnexpectedLogs(currentLine)
				// reset duplicate counter
				duplicates = 0
				// set new currentLine
				currentLine = nextLine
			default:
				break writeLoop
			}
		}

		// write final line
		if currentLine != nil {
			GlobalWriter.WriteMessage(currentLine, duplicates)
			// add to unexpected logs
			addUnexpectedLogs(currentLine)
		}

		// back down a little
		select {
		case <-time.After(10 * time.Millisecond):
		case <-shutdownSignal:
			finalizeWriting()
			return err
		}

	}
}

func finalizeWriting() {
	for {
		select {
		case line := <-logBuffer:
			GlobalWriter.WriteMessage(line, 0)
		case <-time.After(10 * time.Millisecond):
			if GlobalWriter.isStdout {
				fmt.Fprintf(GlobalWriter,
					"%s%s%s %sEOF %s%s\n",

					dimColor(),
					time.Now().Format(timeFormat),
					endDimColor(),

					blueColor(),
					leftArrow,
					endColor(),
				)
			} else {
				fmt.Fprintf(GlobalWriter,
					"%s EOF %s\n",
					time.Now().Format(timeFormat),
					leftArrow,
				)
			}
			return
		}
	}
}

// Last Unexpected Logs

var (
	lastUnexpectedLogs      [10]string
	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.
	logsLen := len(lastUnexpectedLogs)
	start := lastUnexpectedLogsIndex
	logsCopy := make([]string, 0, logsLen)
	// Loop from mid-to-mid.
	for i := start; i < start+logsLen; i++ {
		if lastUnexpectedLogs[i%logsLen] != "" {
			logsCopy = append(logsCopy, lastUnexpectedLogs[i%logsLen])
		}
	}

	return logsCopy
}