Log referrer header at a configurable rate

.gitignore

@@ -1,8 +1,22 @@
+# Compiled Object files, Static and Dynamic libs (Shared Objects)
+*.o
+*.a
+*.so
+
 # dep directory
 vendor
 
 # build artifacts
 prebid-cache
 
 # ide
-.vscode/
+.vscode/
+
+# autogenerated mac file
+
+.DS_Store
+
+# Autogenerated Vim swap files
+*~
+*.swp
+*.swo

config.yaml

@@ -10,6 +10,8 @@ request_limits:
   max_size_bytes: 10240 # 10K
   max_num_values: 10
   max_ttl_seconds: 3600
+request_logging:
+  referer_sampling_rate: 1.0
 backend:
   type: "memory" # Switch to be "aerospike", "cassandra", "memcache", "ignite" or "redis" for production.
 # aerospike:

config/config.go

@@ -97,6 +97,7 @@ func setConfigDefaults(v *viper.Viper) {
 	v.SetDefault("request_limits.max_num_values", utils.REQUEST_MAX_NUM_VALUES)
 	v.SetDefault("request_limits.max_ttl_seconds", utils.REQUEST_MAX_TTL_SECONDS)
 	v.SetDefault("request_limits.max_header_size_bytes", http.DefaultMaxHeaderBytes)
+	v.SetDefault("request_logging.referer_sampling_rate", 0.0)
 	v.SetDefault("routes.allow_public_write", true)
 }
 
@@ -114,17 +115,19 @@ func setEnvVarsLookup(v *viper.Viper) {
 }
 
 type Configuration struct {
-	Port           int           `mapstructure:"port"`
-	AdminPort      int           `mapstructure:"admin_port"`
-	IndexResponse  string        `mapstructure:"index_response"`
-	Log            Log           `mapstructure:"log"`
-	RateLimiting   RateLimiting  `mapstructure:"rate_limiter"`
-	RequestLimits  RequestLimits `mapstructure:"request_limits"`
-	StatusResponse string        `mapstructure:"status_response"`
-	Backend        Backend       `mapstructure:"backend"`
-	Compression    Compression   `mapstructure:"compression"`
-	Metrics        Metrics       `mapstructure:"metrics"`
-	Routes         Routes        `mapstructure:"routes"`
+	Port           int            `mapstructure:"port"`
+	AdminPort      int            `mapstructure:"admin_port"`
+	IndexResponse  string         `mapstructure:"index_response"`
+	Log            Log            `mapstructure:"log"`
+	RateLimiting   RateLimiting   `mapstructure:"rate_limiter"`
+	RequestLimits  RequestLimits  `mapstructure:"request_limits"`
+	RequestLogging RequestLogging `mapstructure:"request_logging"`
+
+	StatusResponse string      `mapstructure:"status_response"`
+	Backend        Backend     `mapstructure:"backend"`
+	Compression    Compression `mapstructure:"compression"`
+	Metrics        Metrics     `mapstructure:"metrics"`
+	Routes         Routes      `mapstructure:"routes"`
 }
 
 // ValidateAndLog validates the config, terminating the program on any errors.
