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: 0.0
 backend:
   type: "memory" # Switch to be "aerospike", "cassandra", "memcache", "ignite" or "redis" for production.
 # aerospike:

config/config.go

@@ -2,6 +2,7 @@ package config
 
 import (
 	"net/http"
+	"strconv"
 	"strings"
 	"time"
 
@@ -97,6 +98,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 +116,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 +140,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 +181,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 float64 `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: %s", strconv.FormatFloat(cfg.RefererSamplingRate, 'f', -1, 64))
+	} else {
+		log.Fatalf("invalid config.request_logging.referer_sampling_rate: value must be positive and not greater than 1.0. Got %s", strconv.FormatFloat(cfg.RefererSamplingRate, 'f', -1, 64))
+	}
+}
+
 type RequestLimits struct {
 	MaxSize          int  `mapstructure:"max_size_bytes"`
 	MaxNumValues     int  `mapstructure:"max_num_values"`

config/config_test.go

@@ -1,7 +1,6 @@
 package config
 
 import (
-	"fmt"
 	"os"
 	"path/filepath"
 	"strings"
@@ -13,6 +12,7 @@ import (
 	testLogrus "github.com/sirupsen/logrus/hooks/test"
 	"github.com/spf13/viper"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 func TestDefaults(t *testing.T) {
@@ -915,6 +915,89 @@ func TestRequestLimitsValidateAndLog(t *testing.T) {
 	}
 }
 
+func TestRequestLogging(t *testing.T) {
+	hook := testLogrus.NewGlobal()
+
+	type logComponents struct {
+		msg string
+		lvl logrus.Level
+	}
+
+	testCases := []struct {
+		name                string
+		inRequestLoggingCfg *RequestLogging
+		expectedLogInfo     []logComponents
+	}{
+		{
+			name: "invalid_nagative", // must be greater or equal to zero. 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.1`, lvl: logrus.FatalLevel},
+			},
+		},
+		{
+			name: "invalid_high", // must be less than or equal to 1. 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.1`, lvl: logrus.FatalLevel},
+			},
+		},
+		{
+			name: "valid_one", // 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`, lvl: logrus.InfoLevel},
+			},
+		},
+		{
+			name: "valid_zero", // 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`, lvl: logrus.InfoLevel},
+			},
+		},
+		{
+			name: "valid",
+			inRequestLoggingCfg: &RequestLogging{
+				RefererSamplingRate: 0.1111,
+			},
+			expectedLogInfo: []logComponents{
+				{msg: `config.request_logging.referer_sampling_rate: 0.1111`, 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 {
+		t.Run(tc.name, func(t *testing.T) {
+			tc.inRequestLoggingCfg.validateAndLog()
+
+			// assertions
+			require.Len(t, hook.Entries, len(tc.expectedLogInfo), tc.name+":log_entries")
+			for i := 0; i < len(tc.expectedLogInfo); i++ {
+				assert.Equal(t, tc.expectedLogInfo[i].msg, hook.Entries[i].Message, tc.name+":message")
+				assert.Equal(t, tc.expectedLogInfo[i].lvl, hook.Entries[i].Level, tc.name+":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
@@ -1081,19 +1164,20 @@ func TestConfigurationValidateAndLog(t *testing.T) {
 	expectedConfig := getExpectedDefaultConfig()
 
 	expectedLogInfo := []logComponents{
-		{msg: fmt.Sprintf("config.port: %d", expectedConfig.Port), lvl: logrus.InfoLevel},
-		{msg: fmt.Sprintf("config.admin_port: %d", expectedConfig.AdminPort), lvl: logrus.InfoLevel},
-		{msg: fmt.Sprintf("config.log.level: %s", expectedConfig.Log.Level), lvl: logrus.InfoLevel},
-		{msg: fmt.Sprintf("config.rate_limiter.enabled: %t", expectedConfig.RateLimiting.Enabled), lvl: logrus.InfoLevel},
-		{msg: fmt.Sprintf("config.rate_limiter.num_requests: %d", expectedConfig.RateLimiting.MaxRequestsPerSecond), lvl: logrus.InfoLevel},
-		{msg: fmt.Sprintf("config.request_limits.allow_setting_keys: %v", expectedConfig.RequestLimits.AllowSettingKeys), lvl: logrus.InfoLevel},
-		{msg: fmt.Sprintf("config.request_limits.max_ttl_seconds: %d", expectedConfig.RequestLimits.MaxTTLSeconds), lvl: logrus.InfoLevel},
-		{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.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},
+		{msg: "config.port: 2424", lvl: logrus.InfoLevel},
+		{msg: "config.admin_port: 2525", lvl: logrus.InfoLevel},
+		{msg: "config.log.level: info", lvl: logrus.InfoLevel},
+		{msg: "config.rate_limiter.enabled: true", lvl: logrus.InfoLevel},
+		{msg: "config.rate_limiter.num_requests: 100", lvl: logrus.InfoLevel},
+		{msg: "config.request_limits.allow_setting_keys: false", lvl: logrus.InfoLevel},
+		{msg: "config.request_limits.max_ttl_seconds: 3600", lvl: logrus.InfoLevel},
+		{msg: "config.request_limits.max_size_bytes: 10240", lvl: logrus.InfoLevel},
+		{msg: "config.request_limits.max_num_values: 10", lvl: logrus.InfoLevel},
+		{msg: "config.request_limits.max_header_size_bytes: 1048576", lvl: logrus.InfoLevel},
+		{msg: "config.request_logging.referer_sampling_rate: 0", lvl: logrus.InfoLevel},
+		{msg: "config.backend.type: memory", lvl: logrus.InfoLevel},
+		{msg: "config.compression.type: snappy", lvl: logrus.InfoLevel},
+		{msg: "Prebid Cache will run without metrics", lvl: logrus.InfoLevel},
 	}
 
 	// Run test
@@ -1102,7 +1186,7 @@ func TestConfigurationValidateAndLog(t *testing.T) {
 	// Assertions
 	if assert.Len(t, hook.Entries, len(expectedLogInfo)) {
 		for i := 0; i < len(expectedLogInfo); i++ {
-			assert.True(t, strings.HasPrefix(hook.Entries[i].Message, expectedLogInfo[i].msg), "Wrong message")
+			assert.Equal(t, expectedLogInfo[i].msg, hook.Entries[i].Message, "Wrong message")
 			assert.Equal(t, expectedLogInfo[i].lvl, hook.Entries[i].Level, "Wrong log level")
 		}
 	}
@@ -1228,6 +1312,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  float64
 }
 
 // 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 float64) 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 referer := r.Referer(); referer != "" {
+			log.Info("GET request Referer header: " + referer)
+		}
+	}
+
 	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()