TUN-9371: Add logging format as JSON

Closes TUN-9371

Author: DevinCarr

cmd/cloudflared/cliutil/logger.go

@@ -4,48 +4,56 @@ import (
 	"github.com/urfave/cli/v2"
 	"github.com/urfave/cli/v2/altsrc"
 
-	cfdflags "github.com/cloudflare/cloudflared/cmd/cloudflared/flags"
+	"github.com/cloudflare/cloudflared/cmd/cloudflared/flags"
 )
 
 var (
 	debugLevelWarning = "At debug level cloudflared will log request URL, method, protocol, content length, as well as, all request and response headers. " +
 		"This can expose sensitive information in your logs."
+
+	FlagLogOutput = &cli.StringFlag{
+		Name:    flags.LogFormatOutput,
+		Usage:   "Output format for the logs (default, json)",
+		Value:   flags.LogFormatOutputValueDefault,
+		EnvVars: []string{"TUNNEL_MANAGEMENT_OUTPUT", "TUNNEL_LOG_OUTPUT"},
+	}
 )
 
 func ConfigureLoggingFlags(shouldHide bool) []cli.Flag {
 	return []cli.Flag{
 		altsrc.NewStringFlag(&cli.StringFlag{
-			Name:    cfdflags.LogLevel,
+			Name:    flags.LogLevel,
 			Value:   "info",
 			Usage:   "Application logging level {debug, info, warn, error, fatal}. " + debugLevelWarning,
 			EnvVars: []string{"TUNNEL_LOGLEVEL"},
 			Hidden:  shouldHide,
 		}),
 		altsrc.NewStringFlag(&cli.StringFlag{
-			Name:    cfdflags.TransportLogLevel,
+			Name:    flags.TransportLogLevel,
 			Aliases: []string{"proto-loglevel"}, // This flag used to be called proto-loglevel
 			Value:   "info",
 			Usage:   "Transport logging level(previously called protocol logging level) {debug, info, warn, error, fatal}",
 			EnvVars: []string{"TUNNEL_PROTO_LOGLEVEL", "TUNNEL_TRANSPORT_LOGLEVEL"},
 			Hidden:  shouldHide,
 		}),
 		altsrc.NewStringFlag(&cli.StringFlag{
-			Name:    cfdflags.LogFile,
+			Name:    flags.LogFile,
 			Usage:   "Save application log to this file for reporting issues.",
 			EnvVars: []string{"TUNNEL_LOGFILE"},
 			Hidden:  shouldHide,
 		}),
 		altsrc.NewStringFlag(&cli.StringFlag{
-			Name:    cfdflags.LogDirectory,
+			Name:    flags.LogDirectory,
 			Usage:   "Save application log to this directory for reporting issues.",
 			EnvVars: []string{"TUNNEL_LOGDIRECTORY"},
 			Hidden:  shouldHide,
 		}),
 		altsrc.NewStringFlag(&cli.StringFlag{
-			Name:    cfdflags.TraceOutput,
+			Name:    flags.TraceOutput,
 			Usage:   "Name of trace output file, generated when cloudflared stops.",
 			EnvVars: []string{"TUNNEL_TRACE_OUTPUT"},
 			Hidden:  shouldHide,
 		}),
+		FlagLogOutput,
 	}
 }

cmd/cloudflared/flags/flags.go

@@ -138,6 +138,11 @@ const (
 	// LogDirectory is the command line flag to define the directory where application logs will be stored.
 	LogDirectory = "log-directory"
 
+	// LogFormatOutput allows the command line logs to be output as JSON.
+	LogFormatOutput             = "output"
+	LogFormatOutputValueDefault = "default"
+	LogFormatOutputValueJSON    = "json"
+
 	// TraceOutput is the command line flag to set the name of trace output file
 	TraceOutput = "trace-output"
 

cmd/cloudflared/tail/cmd.go

@@ -4,6 +4,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"io"
 	"net/http"
 	"net/url"
 	"os"
@@ -97,12 +98,6 @@ func buildTailCommand(subcommands []*cli.Command) *cli.Command {
 				Value:   "",
 				EnvVars: []string{"TUNNEL_MANAGEMENT_TOKEN"},
 			},
-			&cli.StringFlag{
-				Name:    "output",
-				Usage:   "Output format for the logs (default, json)",
-				Value:   "default",
-				EnvVars: []string{"TUNNEL_MANAGEMENT_OUTPUT"},
-			},
 			&cli.StringFlag{
 				Name:    "management-hostname",
 				Usage:   "Management hostname to signify incoming management requests",
@@ -128,6 +123,7 @@ func buildTailCommand(subcommands []*cli.Command) *cli.Command {
 				EnvVars: []string{"TUNNEL_ORIGIN_CERT"},
 				Value:   credentials.FindDefaultOriginCertPath(),
 			},
+			cliutil.FlagLogOutput,
 		},
 		Subcommands: subcommands,
 	}
@@ -171,10 +167,21 @@ func createLogger(c *cli.Context) *zerolog.Logger {
 	if levelErr != nil {
 		level = zerolog.InfoLevel
 	}
-	log := zerolog.New(zerolog.ConsoleWriter{
-		Out:        colorable.NewColorable(os.Stderr),
-		TimeFormat: time.RFC3339,
-	}).With().Timestamp().Logger().Level(level)
+	var writer io.Writer
+	switch c.String(cfdflags.LogFormatOutput) {
+	case cfdflags.LogFormatOutputValueJSON:
+		// zerolog by default outputs as JSON
+		writer = os.Stderr
+	case cfdflags.LogFormatOutputValueDefault:
+		// "default" and unset use the same logger output format
+		fallthrough
+	default:
+		writer = zerolog.ConsoleWriter{
+			Out:        colorable.NewColorable(os.Stderr),
+			TimeFormat: time.RFC3339,
+		}
+	}
+	log := zerolog.New(writer).With().Timestamp().Logger().Level(level)
 	return &log
 }
 

