Syslog Improvements (2) (cloudfoundry#459)

* feat: make syslog logging useable

* do not log an empty new line when writing to syslog
* allow operator to configure truncation on syslog

* fix: allow syslog-only logging

* feat: replace log/syslog with internal version

The go standard library implementation of log/syslog has been abandoned
and is no longer maintained. In our tests with syslog logging in
gorouter we noticed a significant performance penalty over file based
logging. However, with file based logging we frequently observe broken
logs because logrotate interferes with log reading / writing.

This commit inlines the relevant file from log/syslog and refactors the
implementation to be on-par with the file based logging.

Co-authored-by: Alexander Lais <alexander.lais@sap.com>

* fix: rename testState.newRequest -> testState.newGetRequest

* test: add integration test for syslog access logs

* test: check errors

---------

Co-authored-by: Alexander Lais <alexander.lais@sap.com>

accesslog/file_and_loggregator_access_logger.go

@@ -4,10 +4,10 @@ import (
 	"fmt"
 	"io"
 	"log/slog"
-	"log/syslog"
 	"os"
 
 	"code.cloudfoundry.org/gorouter/accesslog/schema"
+	"code.cloudfoundry.org/gorouter/accesslog/syslog"
 	"code.cloudfoundry.org/gorouter/config"
 	log "code.cloudfoundry.org/gorouter/logger"
 )
@@ -38,14 +38,54 @@ type FileAndLoggregatorAccessLogger struct {
 	logsender              schema.LogSender
 }
 
-type CustomWriter struct {
-	Name            string
-	Writer          io.Writer
-	PerformTruncate bool
+type CustomWriter interface {
+	Name() string
+	io.Writer
+}
+
+// SyslogWriter sends logs to a [syslog.Writer].
+type SyslogWriter struct {
+	name     string
+	truncate int
+	*syslog.Writer
+}
+
+func (w *SyslogWriter) Name() string {
+	return w.name
+}
+
+func (w *SyslogWriter) Write(b []byte) (int, error) {
+	n := len(b)
+	if w.truncate > 0 && n > w.truncate {
+		n = w.truncate
+	}
+	return w.Writer.Write(b[:n])
+}
+
+// FileWriter sends logs to a [os.File] and appends a new line to each line written to seperate log
+// lines.
+type FileWriter struct {
+	name string
+	*os.File
+}
+
+func (w *FileWriter) Name() string {
+	return w.name
+}
+
+func (w *FileWriter) Write(b []byte) (int, error) {
+	n, err := w.File.Write(b)
+	if err != nil {
+		return n, err
+	}
+
+	// Do not count the extra bytes, we can not return more than len(b).
+	_, err = w.File.Write([]byte{'\n'})
+	return n, err
 }
 
 func CreateRunningAccessLogger(logger *slog.Logger, logsender schema.LogSender, config *config.Config) (AccessLogger, error) {
-	if config.AccessLog.File == "" && !config.Logging.LoggregatorEnabled {
+	if config.AccessLog.File == "" && !config.Logging.LoggregatorEnabled && !config.AccessLog.EnableStreaming {
 		return &NullAccessLogger{}, nil
 	}
 
@@ -66,17 +106,24 @@ func CreateRunningAccessLogger(logger *slog.Logger, logsender schema.LogSender,
 			return nil, err
 		}
 
-		accessLogger.addWriter(CustomWriter{Name: "accesslog", Writer: file, PerformTruncate: false})
+		accessLogger.addWriter(&FileWriter{
+			name: "accesslog",
+			File: file,
+		})
 	}
 
 	if config.AccessLog.EnableStreaming {
-		syslogWriter, err := syslog.Dial(config.Logging.SyslogNetwork, config.Logging.SyslogAddr, syslog.LOG_INFO, config.Logging.Syslog)
+		syslogWriter, err := syslog.Dial(config.Logging.SyslogNetwork, config.Logging.SyslogAddr, syslog.SeverityInfo, syslog.FacilityUser, config.Logging.Syslog)
 		if err != nil {
 			logger.Error("error-creating-syslog-writer", log.ErrAttr(err))
 			return nil, err
 		}
 
-		accessLogger.addWriter(CustomWriter{Name: "syslog", Writer: syslogWriter, PerformTruncate: true})
+		accessLogger.addWriter(&SyslogWriter{
+			name:     "syslog",
+			truncate: config.Logging.SyslogTruncate,
+			Writer:   syslogWriter,
+		})
 	}
 
 	go accessLogger.Run()
@@ -88,9 +135,9 @@ func (x *FileAndLoggregatorAccessLogger) Run() {
 		select {
 		case record := <-x.channel:
 			for _, w := range x.writers {
-				_, err := record.WriteTo(w.Writer)
+				_, err := record.WriteTo(w)
 				if err != nil {
-					x.logger.Error(fmt.Sprintf("error-emitting-access-log-to-writer-%s", w.Name), log.ErrAttr(err))
+					x.logger.Error(fmt.Sprintf("error-emitting-access-log-to-writer-%s", w.Name()), log.ErrAttr(err))
 				}
 			}
 			record.SendLog(x.logsender)

accesslog/file_and_loggregator_access_logger_test.go

@@ -360,7 +360,8 @@ var _ = Describe("AccessLog", func() {
 			cfg.AccessLog.File = ""
 			cfg.AccessLog.EnableStreaming = false
 
-			accessLogger, _ := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			accessLogger, err := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			Expect(err).NotTo(HaveOccurred())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).FileWriters()).To(BeEmpty())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).WriterCount()).To(Equal(0))
 		})
@@ -369,7 +370,8 @@ var _ = Describe("AccessLog", func() {
 			cfg.AccessLog.File = "/dev/null"
 			cfg.AccessLog.EnableStreaming = false
 
-			accessLogger, _ := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			accessLogger, err := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			Expect(err).NotTo(HaveOccurred())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).FileWriters()).ToNot(BeEmpty())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).WriterCount()).To(Equal(1))
 		})
