refactor: move timing info to extra access log fields logic

accesslog/schema/access_log_record.go

@@ -107,7 +107,6 @@ type AccessLogRecord struct {
 	DisableSourceIPLogging bool
 	RedactQueryParams      string
 	RouterError            string
-	LogAttemptsDetails     bool
 	FailedAttempts         int
 	RoundTripSuccessful    bool
 	ExtraFields            []string
@@ -296,40 +295,33 @@ func (r *AccessLogRecord) makeRecord(performTruncate bool) []byte {
 	b.WriteString(`instance_id:`)
 	b.WriteDashOrStringValue(instanceId)
 
-	if r.LogAttemptsDetails {
-		// #nosec  G104 - ignore errors from writing the access log as it will only cause more errors to log this error
-		b.WriteString(`failed_attempts:`)
-		b.WriteIntValue(r.FailedAttempts)
-
-		// #nosec  G104 - ignore errors from writing the access log as it will only cause more errors to log this error
-		b.WriteString(`failed_attempts_time:`)
-		b.WriteDashOrFloatValue(r.failedAttemptsTime())
-
-		// #nosec  G104 - ignore errors from writing the access log as it will only cause more errors to log this error
-		b.WriteString(`dns_time:`)
-		b.WriteDashOrFloatValue(r.dnsTime())
-
-		// #nosec  G104 - ignore errors from writing the access log as it will only cause more errors to log this error
-		b.WriteString(`dial_time:`)
-		b.WriteDashOrFloatValue(r.dialTime())
-
-		// #nosec  G104 - ignore errors from writing the access log as it will only cause more errors to log this error
-		b.WriteString(`tls_time:`)
-		b.WriteDashOrFloatValue(r.tlsTime())
-
-		// #nosec  G104 - ignore errors from writing the access log as it will only cause more errors to log this error
-		b.WriteString(`backend_time:`)
-		b.WriteDashOrFloatValue(r.successfulAttemptTime())
-	}
-
 	// We have to consider the impact of iterating over a list. This technically allows to repeat
 	// some of the fields but it allows us to iterate over the list only once instead of once per
-	// field when we perform a [slices.Contains] check.
+	// field when we perform a [slices.Contains] check. When loading the fields the list is
+	// deduplicated so this shouldn't be a concern.
 	for _, field := range r.ExtraFields {
 		switch field {
+		case "backend_time":
+			b.WriteString(`backend_time:`)
+			b.WriteDashOrFloatValue(r.successfulAttemptTime())
+		case "dial_time":
+			b.WriteString(`dial_time:`)
+			b.WriteDashOrFloatValue(r.dialTime())
+		case "dns_time":
+			b.WriteString(`dns_time:`)
+			b.WriteDashOrFloatValue(r.dnsTime())
+		case "failed_attempts":
+			b.WriteString(`failed_attempts:`)
+			b.WriteIntValue(r.FailedAttempts)
+		case "failed_attempts_time":
+			b.WriteString(`failed_attempts_time:`)
+			b.WriteDashOrFloatValue(r.failedAttemptsTime())
 		case "local_address":
 			b.WriteString(`local_address:`)
 			b.WriteDashOrStringValue(r.LocalAddress)
+		case "tls_time":
+			b.WriteString(`tls_time:`)
+			b.WriteDashOrFloatValue(r.tlsTime())
 		}
 	}
 

accesslog/schema/access_log_record_test.go

@@ -315,40 +315,106 @@ var _ = Describe("AccessLogRecord", func() {
 			})
 		})
 
