Allow Logging to stdout with separate Error Log Channel (#718)

* Add dedicated error logging writer

* Document new errors to stdout flag

* Update changelog

* Thread-safe the log buffer

* Address feedback

* Remove duplication by adding log level

* Clean up error formatting

* Apply suggestions from code review

Co-authored-by: Joel Speed <Joel.speed@hotmail.co.uk>

pkg/apis/options/legacy_options.go

@@ -91,7 +91,7 @@ func (l *LegacyUpstreams) convert() (Upstreams, error) {
 		case "static":
 			responseCode, err := strconv.Atoi(u.Host)
 			if err != nil {
-				logger.Printf("unable to convert %q to int, use default \"200\"", u.Host)
+				logger.Errorf("unable to convert %q to int, use default \"200\"", u.Host)
 				responseCode = 200
 			}
 			upstream.Static = true

pkg/apis/options/logging.go

@@ -13,6 +13,7 @@ type Logging struct {
 	RequestFormat   string         `flag:"request-logging-format" cfg:"request_logging_format"`
 	StandardEnabled bool           `flag:"standard-logging" cfg:"standard_logging"`
 	StandardFormat  string         `flag:"standard-logging-format" cfg:"standard_logging_format"`
+	ErrToInfo       bool           `flag:"errors-to-info-log" cfg:"errors_to_info_log"`
 	ExcludePaths    []string       `flag:"exclude-logging-path" cfg:"exclude_logging_paths"`
 	LocalTime       bool           `flag:"logging-local-time" cfg:"logging_local_time"`
 	SilencePing     bool           `flag:"silence-ping-logging" cfg:"silence_ping_logging"`
@@ -37,6 +38,7 @@ func loggingFlagSet() *pflag.FlagSet {
 	flagSet.String("standard-logging-format", logger.DefaultStandardLoggingFormat, "Template for standard log lines")
 	flagSet.Bool("request-logging", true, "Log HTTP requests")
 	flagSet.String("request-logging-format", logger.DefaultRequestLoggingFormat, "Template for HTTP request log lines")
+	flagSet.Bool("errors-to-info-log", false, "Log errors to the standard logging channel instead of stderr")
 
 	flagSet.StringSlice("exclude-logging-path", []string{}, "Exclude logging requests to paths (eg: '/path1,/path2,/path3')")
 	flagSet.Bool("logging-local-time", true, "If the time in log files and backup filenames are local or UTC time")
@@ -63,6 +65,7 @@ func loggingDefaults() Logging {
 		RequestFormat:   logger.DefaultRequestLoggingFormat,
 		StandardEnabled: true,
 		StandardFormat:  logger.DefaultStandardLoggingFormat,
+		ErrToInfo:       false,
 		File: LogFileOptions{
 			Filename:   "",
 			MaxSize:    100,

pkg/authentication/basic/htpasswd.go

@@ -78,7 +78,7 @@ func createHtpasswdMap(records [][]string) (*htpasswdMap, error) {
 
 		// Password is neither sha1 or bcrypt
 		// TODO(JoelSpeed): In the next breaking release, make this return an error.
-		logger.Printf("Invalid htpasswd entry for %s. Must be a SHA or bcrypt entry.", user)
+		logger.Errorf("Invalid htpasswd entry for %s. Must be a SHA or bcrypt entry.", user)
 	}
 	return h, nil
 }

pkg/cookies/cookies.go

@@ -20,7 +20,7 @@ func MakeCookie(req *http.Request, name string, value string, path string, domai
 			host = h
 		}
 		if !strings.HasSuffix(host, domain) {
-			logger.Printf("Warning: request host is %q but using configured cookie domain of %q", host, domain)
+			logger.Errorf("Warning: request host is %q but using configured cookie domain of %q", host, domain)
 		}
 	}
 
@@ -45,7 +45,7 @@ func MakeCookieFromOptions(req *http.Request, name string, value string, cookieO
 		return MakeCookie(req, name, value, cookieOpts.Path, domain, cookieOpts.HTTPOnly, cookieOpts.Secure, expiration, now, ParseSameSite(cookieOpts.SameSite))
 	}
 	// If nothing matches, create the cookie with the shortest domain
-	logger.Printf("Warning: request host %q did not match any of the specific cookie domains of %q", GetRequestHost(req), strings.Join(cookieOpts.Domains, ","))
+	logger.Errorf("Warning: request host %q did not match any of the specific cookie domains of %q", GetRequestHost(req), strings.Join(cookieOpts.Domains, ","))
 	defaultDomain := ""
 	if len(cookieOpts.Domains) > 0 {
 		defaultDomain = cookieOpts.Domains[len(cookieOpts.Domains)-1]

pkg/logger/logger.go

@@ -1,6 +1,7 @@
 package logger
 
 import (
+	"bytes"
 	"fmt"
 	"io"
 	"net/http"
@@ -15,6 +16,9 @@ import (
 // AuthStatus defines the different types of auth logging that occur
 type AuthStatus string
 
+// Level indicates the log level for log messages
+type Level int
+
 const (
 	// DefaultStandardLoggingFormat defines the default standard log format
 	DefaultStandardLoggingFormat = "[{{.Timestamp}}] [{{.File}}] {{.Message}}"
@@ -38,6 +42,11 @@ const (
 	LUTC
 	// LstdFlags flag for initial values for the logger
 	LstdFlags = Lshortfile
+
+	// DEFAULT is the default log level (effectively INFO)
+	DEFAULT Level = iota
+	// ERROR is for error-level logging
+	ERROR
 )
 
 // These are the containers for all values that are available as variables in the logging formats.
@@ -87,6 +96,7 @@ type Logger struct {
 	mu             sync.Mutex
 	flag           int
 	writer         io.Writer
+	errWriter      io.Writer
 	stdEnabled     bool
 	authEnabled    bool
 	reqEnabled     bool
@@ -100,7 +110,8 @@ type Logger struct {
 // New creates a new Standarderr Logger.
 func New(flag int) *Logger {
 	return &Logger{
-		writer:         os.Stderr,
+		writer:         os.Stdout,
+		errWriter:      os.Stderr,
 		flag:           flag,
 		stdEnabled:     true,
 		authEnabled:    true,
@@ -115,13 +126,7 @@ func New(flag int) *Logger {
 
 var std = New(LstdFlags)
 
-// Output a standard log template with a simple message.
-// Write a final newline at the end of every message.
-func (l *Logger) Output(calldepth int, message string) {
-	if !l.stdEnabled {
-		return
-	}
-
+func (l *Logger) formatLogMessage(calldepth int, message string) []byte {
 	now := time.Now()
 	file := "???:0"
 
@@ -129,10 +134,8 @@ func (l *Logger) Output(calldepth int, message string) {
 		file = l.GetFileLineString(calldepth + 1)
 	}
 
-	l.mu.Lock()
-	defer l.mu.Unlock()
-
-	err := l.stdLogTemplate.Execute(l.writer, stdLogMessageData{
+	var logBuff = new(bytes.Buffer)
+	err := l.stdLogTemplate.Execute(logBuff, stdLogMessageData{
 		Timestamp: FormatTimestamp(now),
 		File:      file,
 		Message:   message,
@@ -145,6 +148,26 @@ func (l *Logger) Output(calldepth int, message string) {
 	if err != nil {
 		panic(err)
 	}
+	logBuff.Write([]byte("\n"))
+
+	return logBuff.Bytes()
+}
+
+// Output a standard log template with a simple message to default output channel.
+// Write a final newline at the end of every message.
+func (l *Logger) Output(lvl Level, calldepth int, message string) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	if !l.stdEnabled {
+		return
+	}
+	msg := l.formatLogMessage(calldepth, message)
+	switch lvl {
+	case ERROR:
+		l.errWriter.Write(msg)
+	default:
+		l.writer.Write(msg)
+	}
 }
 
 // PrintAuthf writes auth info to the logger. Requires an http.Request to
@@ -302,6 +325,17 @@ func (l *Logger) SetStandardEnabled(e bool) {
 	l.stdEnabled = e
 }
 
+// SetErrToInfo enables or disables error logging to error writer instead of the default.
+func (l *Logger) SetErrToInfo(e bool) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	if e {
+		l.errWriter = l.writer
+	} else {
+		l.errWriter = os.Stderr
+	}
+}
+
 // SetAuthEnabled enables or disables auth logging.
 func (l *Logger) SetAuthEnabled(e bool) {
 	l.mu.Lock()
@@ -371,19 +405,32 @@ func SetFlags(flag int) {
 	std.SetFlags(flag)
 }
 
-// SetOutput sets the output destination for the standard logger.
+// SetOutput sets the output destination for the standard logger's default channel.
 func SetOutput(w io.Writer) {
 	std.mu.Lock()
 	defer std.mu.Unlock()
 	std.writer = w
 }
 
+// SetErrOutput sets the output destination for the standard logger's error channel.
+func SetErrOutput(w io.Writer) {
+	std.mu.Lock()
+	defer std.mu.Unlock()
+	std.errWriter = w
+}
+
 // SetStandardEnabled enables or disables standard logging for the
 // standard logger.
 func SetStandardEnabled(e bool) {
 	std.SetStandardEnabled(e)
 }
 
+// SetErrToInfo enables or disables error logging to output writer instead of
+// error writer.
+func SetErrToInfo(e bool) {
+	std.SetErrToInfo(e)
+}
+
 // SetAuthEnabled enables or disables auth logging for the standard
 // logger.
 func SetAuthEnabled(e bool) {
@@ -428,57 +475,75 @@ func SetReqTemplate(t string) {
 // Print calls Output to print to the standard logger.
 // Arguments are handled in the manner of fmt.Print.
 func Print(v ...interface{}) {
-	std.Output(2, fmt.Sprint(v...))
+	std.Output(DEFAULT, 2, fmt.Sprint(v...))
 }
 
 // Printf calls Output to print to the standard logger.
 // Arguments are handled in the manner of fmt.Printf.
 func Printf(format string, v ...interface{}) {
-	std.Output(2, fmt.Sprintf(format, v...))
+	std.Output(DEFAULT, 2, fmt.Sprintf(format, v...))
 }
 
 // Println calls Output to print to the standard logger.
 // Arguments are handled in the manner of fmt.Println.
 func Println(v ...interface{}) {
-	std.Output(2, fmt.Sprintln(v...))
+	std.Output(DEFAULT, 2, fmt.Sprintln(v...))
+}
+
+// Error calls OutputErr to print to the standard logger's error channel.
+// Arguments are handled in the manner of fmt.Print.
+func Error(v ...interface{}) {
+	std.Output(ERROR, 2, fmt.Sprint(v...))
+}
+
+// Errorf calls OutputErr to print to the standard logger's error channel.
+// Arguments are handled in the manner of fmt.Printf.
+func Errorf(format string, v ...interface{}) {
+	std.Output(ERROR, 2, fmt.Sprintf(format, v...))
+}
+
+// Errorln calls OutputErr to print to the standard logger's error channel.
+// Arguments are handled in the manner of fmt.Println.
+func Errorln(v ...interface{}) {
+	std.Output(ERROR, 2, fmt.Sprintln(v...))
 }
 
 // Fatal is equivalent to Print() followed by a call to os.Exit(1).
 func Fatal(v ...interface{}) {
-	std.Output(2, fmt.Sprint(v...))
+	std.Output(ERROR, 2, fmt.Sprint(v...))
 	os.Exit(1)
 }
 
 // Fatalf is equivalent to Printf() followed by a call to os.Exit(1).
 func Fatalf(format string, v ...interface{}) {
-	std.Output(2, fmt.Sprintf(format, v...))
+	std.Output(ERROR, 2, fmt.Sprintf(format, v...))
 	os.Exit(1)
 }
 
 // Fatalln is equivalent to Println() followed by a call to os.Exit(1).
 func Fatalln(v ...interface{}) {
-	std.Output(2, fmt.Sprintln(v...))
+	std.Output(ERROR, 2, fmt.Sprintln(v...))
 	os.Exit(1)
 }
 
 // Panic is equivalent to Print() followed by a call to panic().
 func Panic(v ...interface{}) {
 	s := fmt.Sprint(v...)
-	std.Output(2, s)
+	std.Output(ERROR, 2, s)
 	panic(s)
 }
 
 // Panicf is equivalent to Printf() followed by a call to panic().
 func Panicf(format string, v ...interface{}) {
 	s := fmt.Sprintf(format, v...)
-	std.Output(2, s)
+	std.Output(ERROR, 2, s)
 	panic(s)
 }
 
 // Panicln is equivalent to Println() followed by a call to panic().
 func Panicln(v ...interface{}) {
 	s := fmt.Sprintln(v...)
-	std.Output(2, s)
+	std.Output(ERROR, 2, s)
 	panic(s)
 }
 

pkg/middleware/basic_session.go

@@ -34,7 +34,7 @@ func loadBasicAuthSession(validator basic.Validator, next http.Handler) http.Han
 
 		session, err := getBasicSession(validator, req)
 		if err != nil {
-			logger.Printf("Error retrieving session from token in Authorization header: %v", err)
+			logger.Errorf("Error retrieving session from token in Authorization header: %v", err)
 		}
 
 		// Add the session to the scope if it was found

pkg/middleware/jwt_session.go

@@ -57,7 +57,7 @@ func (j *jwtSessionLoader) loadSession(next http.Handler) http.Handler {
 
 		session, err := j.getJwtSession(req)
 		if err != nil {
-			logger.Printf("Error retrieving session from token in Authorization header: %v", err)
+			logger.Errorf("Error retrieving session from token in Authorization header: %v", err)
 		}
 
 		// Add the session to the scope if it was found

pkg/middleware/stored_session.go

@@ -72,10 +72,10 @@ func (s *storedSessionLoader) loadSession(next http.Handler) http.Handler {
 		if err != nil {
 			// In the case when there was an error loading the session,
 			// we should clear the session
-			logger.Printf("Error loading cookied session: %v, removing session", err)
+			logger.Errorf("Error loading cookied session: %v, removing session", err)
 			err = s.store.Clear(rw, req)
 			if err != nil {
-				logger.Printf("Error removing session: %v", err)
+				logger.Errorf("Error removing session: %v", err)
 			}
 		}
 

pkg/sessions/cookie/session_store.go

@@ -176,7 +176,7 @@ func splitCookie(c *http.Cookie) []*http.Cookie {
 		return []*http.Cookie{c}
 	}
 
-	logger.Printf("WARNING: Multiple cookies are required for this session as it exceeds the 4kb cookie limit. Please use server side session storage (eg. Redis) instead.")
+	logger.Errorf("WARNING: Multiple cookies are required for this session as it exceeds the 4kb cookie limit. Please use server side session storage (eg. Redis) instead.")
 
 	cookies := []*http.Cookie{}
 	valueBytes := []byte(c.Value)

pkg/sessions/redis/redis_store.go

@@ -121,7 +121,7 @@ func buildStandaloneClient(opts options.RedisStoreOptions) (Client, error) {
 	if opts.CAPath != "" {
 		rootCAs, err := x509.SystemCertPool()
 		if err != nil {
-			logger.Printf("failed to load system cert pool for redis connection, falling back to empty cert pool")
+			logger.Errorf("failed to load system cert pool for redis connection, falling back to empty cert pool")
 		}
 		if rootCAs == nil {
 			rootCAs = x509.NewCertPool()
@@ -133,7 +133,7 @@ func buildStandaloneClient(opts options.RedisStoreOptions) (Client, error) {
 
 		// Append our cert to the system pool
 		if ok := rootCAs.AppendCertsFromPEM(certs); !ok {
-			logger.Printf("no certs appended, using system certs only")
+			logger.Errorf("no certs appended, using system certs only")
 		}
 
 		opt.TLSConfig.RootCAs = rootCAs

pkg/upstream/proxy.go

@@ -74,7 +74,7 @@ func (m *multiUpstreamProxy) registerHTTPUpstreamProxy(upstream options.Upstream
 // NewProxyErrorHandler creates a ProxyErrorHandler using the template given.
 func NewProxyErrorHandler(errorTemplate *template.Template, proxyPrefix string) ProxyErrorHandler {
 	return func(rw http.ResponseWriter, req *http.Request, proxyErr error) {
-		logger.Printf("Error proxying to upstream server: %v", proxyErr)
+		logger.Errorf("Error proxying to upstream server: %v", proxyErr)
 		rw.WriteHeader(http.StatusBadGateway)
 		data := struct {
 			Title       string

pkg/validation/logging.go

@@ -40,11 +40,12 @@ func configureLogger(o options.Logging, msgs []string) []string {
 
 	// Supply a sanity warning to the logger if all logging is disabled
 	if !o.StandardEnabled && !o.AuthEnabled && !o.RequestEnabled {
-		logger.Print("Warning: Logging disabled. No further logs will be shown.")
+		logger.Error("Warning: Logging disabled. No further logs will be shown.")
 	}
 
 	// Pass configuration values to the standard logger
 	logger.SetStandardEnabled(o.StandardEnabled)
+	logger.SetErrToInfo(o.ErrToInfo)
 	logger.SetAuthEnabled(o.AuthEnabled)
 	logger.SetReqEnabled(o.RequestEnabled)
 	logger.SetStandardTemplate(o.StandardFormat)

pkg/validation/options.go

@@ -92,7 +92,7 @@ func Validate(o *options.Options) error {
 				Do().
 				UnmarshalJSON()
 			if err != nil {
-				logger.Printf("error: failed to discover OIDC configuration: %v", err)
+				logger.Errorf("error: failed to discover OIDC configuration: %v", err)
 			} else {
 				// Prefer manually configured URLs. It's a bit unclear
 				// why you'd be doing discovery and also providing the URLs