cmd/tailscaled, logpolicy, logtail: support log levels

Log levels can now be specified with "[v1] " or "[v2] " substrings
that are then stripped and filtered at the final logger. This follows
our existing "[unexpected]" etc convention and doesn't require a
wholesale reworking of our logging at the moment.

cmd/tailscaled then gets a new --verbose=N flag to take a log level
that controls what gets logged to stderr (and thus systemd, syslog,
etc). Logtail is unaffected by --verbose.

This commit doesn't add annotations to any existing log prints. That
is in the next commit.

Updates #924
Updates #282

Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>

cmd/tailscaled/tailscaled.go

@@ -64,6 +64,7 @@ var args struct {
 	port       uint16
 	statepath  string
 	socketpath string
+	verbose    int
 }
 
 func main() {
@@ -76,6 +77,7 @@ func main() {
 	}
 
 	printVersion := false
+	flag.IntVar(&args.verbose, "verbose", 0, "log verbosity level; 0 is default, 1 or higher are increasingly verbose")
 	flag.BoolVar(&args.cleanup, "cleanup", false, "clean up system state and exit")
 	flag.BoolVar(&args.fake, "fake", false, "use userspace fake tunnel+routing instead of kernel TUN interface")
 	flag.StringVar(&args.debug, "debug", "", "listen address ([ip]:port) of optional debug server")
@@ -118,6 +120,7 @@ func run() error {
 	var err error
 
 	pol := logpolicy.New("tailnode.log.tailscale.io")
+	pol.SetVerbosityLevel(args.verbose)
 	defer func() {
 		// Finish uploading logs after closing everything else.
 		ctx, cancel := context.WithTimeout(context.Background(), time.Second)

logpolicy/logpolicy.go

@@ -413,6 +413,15 @@ func New(collection string) *Policy {
 	}
 }
 
+// SetVerbosityLevel controls the verbosity level that should be
+// written to stderr. 0 is the default (not verbose). Levels 1 or higher
+// are increasingly verbose.
+//
+// It should not be changed concurrently with log writes.
+func (p *Policy) SetVerbosityLevel(level int) {
+	p.Logtail.SetVerbosityLevel(level)
+}
+
 // Close immediately shuts down the logger.
 func (p *Policy) Close() {
 	ctx, cancel := context.WithCancel(context.Background())

logtail/logtail.go

@@ -39,6 +39,7 @@ type Config struct {
 	LowMemory      bool             // if true, logtail minimizes memory use
 	TimeNow        func() time.Time // if set, subsitutes uses of time.Now
 	Stderr         io.Writer        // if set, logs are sent here instead of os.Stderr
+	StderrLevel    int              // max verbosity level to write to stderr; 0 means the non-verbose messages only
 	Buffer         Buffer           // temp storage, if nil a MemoryBuffer
 	NewZstdEncoder func() Encoder   // if set, used to compress logs for transmission
 
@@ -69,6 +70,7 @@ func NewLogger(cfg Config, logf tslogger.Logf) *Logger {
 	}
 	l := &Logger{
 		stderr:         cfg.Stderr,
+		stderrLevel:    cfg.StderrLevel,
 		httpc:          cfg.HTTPC,
 		url:            cfg.BaseURL + "/c/" + cfg.Collection + "/" + cfg.PrivateID.String(),
 		lowMem:         cfg.LowMemory,
@@ -99,6 +101,7 @@ func NewLogger(cfg Config, logf tslogger.Logf) *Logger {
 // logging facilities and uploading to a log server.
 type Logger struct {
 	stderr         io.Writer
+	stderrLevel    int
 	httpc          *http.Client
 	url            string
 	lowMem         bool
@@ -116,6 +119,15 @@ type Logger struct {
 	shutdownDone  chan struct{} // closd when shutdown complete
 }
 
+// SetVerbosityLevel controls the verbosity level that should be
+// written to stderr. 0 is the default (not verbose). Levels 1 or higher
+// are increasingly verbose.
+//
+// It should not be changed concurrently with log writes.
+func (l *Logger) SetVerbosityLevel(level int) {
+	l.stderrLevel = level
+}
+
 // Shutdown gracefully shuts down the logger while completing any
 // remaining uploads.
 //
@@ -457,7 +469,8 @@ func (l *Logger) Write(buf []byte) (int, error) {
 	if len(buf) == 0 {
 		return 0, nil
 	}
-	if l.stderr != nil && l.stderr != ioutil.Discard {
+	level, buf := parseAndRemoveLogLevel(buf)
+	if l.stderr != nil && l.stderr != ioutil.Discard && level <= l.stderrLevel {
 		if buf[len(buf)-1] == '\n' {
 			l.stderr.Write(buf)
 		} else {
@@ -471,3 +484,23 @@ func (l *Logger) Write(buf []byte) (int, error) {
 	_, err := l.send(b)
 	return len(buf), err
 }
+
+var (
+	openBracketV = []byte("[v")
+	v1           = []byte("[v1] ")
+	v2           = []byte("[v2] ")
+)
+
+// level 0 is normal (or unknown) level; 1+ are increasingly verbose
+func parseAndRemoveLogLevel(buf []byte) (level int, cleanBuf []byte) {
+	if len(buf) == 0 || buf[0] == '{' || !bytes.Contains(buf, openBracketV) {
+		return 0, buf
+	}
+	if bytes.Contains(buf, v1) {
+		return 1, bytes.ReplaceAll(buf, v1, nil)
+	}
+	if bytes.Contains(buf, v2) {
+		return 2, bytes.ReplaceAll(buf, v2, nil)
+	}
+	return 0, buf
+}