-		Context("when extra_fields is set to [local_address]", func() {
-			Context("and the local address is empty", func() {
-				It("makes a record with the local address set to -", func() {
-					record.ExtraFields = []string{"local_address"}
-
-					r := BufferReader(bytes.NewBufferString(record.LogMessage()))
-					Eventually(r).Should(Say(`local_address:"-"`))
+		Context("when extra_fields is set", func() {
+			Context("to [local_address]", func() {
+				Context("and the local address is empty", func() {
+					It("makes a record with the local address set to -", func() {
+						record.ExtraFields = []string{"local_address"}
+
+						r := BufferReader(bytes.NewBufferString(record.LogMessage()))
+						Eventually(r).Should(Say(`local_address:"-"`))
+					})
+				})
+				Context("and the local address contains an address", func() {
+					It("makes a record with the local address set to that address", func() {
+						record.ExtraFields = []string{"local_address"}
+						record.LocalAddress = "10.0.0.1:34823"
+
+						r := BufferReader(bytes.NewBufferString(record.LogMessage()))
+						Eventually(r).Should(Say(`local_address:"10.0.0.1:34823"`))
+					})
 				})
 			})
-			Context("and the local address contains an address", func() {
-				It("makes a record with the local address set to that address", func() {
-					record.ExtraFields = []string{"local_address"}
-					record.LocalAddress = "10.0.0.1:34823"
 
-					r := BufferReader(bytes.NewBufferString(record.LogMessage()))
-					Eventually(r).Should(Say(`local_address:"10.0.0.1:34823"`))
+			// ['failed_attempts', 'failed_attempts_time', 'dns_time', 'dial_time', 'tls_time', 'backend_time']
+			Context("to [failed_attempts failed_attempts_time dns_time dial_time tls_time backend_time]", func() {
+				It("adds all fields if set to true", func() {
+					record.ExtraFields = []string{"failed_attempts", "failed_attempts_time", "dns_time", "dial_time", "tls_time", "backend_time"}
+					record.FailedAttempts = 4
+					start := time.Now()
+					record.ReceivedAt = start.Add(1 * time.Second)
+					record.AppRequestStartedAt = start.Add(2 * time.Second)
+					record.LastFailedAttemptFinishedAt = start.Add(3 * time.Second)
+					record.DnsStartedAt = start.Add(4 * time.Second)
+					record.DnsFinishedAt = start.Add(5 * time.Second)
+					record.DialStartedAt = start.Add(6 * time.Second)
+					record.DialFinishedAt = start.Add(7 * time.Second)
+					record.TlsHandshakeStartedAt = start.Add(8 * time.Second)
+					record.TlsHandshakeFinishedAt = start.Add(9 * time.Second)
+					record.AppRequestFinishedAt = start.Add(10 * time.Second)
+					record.FinishedAt = start.Add(11 * time.Second)
+
+					var b bytes.Buffer
+					_, err := record.WriteTo(&b)
+					Expect(err).ToNot(HaveOccurred())
+
+					r := b.String()
+
+					Expect(r).To(ContainSubstring("failed_attempts:4"))
+					Expect(r).To(ContainSubstring("failed_attempts_time:1.0"))
+					Expect(r).To(ContainSubstring("dns_time:1.0"))
+					Expect(r).To(ContainSubstring("dial_time:1.0"))
+					Expect(r).To(ContainSubstring("tls_time:1.0"))
+					Expect(r).To(ContainSubstring("backend_time:7.0"))
 				})
-			})
-		})
 
-		Context("when extra_fields is set to [foobarbazz]", func() {
-			It("ignores it", func() {
-				record.ExtraFields = []string{"foobarbazz"}
-				record.LocalAddress = "10.0.0.1:34823"
+				It("adds all appropriate empty values if fields are unset", func() {
+					record.ExtraFields = []string{"failed_attempts", "failed_attempts_time", "dns_time", "dial_time", "tls_time", "backend_time"}
+					record.FailedAttempts = 0
 
-				r := BufferReader(bytes.NewBufferString(record.LogMessage()))
-				Consistently(r).ShouldNot(Say("foobarbazz"))
+					var b bytes.Buffer
+					_, err := record.WriteTo(&b)
+					Expect(err).ToNot(HaveOccurred())
+
+					r := b.String()
+
+					Expect(r).To(ContainSubstring(`failed_attempts:0`))
+					Expect(r).To(ContainSubstring(`failed_attempts_time:"-"`))
+					Expect(r).To(ContainSubstring(`dns_time:"-"`))
+					Expect(r).To(ContainSubstring(`dial_time:"-"`))
+					Expect(r).To(ContainSubstring(`tls_time:"-"`))
+				})
+
+				It("adds a '-' if there was no successful attempt", func() {
+					record.ExtraFields = []string{"failed_attempts", "failed_attempts_time", "dns_time", "dial_time", "tls_time", "backend_time"}
+					record.FailedAttempts = 1
+					record.RoundTripSuccessful = false
+
+					var b bytes.Buffer
+					_, err := record.WriteTo(&b)
+					Expect(err).ToNot(HaveOccurred())
+
+					r := b.String()
+
+					Expect(r).To(ContainSubstring(`backend_time:"-"`))
+				})
 			})
-			It("does not log local_address", func() {
-				record.ExtraFields = []string{"foobarbazz"}
-				record.LocalAddress = "10.0.0.1:34823"
 
-				r := BufferReader(bytes.NewBufferString(record.LogMessage()))
-				Consistently(r).ShouldNot(Say(`local_address:"10.0.0.1:34823"`))
+			Context("to [foobarbazz]", func() {
+				It("ignores it", func() {
+					record.ExtraFields = []string{"foobarbazz"}
+					record.LocalAddress = "10.0.0.1:34823"
+
+					r := BufferReader(bytes.NewBufferString(record.LogMessage()))
+					Consistently(r).ShouldNot(Say("foobarbazz"))
+				})
+				It("does not log local_address", func() {
+					record.ExtraFields = []string{"foobarbazz"}
+					record.LocalAddress = "10.0.0.1:34823"
+
+					r := BufferReader(bytes.NewBufferString(record.LogMessage()))
+					Consistently(r).ShouldNot(Say(`local_address:"10.0.0.1:34823"`))
+				})
 			})
 		})
 	})
@@ -456,87 +522,4 @@ var _ = Describe("AccessLogRecord", func() {
 			})
 		})
 	})
-
-	Describe("AttemptsDetails", func() {
-		It("does not add fields if set to false", func() {
-			record.LogAttemptsDetails = false
-			record.FailedAttempts = 4
-			record.AppRequestStartedAt = time.Now().Add(-time.Second)
-			record.AppRequestFinishedAt = time.Now()
-
-			var b bytes.Buffer
-			_, err := record.WriteTo(&b)
-			Expect(err).ToNot(HaveOccurred())
-
-			r := b.String()
-
-			Expect(r).ToNot(ContainSubstring("failed_attempts"))
-			Expect(r).ToNot(ContainSubstring("failed_attempts_time"))
-			Expect(r).ToNot(ContainSubstring("dns_time"))
-			Expect(r).ToNot(ContainSubstring("dial_time"))
-			Expect(r).ToNot(ContainSubstring("tls_time"))
-			Expect(r).ToNot(ContainSubstring("backend_time"))
-		})
-
-		It("adds all fields if set to true", func() {
-			record.LogAttemptsDetails = true
-			record.FailedAttempts = 4
-			start := time.Now()
-			record.ReceivedAt = start.Add(1 * time.Second)
-			record.AppRequestStartedAt = start.Add(2 * time.Second)
-			record.LastFailedAttemptFinishedAt = start.Add(3 * time.Second)
-			record.DnsStartedAt = start.Add(4 * time.Second)
-			record.DnsFinishedAt = start.Add(5 * time.Second)
-			record.DialStartedAt = start.Add(6 * time.Second)
-			record.DialFinishedAt = start.Add(7 * time.Second)
-			record.TlsHandshakeStartedAt = start.Add(8 * time.Second)
-			record.TlsHandshakeFinishedAt = start.Add(9 * time.Second)
-			record.AppRequestFinishedAt = start.Add(10 * time.Second)
-			record.FinishedAt = start.Add(11 * time.Second)
-
-			var b bytes.Buffer
-			_, err := record.WriteTo(&b)
-			Expect(err).ToNot(HaveOccurred())
-
-			r := b.String()
-
-			Expect(r).To(ContainSubstring("failed_attempts:4"))
-			Expect(r).To(ContainSubstring("failed_attempts_time:1.0"))
-			Expect(r).To(ContainSubstring("dns_time:1.0"))
-			Expect(r).To(ContainSubstring("dial_time:1.0"))
-			Expect(r).To(ContainSubstring("tls_time:1.0"))
-			Expect(r).To(ContainSubstring("backend_time:7.0"))
-		})
-
-		It("adds all appropriate empty values if fields are unset", func() {
-			record.LogAttemptsDetails = true
-			record.FailedAttempts = 0
-
-			var b bytes.Buffer
-			_, err := record.WriteTo(&b)
-			Expect(err).ToNot(HaveOccurred())
-
-			r := b.String()
-
-			Expect(r).To(ContainSubstring(`failed_attempts:0`))
-			Expect(r).To(ContainSubstring(`failed_attempts_time:"-"`))
-			Expect(r).To(ContainSubstring(`dns_time:"-"`))
-			Expect(r).To(ContainSubstring(`dial_time:"-"`))
-			Expect(r).To(ContainSubstring(`tls_time:"-"`))
-		})
-
-		It("adds a '-' if there was no successful attempt", func() {
-			record.LogAttemptsDetails = true
-			record.FailedAttempts = 1
-			record.RoundTripSuccessful = false
-
-			var b bytes.Buffer
-			_, err := record.WriteTo(&b)
-			Expect(err).ToNot(HaveOccurred())
-
-			r := b.String()
-
-			Expect(r).To(ContainSubstring(`backend_time:"-"`))
-		})
-	})
 })

config/config.go

@@ -184,7 +184,6 @@ type LoggingConfig struct {
 	DisableLogForwardedFor bool         `yaml:"disable_log_forwarded_for"`
 	DisableLogSourceIP     bool         `yaml:"disable_log_source_ip"`
 	RedactQueryParams      string       `yaml:"redact_query_params"`
-	EnableAttemptsDetails  bool         `yaml:"enable_attempts_details"`
 	Format                 FormatConfig `yaml:"format"`
 	ExtraAccessLogFields   []string     `yaml:"extra_access_log_fields"`
 
@@ -213,14 +212,13 @@ type TLSPem struct {
 }
 
 var defaultLoggingConfig = LoggingConfig{
-	Level:                 "debug",
-	MetronAddress:         "localhost:3457",
-	Format:                FormatConfig{"unix-epoch"},
-	JobName:               "gorouter",
-	RedactQueryParams:     REDACT_QUERY_PARMS_NONE,
-	EnableAttemptsDetails: false,
-	SyslogNetwork:         "udp",
-	SyslogAddr:            "127.0.0.1:514",
+	Level:             "debug",
+	MetronAddress:     "localhost:3457",
+	Format:            FormatConfig{"unix-epoch"},
+	JobName:           "gorouter",
+	RedactQueryParams: REDACT_QUERY_PARMS_NONE,
+	SyslogNetwork:     "udp",
+	SyslogAddr:        "127.0.0.1:514",
 }
 
 type HeaderNameValue struct {

config/config_test.go

@@ -435,7 +435,6 @@ suspend_pruning_if_nats_unavailable: true
 			Expect(config.Logging.DisableLogSourceIP).To(Equal(false))
 			Expect(config.Logging.RedactQueryParams).To(Equal("none"))
 			Expect(config.Logging.Format.Timestamp).To(Equal("unix-epoch"))
-			Expect(config.Logging.EnableAttemptsDetails).To(BeFalse())
 		})
 
 		It("sets default access log config", func() {
@@ -502,7 +501,6 @@ logging:
   syslog: syslog
   level: debug2
   loggregator_enabled: true
-  enable_attempts_details: true
   format:
     timestamp: just_log_something
 `)
@@ -514,7 +512,6 @@ logging:
 			Expect(config.Logging.LoggregatorEnabled).To(Equal(true))
 			Expect(config.Logging.JobName).To(Equal("gorouter"))
 			Expect(config.Logging.Format.Timestamp).To(Equal("just_log_something"))
-			Expect(config.Logging.EnableAttemptsDetails).To(BeTrue())
 		})
 
 		It("sets the rest of config", func() {

handlers/access_log.go

@@ -18,39 +18,35 @@ import (
 )
 
 type accessLog struct {
-	accessLogger       accesslog.AccessLogger
-	extraHeadersToLog  []string
-	logAttemptsDetails bool
-	extraFields        []string
-	logger             *slog.Logger
+	accessLogger      accesslog.AccessLogger
+	extraHeadersToLog []string
+	extraFields       []string
+	logger            *slog.Logger
 }
 
 // NewAccessLog creates a new handler that handles logging requests to the
 // access log
 func NewAccessLog(
 	accessLogger accesslog.AccessLogger,
 	extraHeadersToLog []string,
-	logAttemptsDetails bool,
 	extraFields []string,
 	logger *slog.Logger,
 ) negroni.Handler {
 	return &accessLog{
-		accessLogger:       accessLogger,
-		extraHeadersToLog:  extraHeadersToLog,
-		logAttemptsDetails: logAttemptsDetails,
-		extraFields:        deduplicate(extraFields),
-		logger:             logger,
+		accessLogger:      accessLogger,
+		extraHeadersToLog: extraHeadersToLog,
+		extraFields:       deduplicate(extraFields),
+		logger:            logger,
 	}
 }
 
 func (a *accessLog) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http.HandlerFunc) {
 	proxyWriter := rw.(utils.ProxyResponseWriter)
 
 	alr := &schema.AccessLogRecord{
-		Request:            r,
-		ExtraHeadersToLog:  a.extraHeadersToLog,
-		LogAttemptsDetails: a.logAttemptsDetails,
-		ExtraFields:        a.extraFields,
+		Request:           r,
+		ExtraHeadersToLog: a.extraHeadersToLog,
+		ExtraFields:       a.extraFields,
 	}
 
 	requestBodyCounter := &countingReadCloser{delegate: r.Body}