Make access log output deterministic by removing the map implementation

- Decided that since access logs are potentially being parsed in order-dependent ways, we wanted to be deterministic in our output. - Have to use a pointer to a slice in order to maintain shared state between zipkin handler and access log record Signed-off-by: Shash Reddy <sreddy@pivotal.io>
cloudfoundry · Sep 13, 2016 · 394ea17 · 394ea17
1 parent f1f9fd0
commit 394ea17
Show file tree

Hide file tree

Showing 9 changed files with 45 additions and 41 deletions.
diff --git a/access_log/schema/access_log_record.go b/access_log/schema/access_log_record.go
@@ -21,7 +21,7 @@ type AccessLogRecord struct {
 	FinishedAt           time.Time
 	BodyBytesSent        int
 	RequestBytesReceived int
-	ExtraHeadersToLog    map[string]struct{}
+	ExtraHeadersToLog    *[]string
 	record               string
 }
 
@@ -68,7 +68,7 @@ func (r *AccessLogRecord) makeRecord() string {
 		}
 	}
 
-	if r.ExtraHeadersToLog != nil && len(r.ExtraHeadersToLog) > 0 {
+	if r.ExtraHeadersToLog != nil && len(*r.ExtraHeadersToLog) > 0 {
 		extraHeaders = r.ExtraHeaders()
 	}
 
@@ -115,9 +115,9 @@ func (r *AccessLogRecord) LogMessage() string {
 }
 
 func (r *AccessLogRecord) ExtraHeaders() string {
-	extraHeaders := make([]string, 0, len(r.ExtraHeadersToLog)*4)
+	extraHeaders := make([]string, 0, len(*r.ExtraHeadersToLog)*4)
 
-	for header := range r.ExtraHeadersToLog {
+	for _, header := range *r.ExtraHeadersToLog {
 		// X-Something-Cool -> x_something_cool
 		headerName := strings.Replace(strings.ToLower(header), "-", "_", -1)
 		headerValue := strconv.Quote(r.FormatRequestHeader(header))

diff --git a/access_log/schema/access_log_record_test.go b/access_log/schema/access_log_record_test.go
@@ -127,12 +127,8 @@ var _ = Describe("AccessLogRecord", func() {
 			RouteEndpoint: &route.Endpoint{
 				ApplicationId: "FakeApplicationId",
 			},
-			StartedAt: time.Date(2000, time.January, 1, 0, 0, 0, 0, time.UTC),
-			ExtraHeadersToLog: map[string]struct{}{
-				"Cache-Control":   struct{}{},
-				"Accept-Encoding": struct{}{},
-				"If-Match":        struct{}{},
-				"Doesnt-Exist":    struct{}{}},
+			StartedAt:         time.Date(2000, time.January, 1, 0, 0, 0, 0, time.UTC),
+			ExtraHeadersToLog: &[]string{"Cache-Control", "Accept-Encoding", "If-Match", "Doesnt-Exist"},
 		}
 
 		recordString := "FakeRequestHost - " +

diff --git a/config/config.go b/config/config.go
@@ -130,8 +130,7 @@ type Config struct {
 	RouteServiceEnabled    bool          `yaml:"-"`
 	NatsClientPingInterval time.Duration `yaml:"-"`
 
-	ExtraHeadersToLogArray []string `yaml:"extra_headers_to_log"`
-	ExtraHeadersToLog      map[string]struct{}
+	ExtraHeadersToLog []string `yaml:"extra_headers_to_log"`
 
 	TokenFetcherMaxRetries                    uint32        `yaml:"token_fetcher_max_retries"`
 	TokenFetcherRetryInterval                 time.Duration `yaml:"token_fetcher_retry_interval"`
@@ -214,11 +213,6 @@ func (c *Config) Process() {
 	if c.RouteServiceSecret != "" {
 		c.RouteServiceEnabled = true
 	}
-
-	c.ExtraHeadersToLog = make(map[string]struct{})
-	for _, header := range c.ExtraHeadersToLogArray {
-		c.ExtraHeadersToLog[header] = struct{}{}
-	}
 }
 
 func (c *Config) processCipherSuites() []uint16 {

diff --git a/config/config_test.go b/config/config_test.go
@@ -396,8 +396,8 @@ extra_headers_to_log:
 			Expect(err).ToNot(HaveOccurred())
 			config.Process()
 
-			Expect(config.ExtraHeadersToLog).To(HaveKey("something"))
-			Expect(config.ExtraHeadersToLog).To(HaveKey("x-b3-trace-id"))
+			Expect(config.ExtraHeadersToLog).To(ContainElement("something"))
+			Expect(config.ExtraHeadersToLog).To(ContainElement("x-b3-trace-id"))
 		})
 
 		Context("When secure cookies is set to false", func() {

diff --git a/handlers/zipkin.go b/handlers/zipkin.go
@@ -12,10 +12,10 @@ import (
 type zipkin struct {
 	zipkinEnabled bool
 	logger        lager.Logger
-	headersToLog  map[string]struct{} // Shared state with proxy for access logs
+	headersToLog  *[]string // Shared state with proxy for access logs
 }
 
-func NewZipkin(enabled bool, headersToLog map[string]struct{}, logger lager.Logger) negroni.Handler {
+func NewZipkin(enabled bool, headersToLog *[]string, logger lager.Logger) negroni.Handler {
 	return &zipkin{
 		zipkinEnabled: enabled,
 		headersToLog:  headersToLog,
@@ -30,6 +30,20 @@ func (z *zipkin) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http.Ha
 	}
 	router_http.SetB3Headers(r, z.logger)
 
-	z.headersToLog[router_http.B3TraceIdHeader] = struct{}{}
-	z.headersToLog[router_http.B3SpanIdHeader] = struct{}{}
+	if !contains(*z.headersToLog, router_http.B3TraceIdHeader) {
+		*z.headersToLog = append(*z.headersToLog, router_http.B3TraceIdHeader)
+	}
+
+	if !contains(*z.headersToLog, router_http.B3SpanIdHeader) {
+		*z.headersToLog = append(*z.headersToLog, router_http.B3SpanIdHeader)
+	}
+}
+
+func contains(s []string, e string) bool {
+	for _, a := range s {
+		if a == e {
+			return true
+		}
+	}
+	return false
 }
diff --git a/handlers/zipkin_test.go b/handlers/zipkin_test.go
@@ -19,7 +19,7 @@ import (
 var _ = Describe("Zipkin", func() {
 	var (
 		handler      negroni.Handler
-		headersToLog map[string]struct{}
+		headersToLog *[]string
 		logger       lager.Logger
 		resp         http.ResponseWriter
 		req          *http.Request
@@ -31,7 +31,7 @@ var _ = Describe("Zipkin", func() {
 	})
 
 	BeforeEach(func() {
-		headersToLog = make(map[string]struct{})
+		headersToLog = &[]string{}
 		logger = lagertest.NewTestLogger("zipkin")
 		req = test_util.NewRequest("GET", "example.com", "/", nil)
 		resp = httptest.NewRecorder()
@@ -55,8 +55,8 @@ var _ = Describe("Zipkin", func() {
 
 		It("adds zipkin headers to access log record", func() {
 			handler.ServeHTTP(resp, req, nextHandler)
-			Expect(headersToLog).To(HaveKey(router_http.B3SpanIdHeader))
-			Expect(headersToLog).To(HaveKey(router_http.B3TraceIdHeader))
+			Expect(*headersToLog).To(ContainElement(router_http.B3SpanIdHeader))
+			Expect(*headersToLog).To(ContainElement(router_http.B3TraceIdHeader))
 		})
 
 		Context("with B3TraceIdHeader already set", func() {
@@ -72,13 +72,13 @@ var _ = Describe("Zipkin", func() {
 
 		Context("when X-B3-* headers are already set to be logged", func() {
 			BeforeEach(func() {
-				headersToLog[router_http.B3SpanIdHeader] = struct{}{}
-				headersToLog[router_http.B3TraceIdHeader] = struct{}{}
+				newSlice := []string{router_http.B3TraceIdHeader, router_http.B3SpanIdHeader}
+				headersToLog = &newSlice
 			})
 			It("adds zipkin headers to access log record", func() {
 				handler.ServeHTTP(resp, req, nextHandler)
-				Expect(headersToLog).To(HaveKey(router_http.B3SpanIdHeader))
-				Expect(headersToLog).To(HaveKey(router_http.B3TraceIdHeader))
+				Expect(*headersToLog).To(ContainElement(router_http.B3SpanIdHeader))
+				Expect(*headersToLog).To(ContainElement(router_http.B3TraceIdHeader))
 			})
 		})
 	})
@@ -96,19 +96,19 @@ var _ = Describe("Zipkin", func() {
 
 		It("does not add zipkin headers to access log record", func() {
 			handler.ServeHTTP(resp, req, nextHandler)
-			Expect(headersToLog).NotTo(HaveKey(router_http.B3SpanIdHeader))
-			Expect(headersToLog).NotTo(HaveKey(router_http.B3TraceIdHeader))
+			Expect(*headersToLog).NotTo(ContainElement(router_http.B3SpanIdHeader))
+			Expect(*headersToLog).NotTo(ContainElement(router_http.B3TraceIdHeader))
 		})
 
 		Context("when X-B3-* headers are already set to be logged", func() {
 			BeforeEach(func() {
-				headersToLog[router_http.B3SpanIdHeader] = struct{}{}
-				headersToLog[router_http.B3TraceIdHeader] = struct{}{}
+				newSlice := []string{router_http.B3TraceIdHeader, router_http.B3SpanIdHeader}
+				headersToLog = &newSlice
 			})
 			It("adds zipkin headers to access log record", func() {
 				handler.ServeHTTP(resp, req, nextHandler)
-				Expect(headersToLog).To(HaveKey(router_http.B3SpanIdHeader))
-				Expect(headersToLog).To(HaveKey(router_http.B3TraceIdHeader))
+				Expect(*headersToLog).To(ContainElement(router_http.B3SpanIdHeader))
+				Expect(*headersToLog).To(ContainElement(router_http.B3TraceIdHeader))
 			})
 		})
 	})

diff --git a/main.go b/main.go
@@ -179,7 +179,7 @@ func buildProxy(logger lager.Logger, c *config.Config, registry rregistry.Regist
 		RouteServiceRecommendHttps: c.RouteServiceRecommendHttps,
 		Crypto:               crypto,
 		CryptoPrev:           cryptoPrev,
-		ExtraHeadersToLog:    c.ExtraHeadersToLog,
+		ExtraHeadersToLog:    &c.ExtraHeadersToLog,
 		HealthCheckUserAgent: c.HealthCheckUserAgent,
 		EnableZipkin:         c.Tracing.EnableZipkin,
 	}

diff --git a/proxy/proxy.go b/proxy/proxy.go
@@ -57,7 +57,7 @@ type ProxyArgs struct {
 	RouteServiceRecommendHttps bool
 	Crypto                     secure.Crypto
 	CryptoPrev                 secure.Crypto
-	ExtraHeadersToLog          map[string]struct{}
+	ExtraHeadersToLog          *[]string
 	Logger                     lager.Logger
 	HealthCheckUserAgent       string
 	EnableZipkin               bool
@@ -87,7 +87,7 @@ type proxy struct {
 	secureCookies              bool
 	heartbeatOK                int32
 	routeServiceConfig         *route_service.RouteServiceConfig
-	extraHeadersToLog          map[string]struct{}
+	extraHeadersToLog          *[]string
 	routeServiceRecommendHttps bool
 	healthCheckUserAgent       string
 }

diff --git a/proxy/proxy_suite_test.go b/proxy/proxy_suite_test.go
@@ -93,7 +93,7 @@ var _ = JustBeforeEach(func() {
 		RouteServiceRecommendHttps: recommendHttps,
 		HealthCheckUserAgent:       "HTTP-Monitor/1.1",
 		EnableZipkin:               conf.Tracing.EnableZipkin,
-		ExtraHeadersToLog:          conf.ExtraHeadersToLog,
+		ExtraHeadersToLog:          &conf.ExtraHeadersToLog,
 	})
 
 	proxyServer, err = net.Listen("tcp", "127.0.0.1:0")