logger/configuration.go

@@ -17,6 +17,7 @@ type Config struct {
 
 type ConsoleConfig struct {
 	noColor bool
+	asJSON  bool
 }
 
 type FileConfig struct {
@@ -48,6 +49,7 @@ func createDefaultConfig() Config {
 	return Config{
 		ConsoleConfig: &ConsoleConfig{
 			noColor: false,
+			asJSON:  false,
 		},
 		FileConfig: &FileConfig{
 			Dirname:  "",
@@ -67,11 +69,12 @@ func createDefaultConfig() Config {
 func CreateConfig(
 	minLevel string,
 	disableTerminal bool,
+	formatJSON bool,
 	rollingLogPath, nonRollingLogFilePath string,
 ) *Config {
 	var console *ConsoleConfig
 	if !disableTerminal {
-		console = createConsoleConfig()
+		console = createConsoleConfig(formatJSON)
 	}
 
 	var file *FileConfig
@@ -95,9 +98,10 @@ func CreateConfig(
 	}
 }
 
-func createConsoleConfig() *ConsoleConfig {
+func createConsoleConfig(formatJSON bool) *ConsoleConfig {
 	return &ConsoleConfig{
 		noColor: false,
+		asJSON:  formatJSON,
 	}
 }
 

logger/console.go

@@ -0,0 +1,37 @@
+package logger
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+
+	jsoniter "github.com/json-iterator/go"
+)
+
+var json = jsoniter.ConfigCompatibleWithStandardLibrary
+
+// consoleWriter allows us the simplicity to prevent duplicate json keys in the logger events reported.
+//
+// By default zerolog constructs the json event in parts by appending each additional key after the first. It
+// doesn't have any internal state or struct of the json message representation so duplicate keys can be
+// inserted without notice and no pruning will occur before writing the log event out to the io.Writer.
+//
+// To help prevent these duplicate keys, we will decode the json log event and then immediately re-encode it
+// again as writing it to the output io.Writer. Since we encode it to a map[string]any, duplicate keys
+// are pruned. We pay the cost of decoding and encoding the log event for each time, but helps prevent
+// us from needing to worry about adding duplicate keys in the log event from different areas of code.
+type consoleWriter struct {
+	out io.Writer
+}
+
+func (c *consoleWriter) Write(p []byte) (n int, err error) {
+	var evt map[string]any
+	d := json.NewDecoder(bytes.NewReader(p))
+	d.UseNumber()
+	err = d.Decode(&evt)
+	if err != nil {
+		return n, fmt.Errorf("cannot decode event: %s", err)
+	}
+	e := json.NewEncoder(c.out)
+	return len(p), e.Encode(evt)
+}

logger/console_test.go

@@ -0,0 +1,33 @@
+package logger
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	"github.com/rs/zerolog"
+)
+
+func TestConsoleLoggerDuplicateKeys(t *testing.T) {
+	r := bytes.NewBuffer(make([]byte, 500))
+	logger := zerolog.New(&consoleWriter{out: r}).With().Timestamp().Logger()
+	logger.Debug().Str("test", "1234").Int("number", 45).Str("test", "5678").Msg("log message")
+
+	event, err := r.ReadString('\n')
+	if err != nil {
+		t.Error(err)
+	}
+
+	if !strings.Contains(event, "\"test\":\"5678\"") {
+		t.Errorf("log event missing key 'test': %s", event)
+	}
+	if !strings.Contains(event, "\"number\":45") {
+		t.Errorf("log event missing key 'number': %s", event)
+	}
+	if !strings.Contains(event, "\"time\":") {
+		t.Errorf("log event missing key 'time': %s", event)
+	}
+	if !strings.Contains(event, "\"level\":\"debug\"") {
+		t.Errorf("log event missing key 'level': %s", event)
+	}
+}

logger/create.go

@@ -149,10 +149,21 @@ func createFromContext(
 	logLevel := c.String(logLevelFlagName)
 	logFile := c.String(cfdflags.LogFile)
 	logDirectory := c.String(logDirectoryFlagName)
+	var logFormatJSON bool
+	switch c.String(cfdflags.LogFormatOutput) {
+	case cfdflags.LogFormatOutputValueJSON:
+		logFormatJSON = true
+	case cfdflags.LogFormatOutputValueDefault:
+		// "default" and unset use the same logger output format
+		fallthrough
+	default:
+		logFormatJSON = false
+	}
 
 	loggerConfig := CreateConfig(
 		logLevel,
 		disableTerminal,
+		logFormatJSON,
 		logDirectory,
 		logFile,
 	)
@@ -177,6 +188,9 @@ func Create(loggerConfig *Config) *zerolog.Logger {
 }
 
 func createConsoleLogger(config ConsoleConfig) io.Writer {
+	if config.asJSON {
+		return &consoleWriter{out: os.Stderr}
+	}
 	consoleOut := os.Stderr
 	return zerolog.ConsoleWriter{
 		Out:        colorable.NewColorable(consoleOut),