@@ -379,7 +381,8 @@ var _ = Describe("AccessLog", func() {
 			cfg.AccessLog.File = "/dev/null"
 			cfg.AccessLog.EnableStreaming = false
 
-			accessLogger, _ := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			accessLogger, err := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			Expect(err).NotTo(HaveOccurred())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).FileWriters()).ToNot(BeEmpty())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).WriterCount()).To(Equal(1))
 		})
@@ -389,7 +392,8 @@ var _ = Describe("AccessLog", func() {
 			cfg.AccessLog.File = "/dev/null"
 			cfg.AccessLog.EnableStreaming = true
 
-			accessLogger, _ := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			accessLogger, err := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			Expect(err).NotTo(HaveOccurred())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).FileWriters()).ToNot(BeNil())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).WriterCount()).To(Equal(2))
 		})
@@ -399,7 +403,8 @@ var _ = Describe("AccessLog", func() {
 			cfg.AccessLog.File = "/dev/null"
 			cfg.AccessLog.EnableStreaming = false
 
-			accessLogger, _ := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			accessLogger, err := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			Expect(err).NotTo(HaveOccurred())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).FileWriters()).ToNot(BeNil())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).WriterCount()).To(Equal(1))
 		})
@@ -409,7 +414,8 @@ var _ = Describe("AccessLog", func() {
 			cfg.AccessLog.File = ""
 			cfg.AccessLog.EnableStreaming = true
 
-			accessLogger, _ := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			accessLogger, err := accesslog.CreateRunningAccessLogger(logger.Logger, ls, cfg)
+			Expect(err).NotTo(HaveOccurred())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).FileWriters()).ToNot(BeNil())
 			Expect(accessLogger.(*accesslog.FileAndLoggregatorAccessLogger).WriterCount()).To(Equal(1))
 		})

accesslog/schema/access_log_record.go

@@ -373,12 +373,8 @@ func formatHeader(headers http.Header, name string, performTruncate bool) string
 
 // WriteTo allows the AccessLogRecord to implement the io.WriterTo interface
 func (r *AccessLogRecord) WriteTo(w io.Writer) (int64, error) {
-	bytesWritten, err := w.Write(r.getRecord(false))
-	if err != nil {
-		return int64(bytesWritten), err
-	}
-	newline, err := w.Write([]byte("\n"))
-	return int64(bytesWritten + newline), err
+	n, err := w.Write(r.getRecord(false))
+	return int64(n), err
 }
 
 func (r *AccessLogRecord) SendLog(ls LogSender) {

accesslog/schema/access_log_record_test.go

@@ -330,7 +330,7 @@ var _ = Describe("AccessLogRecord", func() {
 			Eventually(r).Should(Say(`x_forwarded_proto:"FakeOriginalRequestProto" `))
 			Eventually(r).Should(Say(`vcap_request_id:"abc-123-xyz-pdq" response_time:60.000000 gorouter_time:10.000000 app_id:"FakeApplicationId" `))
 			Eventually(r).Should(Say(`app_index:"3"`))
-			Eventually(r).Should(Say(`x_cf_routererror:"some-router-error"\n`))
+			Eventually(r).Should(Say(`x_cf_routererror:"some-router-error"`))
 		})
 
 		Context("when the AccessLogRecord is too large for UDP", func() {