@@ -136,6 +139,7 @@ func (cfg *Configuration) ValidateAndLog() {
 	cfg.Log.validateAndLog()
 	cfg.RateLimiting.validateAndLog()
 	cfg.RequestLimits.validateAndLog()
+	cfg.RequestLogging.validateAndLog()
 
 	if err := cfg.Backend.validateAndLog(); err != nil {
 		log.Fatalf("%s", err.Error())
@@ -176,6 +180,21 @@ func (cfg *RateLimiting) validateAndLog() {
 	log.Infof("config.rate_limiter.num_requests: %d", cfg.MaxRequestsPerSecond)
 }
 
+type RequestLogging struct {
+	// RefererSamplingRate represents the probability of Prebid Cache loging the incoming request referer header
+	// chance = 1.0 => always log,
+	// chance = 0.0 => never log
+	RefererSamplingRate float32 `mapstructure:"referer_sampling_rate"`
+}
+
+func (cfg *RequestLogging) validateAndLog() {
+	if cfg.RefererSamplingRate >= 0.0 && cfg.RefererSamplingRate <= 1.0 {
+		log.Infof("config.request_logging.referer_sampling_rate: %.2f", cfg.RefererSamplingRate)
+	} else {
+		log.Fatalf("invalid config.request_logging.referer_sampling_rate: value must be positive and not greater than 1.0. Got %.2f", cfg.RefererSamplingRate)
+	}
+}
+
 type RequestLimits struct {
 	MaxSize          int  `mapstructure:"max_size_bytes"`
 	MaxNumValues     int  `mapstructure:"max_num_values"`

config/config_test.go

@@ -915,6 +915,88 @@ func TestRequestLimitsValidateAndLog(t *testing.T) {
 	}
 }
 
+func TestRequestLogging(t *testing.T) {
+	hook := testLogrus.NewGlobal()
+
+	type logComponents struct {
+		msg string
+		lvl logrus.Level
+	}
+
+	testCases := []struct {
+		desc                string
+		inRequestLoggingCfg *RequestLogging
+		expectedLogInfo     []logComponents
+	}{
+		{
+			desc: "negative sampling rate, expect fatal log",
+			inRequestLoggingCfg: &RequestLogging{
+				RefererSamplingRate: -0.1,
+			},
+			expectedLogInfo: []logComponents{
+				{msg: `invalid config.request_logging.referer_sampling_rate: value must be positive and not greater than 1.0. Got -0.10`, lvl: logrus.FatalLevel},
+			},
+		},
+		{
+			desc: "Sampling rate greater than 1.0, expect fatal log",
+			inRequestLoggingCfg: &RequestLogging{
+				RefererSamplingRate: 1.1,
+			},
+			expectedLogInfo: []logComponents{
+				{msg: `invalid config.request_logging.referer_sampling_rate: value must be positive and not greater than 1.0. Got 1.10`, lvl: logrus.FatalLevel},
+			},
+		},
+		{
+			desc: "Sampling rate of 1.0 is between the acceptable threshold. Expect info log",
+			inRequestLoggingCfg: &RequestLogging{
+				RefererSamplingRate: 1.0,
+			},
+			expectedLogInfo: []logComponents{
+				{msg: `config.request_logging.referer_sampling_rate: 1.00`, lvl: logrus.InfoLevel},
+			},
+		},
+		{
+			desc: "Sampling rate of 0.0 is between the acceptable threshold. Expect info log",
+			inRequestLoggingCfg: &RequestLogging{
+				RefererSamplingRate: 0.0,
+			},
+			expectedLogInfo: []logComponents{
+				{msg: `config.request_logging.referer_sampling_rate: 0.00`, lvl: logrus.InfoLevel},
+			},
+		},
+		{
+			desc: "Sampling rate of 0.6814 is between the acceptable threshold. Expect info log",
+			inRequestLoggingCfg: &RequestLogging{
+				RefererSamplingRate: 0.6814,
+			},
+			expectedLogInfo: []logComponents{
+				{msg: `config.request_logging.referer_sampling_rate: 0.68`, lvl: logrus.InfoLevel},
+			},
+		},
+	}
+
+	//substitute logger exit function so execution doesn't get interrupted
+	defer func() { logrus.StandardLogger().ExitFunc = nil }()
+	logrus.StandardLogger().ExitFunc = func(int) {}
+
+	for _, tc := range testCases {
+		//Run
+		tc.inRequestLoggingCfg.validateAndLog()
+
+		//Assert
+		if assert.Len(t, hook.Entries, len(tc.expectedLogInfo), tc.desc+":different number of entries") {
+			for i := 0; i < len(tc.expectedLogInfo); i++ {
+				assert.Equal(t, tc.expectedLogInfo[i].msg, hook.Entries[i].Message, tc.desc+":message")
+				assert.Equal(t, tc.expectedLogInfo[i].lvl, hook.Entries[i].Level, tc.desc+":log level")
+			}
+		}
+
+		//Reset log after every test and assert successful reset
+		hook.Reset()
+		assert.Nil(t, hook.LastEntry())
+	}
+}
+
 func TestCompressionValidateAndLog(t *testing.T) {
 
 	// logrus entries will be recorded to this `hook` object so we can compare and assert them
@@ -1091,6 +1173,7 @@ func TestConfigurationValidateAndLog(t *testing.T) {
 		{msg: fmt.Sprintf("config.request_limits.max_size_bytes: %d", expectedConfig.RequestLimits.MaxSize), lvl: logrus.InfoLevel},
 		{msg: fmt.Sprintf("config.request_limits.max_num_values: %d", expectedConfig.RequestLimits.MaxNumValues), lvl: logrus.InfoLevel},
 		{msg: fmt.Sprintf("config.request_limits.max_header_size_bytes: %d", expectedConfig.RequestLimits.MaxHeaderSize), lvl: logrus.InfoLevel},
+		{msg: fmt.Sprintf("config.request_logging.referer_sampling_rate: %.2f", expectedConfig.RequestLogging.RefererSamplingRate), lvl: logrus.InfoLevel},
 		{msg: fmt.Sprintf("config.backend.type: %s", expectedConfig.Backend.Type), lvl: logrus.InfoLevel},
 		{msg: fmt.Sprintf("config.compression.type: %s", expectedConfig.Compression.Type), lvl: logrus.InfoLevel},
 		{msg: fmt.Sprintf("Prebid Cache will run without metrics"), lvl: logrus.InfoLevel},
@@ -1228,6 +1311,9 @@ func getExpectedDefaultConfig() Configuration {
 			Enabled:              true,
 			MaxRequestsPerSecond: 100,
 		},
+		RequestLogging: RequestLogging{
+			RefererSamplingRate: 0.00,
+		},
 		RequestLimits: RequestLimits{
 			MaxSize:       10240,
 			MaxNumValues:  10,

endpoints/get.go

@@ -16,20 +16,28 @@ import (
 
 // GetHandler serves "GET /cache" requests.
 type GetHandler struct {
-	backend         backends.Backend
-	metrics         *metrics.Metrics
+	backend backends.Backend
+	metrics *metrics.Metrics
+	cfg     getHandlerConfig
+}
+
+type getHandlerConfig struct {
 	allowCustomKeys bool
+	refererLogRate  float32
 }
 
 // NewGetHandler returns the handle function for the "/cache" endpoint when it receives a GET request
-func NewGetHandler(storage backends.Backend, metrics *metrics.Metrics, allowCustomKeys bool) func(w http.ResponseWriter, r *http.Request, ps httprouter.Params) {
+func NewGetHandler(storage backends.Backend, metrics *metrics.Metrics, allowCustomKeys bool, refererSamplingRate float32) func(w http.ResponseWriter, r *http.Request, ps httprouter.Params) {
 	getHandler := &GetHandler{
 		// Assign storage client to get endpoint
 		backend: storage,
 		// pass metrics engine
 		metrics: metrics,
-		// Pass configuration value
-		allowCustomKeys: allowCustomKeys,
+		// Pass configuration values
+		cfg: getHandlerConfig{
+			allowCustomKeys: allowCustomKeys,
+			refererLogRate:  refererSamplingRate,
+		},
 	}
 
 	// Return handle function
@@ -38,9 +46,16 @@ func NewGetHandler(storage backends.Backend, metrics *metrics.Metrics, allowCust
 
 func (e *GetHandler) handle(w http.ResponseWriter, r *http.Request, ps httprouter.Params) {
 	e.metrics.RecordGetTotal()
+
+	if utils.RandomPick(e.cfg.refererLogRate) == true {
+		if refererHeaderValue := r.Header.Get(utils.REFERER_HEADER_KEY); refererHeaderValue != "" {
+			log.Info("Incoming request Referer header: " + refererHeaderValue)
+		}
+	}
+
 	start := time.Now()
 
-	uuid, parseErr := parseUUID(r, e.allowCustomKeys)
+	uuid, parseErr := parseUUID(r, e.cfg.allowCustomKeys)
 	if parseErr != nil {
 		// parseUUID either returns http.StatusBadRequest or http.StatusNotFound. Both should be
 		// accounted using RecordGetBadRequest()

endpoints/get_test.go

@@ -33,7 +33,7 @@ func TestGetJsonTests(t *testing.T) {
 		}
 
 		router := httprouter.New()
-		router.GET("/cache", NewGetHandler(backend, m, tc.HostConfig.AllowSettingKeys))
+		router.GET("/cache", NewGetHandler(backend, m, tc.HostConfig.AllowSettingKeys, tc.HostConfig.RefererLogRate))
 		request, err := http.NewRequest("GET", "/cache?"+tc.Query, nil)
 		if !assert.NoError(t, err, "Failed to create a GET request: %v", err) {
 			hook.Reset()
@@ -82,7 +82,7 @@ func TestGetInvalidUUIDs(t *testing.T) {
 		},
 	}
 
-	router.GET("/cache", NewGetHandler(backend, m, false))
+	router.GET("/cache", NewGetHandler(backend, m, false, 0.0))
 
 	getResults := doMockGet(t, router, "fdd9405b-ef2b-46da-a55a-2f526d338e16")
 	if getResults.Code != http.StatusNotFound {
@@ -108,9 +108,13 @@ func TestGetHandler(t *testing.T) {
 		msg string
 		lvl logrus.Level
 	}
+	type testConfig struct {
+		allowKeys           bool
+		refererSamplingRate float32
+	}
 	type testInput struct {
-		uuid      string
-		allowKeys bool
+		uuid string
+		cfg  testConfig
 	}
 	type testOutput struct {
 		responseCode    int
@@ -127,8 +131,8 @@ func TestGetHandler(t *testing.T) {
 		{
 			"Missing UUID. Return http error but don't interrupt server's execution",
 			testInput{
-				uuid:      "",
-				allowKeys: false,
+				uuid: "",
+				cfg:  testConfig{allowKeys: false},
 			},
 			testOutput{
 				responseCode: http.StatusBadRequest,
@@ -148,8 +152,8 @@ func TestGetHandler(t *testing.T) {
 		{
 			"Prebid Cache wasn't configured to allow custom keys therefore, it doesn't allow for keys different than 36 char long. Respond with http error and don't interrupt server's execution",
 			testInput{
-				uuid:      "non-36-char-key-maps-to-json",
-				allowKeys: false,
+				uuid: "non-36-char-key-maps-to-json",
+				cfg:  testConfig{allowKeys: false},
 			},
 			testOutput{
 				responseCode: http.StatusNotFound,
@@ -169,8 +173,8 @@ func TestGetHandler(t *testing.T) {
 		{
 			"Configuration that allows custom keys. These are not required to be 36 char long. Since the uuid maps to a value, return it along a 200 status code",
 			testInput{
-				uuid:      "non-36-char-key-maps-to-json",
-				allowKeys: true,
+				uuid: "non-36-char-key-maps-to-json",
+				cfg:  testConfig{allowKeys: true},
 			},
 			testOutput{
 				responseCode: http.StatusOK,
@@ -260,7 +264,7 @@ func TestGetHandler(t *testing.T) {
 				&mockMetrics,
 			},
 		}
-		router.GET("/cache", NewGetHandler(backend, m, test.in.allowKeys))
+		router.GET("/cache", NewGetHandler(backend, m, test.in.cfg.allowKeys, test.in.cfg.refererSamplingRate))
 
 		// Run test
 		getResults := httptest.NewRecorder()

endpoints/put.go

@@ -26,8 +26,9 @@ type PutHandler struct {
 }
 
 type putHandlerConfig struct {
-	maxNumValues int
-	allowKeys    bool
+	maxNumValues   int
+	allowKeys      bool
+	refererLogRate float32
 }
 
 type syncPools struct {
@@ -36,7 +37,7 @@ type syncPools struct {
 }
 
 // NewPutHandler returns the handle function for the "/cache" endpoint when it receives a POST request
-func NewPutHandler(storage backends.Backend, metrics *metrics.Metrics, maxNumValues int, allowKeys bool) func(http.ResponseWriter, *http.Request, httprouter.Params) {
+func NewPutHandler(storage backends.Backend, metrics *metrics.Metrics, maxNumValues int, allowKeys bool, refererLogRate float32) func(http.ResponseWriter, *http.Request, httprouter.Params) {
 	putHandler := &PutHandler{}
 
 	// Assign storage client to put endpoint
@@ -47,8 +48,9 @@ func NewPutHandler(storage backends.Backend, metrics *metrics.Metrics, maxNumVal
 
 	// Pass configuration values
 	putHandler.cfg = putHandlerConfig{
-		maxNumValues: maxNumValues,
-		allowKeys:    allowKeys,
+		maxNumValues:   maxNumValues,
+		allowKeys:      allowKeys,
+		refererLogRate: refererLogRate,
 	}
 
 	// Instantiate thread-safe memory pools
@@ -184,6 +186,12 @@ func logBackendError(err error) {
 func (e *PutHandler) handle(w http.ResponseWriter, r *http.Request, ps httprouter.Params) {
 	e.metrics.RecordPutTotal()
 
+	if utils.RandomPick(e.cfg.refererLogRate) == true {
+		if refererHeaderValue := r.Header.Get(utils.REFERER_HEADER_KEY); refererHeaderValue != "" {
+			logrus.Info("Incoming request Referer header: " + refererHeaderValue)
+		}
+	}
+
 	start := time.Now()
 
 	bytes, err := e.processPutRequest(r)