Log client_id in addition to visit_id (#156)

Author: willdurand

go.mod

@@ -12,6 +12,7 @@ require (
 	github.com/pkg/errors v0.9.1
 	github.com/sirupsen/logrus v1.9.0
 	go.mozilla.org/mozlogrus v1.0.0
+	golang.org/x/exp v0.0.0-20230224173230-c95f2b4c22f2
 )
 
 require (

go.sum

@@ -87,6 +87,8 @@ go.opencensus.io v0.24.0/go.mod h1:vNK8G9p7aAivkbmorf4v+7Hgx+Zs0yY+0fOtgBfjQKo=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
 golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
+golang.org/x/exp v0.0.0-20230224173230-c95f2b4c22f2 h1:Jvc7gsqn21cJHCmAWx0LiimpP18LZmUxkT5Mp7EZ1mI=
+golang.org/x/exp v0.0.0-20230224173230-c95f2b4c22f2/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc=
 golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE=
 golang.org/x/lint v0.0.0-20190227174305-5b3e6a55c961/go.mod h1:wehouNa3lNwaWXcvxsM5YxQ5yQlVC4a0KAMCusXpPoU=
 golang.org/x/lint v0.0.0-20190313153728-d0100b6bd8b3/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=

stubservice/stubhandlers/stubhandler_test.go

@@ -14,8 +14,21 @@ import (
 
 	"github.com/mozilla-services/stubattribution/attributioncode"
 	"github.com/mozilla-services/stubattribution/stubservice/backends"
+	"github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/test"
+	"golang.org/x/exp/slices"
 )
 
+// testHook is a logrus hook that is registered globally in order to capture
+// the messages logged during the execution of the tests. This is useful to
+// verify some important log statements. We have to register a global hook
+// because we use the global logrus instance in our code.
+var testHook *test.Hook
+
+func init() {
+	testHook = test.NewGlobal()
+}
+
 func TestUniqueKey(t *testing.T) {
 	f := func(url, code string) bool {
 		key := uniqueKey(url, code)
@@ -137,15 +150,95 @@ func TestRedirectFull(t *testing.T) {
 
 	svc := NewStubService(
 		NewRedirectHandler(storage, server.URL+"/cdn/", ""),
-		&attributioncode.Validator{})
+		&attributioncode.Validator{},
+	)
+
+	for _, params := range []struct {
+		AttributionCode       string
+		Referer               string
+		ExpectedLocation      string
+		ExpectedCode          string
+		SkipDownloadLogChecks bool
+		ExpectedClientID      string
+		ExpectedSessionID     string
+	}{
+		{
+			AttributionCode:  `campaign=%28not+set%29&content=%28not+set%29&medium=organic&source=www.google.com`,
+			Referer:          "",
+			ExpectedLocation: `/cdn/builds/firefox-stub/en-US/win/`,
+			ExpectedCode:     `campaign%3D%2528not%2Bset%2529%26content%3D%2528not%2Bset%2529%26dltoken%3D[\w\d-]+%26medium%3Dorganic%26source%3Dwww.google.com`,
+		},
+		{
+			AttributionCode:  `campaign=%28not+set%29&content=%28not+set%29&medium=organic&source=www.notinwhitelist.com`,
+			Referer:          "",
+			ExpectedLocation: `/cdn/builds/firefox-stub/en-US/win/`,
+			ExpectedCode:     `campaign%3D%2528not%2Bset%2529%26content%3D%2528not%2Bset%2529%26dltoken%3D[\w\d-]+%26medium%3Dorganic%26source%3D%2528other%2529`,
+		},
+		{
+			// We expect the product to be prefixed in the location URL below because
+			// the attribution code contains data for RTAMO and the referer header
+			// contains the right value.
+			AttributionCode:  `campaign=fxa-cta-123&content=rta:value&medium=referral&source=addons.mozilla.org`,
+			Referer:          `https://www.mozilla.org/`,
+			ExpectedLocation: `/cdn/builds/rtamo-firefox-stub/en-US/win/`,
+			ExpectedCode:     `campaign%3Dfxa-cta-123%26content%3Drta%253Avalue%26dltoken%3D[\w\d-]+%26medium%3Dreferral%26source%3Daddons.mozilla.org`,
+		},
+		{
+			// Same as before with a `client_id`.
+			AttributionCode:  `campaign=fxa-cta-123&content=rta:value&medium=referral&source=addons.mozilla.org&client_id=some-client-id`,
+			Referer:          `https://www.mozilla.org/`,
+			ExpectedLocation: `/cdn/builds/rtamo-firefox-stub/en-US/win/`,
+			ExpectedCode:     `campaign%3Dfxa-cta-123%26content%3Drta%253Avalue%26dltoken%3D[\w\d-]+%26medium%3Dreferral%26source%3Daddons.mozilla.org`,
+			ExpectedClientID: "some-client-id",
+		},
+		{
+			// Same as before with a `visit_id`.
+			AttributionCode:  `campaign=fxa-cta-123&content=rta:value&medium=referral&source=addons.mozilla.org&visit_id=some-visit-id`,
+			Referer:          `https://www.mozilla.org/`,
+			ExpectedLocation: `/cdn/builds/rtamo-firefox-stub/en-US/win/`,
+			ExpectedCode:     `campaign%3Dfxa-cta-123%26content%3Drta%253Avalue%26dltoken%3D[\w\d-]+%26medium%3Dreferral%26source%3Daddons.mozilla.org`,
+			ExpectedClientID: "some-visit-id",
+		},
+		{
+			// Same as before with the addition of a `session_id`.
+			AttributionCode:   `campaign=fxa-cta-123&content=rta:value&medium=referral&source=addons.mozilla.org&visit_id=some-visit-id&session_id=some-session-id`,
+			Referer:           `https://www.mozilla.org/`,
+			ExpectedLocation:  `/cdn/builds/rtamo-firefox-stub/en-US/win/`,
+			ExpectedCode:      `campaign%3Dfxa-cta-123%26content%3Drta%253Avalue%26dltoken%3D[\w\d-]+%26medium%3Dreferral%26source%3Daddons.mozilla.org`,
+			ExpectedClientID:  "some-visit-id",
+			ExpectedSessionID: "some-session-id",
+		},
+		{
+			// We expect no prefix because the attribution data is not related to
+			// RTAMO.
+			AttributionCode:  `campaign=some-campaign&content=not-for-rtamo&medium=referral&source=addons.mozilla.org`,
+			Referer:          `https://www.mozilla.org/`,
+			ExpectedLocation: `/cdn/builds/firefox-stub/en-US/win/`,
+			ExpectedCode:     `campaign%3Dsome-campaign%26content%3Dnot-for-rtamo%26dltoken%3D[\w\d-]+%26medium%3Dreferral%26source%3Daddons.mozilla.org`,
+		},
+		{
+			// This should not return a modified installer because the referer is not
+			// the expected one.
+			AttributionCode:       `campaign=fxa-cta-123&content=rta:value&medium=referral&source=addons.mozilla.org`,
+			Referer:               `https://example.org/`,
+			ExpectedLocation:      `\?lang=en-US&os=win&product=firefox-stub`,
+			ExpectedCode:          "",
+			SkipDownloadLogChecks: true,
+		},
+	} {
+		testHook.Reset()
+
+		expectedLocationRegexp := regexp.MustCompile(params.ExpectedLocation)
+		expectedCodeRegexp := regexp.MustCompile(params.ExpectedCode)
 
-	runTest := func(attributionCode, referer string, expectedLocation string, expectedCode string) {
-		expectedCodeRegexp := regexp.MustCompile(expectedCode)
-		expectedLocationRegexp := regexp.MustCompile(expectedLocation)
 		recorder := httptest.NewRecorder()
-		base64Code := base64.URLEncoding.WithPadding('.').EncodeToString([]byte(attributionCode))
-		req := httptest.NewRequest("GET", `http://test/?product=firefox-stub&os=win&lang=en-US&attribution_code=`+url.QueryEscape(base64Code), nil)
-		req.Header.Set("Referer", referer)
+		base64Code := base64.URLEncoding.WithPadding('.').EncodeToString([]byte(params.AttributionCode))
+		req := httptest.NewRequest(
+			"GET",
+			`http://test/?product=firefox-stub&os=win&lang=en-US&attribution_code=`+url.QueryEscape(base64Code),
+			nil,
+		)
+		req.Header.Set("Referer", params.Referer)
 		svc.ServeHTTP(recorder, req)
 
 		location := recorder.HeaderMap.Get("Location")
@@ -169,53 +262,48 @@ func TestRedirectFull(t *testing.T) {
 		if err != nil {
 			t.Fatal("could not read body", err)
 		}
-
 		if len(bodyBytes) != len(testFileBytes) {
 			t.Error("Returned file was not the same length as the original file")
 		}
-
 		if !expectedCodeRegexp.Match(bodyBytes) {
 			t.Error("Returned file did not contain attribution code")
 		}
-	}
 
-	emptyReferer := ""
-	runTest(
-		`campaign=%28not+set%29&content=%28not+set%29&medium=organic&source=www.google.com`,
-		emptyReferer,
-		`/cdn/builds/firefox-stub/en-US/win/`,
-		`campaign%3D%2528not%2Bset%2529%26content%3D%2528not%2Bset%2529%26dltoken%3D[\w\d-]+%26medium%3Dorganic%26source%3Dwww.google.com`,
-	)
-	runTest(
-		`campaign=%28not+set%29&content=%28not+set%29&medium=organic&source=www.notinwhitelist.com`,
-		emptyReferer,
-		`/cdn/builds/firefox-stub/en-US/win/`,
-		`campaign%3D%2528not%2Bset%2529%26content%3D%2528not%2Bset%2529%26dltoken%3D[\w\d-]+%26medium%3Dorganic%26source%3D%2528other%2529`,
-	)
-	// We expect the product to be prefixed in the location URL below because the
-	// attribution code contains data for RTAMO and the referer header contains
-	// the right value.
-	runTest(
-		`campaign=fxa-cta-123&content=rta:value&medium=referral&source=addons.mozilla.org`,
-		`https://www.mozilla.org/`,
-		`/cdn/builds/rtamo-firefox-stub/en-US/win/`,
-		`campaign%3Dfxa-cta-123%26content%3Drta%253Avalue%26dltoken%3D[\w\d-]+%26medium%3Dreferral%26source%3Daddons.mozilla.org`,
-	)
-	// We expect no prefix because the attribution data is not related to RTAMO.
-	runTest(
-		`campaign=some-campaign&content=not-for-rtamo&medium=referral&source=addons.mozilla.org`,
-		`https://www.mozilla.org/`,
-		`/cdn/builds/firefox-stub/en-US/win/`,
-		`campaign%3Dsome-campaign%26content%3Dnot-for-rtamo%26dltoken%3D[\w\d-]+%26medium%3Dreferral%26source%3Daddons.mozilla.org`,
-	)
-	// This should not return a modified installer because the referer is not the
-	// expected one.
-	runTest(
-		`campaign=fxa-cta-123&content=rta:value&medium=referral&source=addons.mozilla.org`,
-		`https://example.org/`,
-		`\?lang=en-US&os=win&product=firefox-stub`,
-		``,
-	)
+		if !params.SkipDownloadLogChecks {
+			entries := testHook.AllEntries()
+
+			idx := slices.IndexFunc(entries, func(e *logrus.Entry) bool {
+				return e.Message == "Download Started"
+			})
+			if idx == -1 {
+				t.Error("Could not find Download Started log entry")
+			}
+			downloadStarted := entries[idx]
+
+			// This one should always be the last log entry.
+			downloadFinished := entries[len(entries)-1]
+			if downloadFinished.Message != "Download Finished" {
+				t.Errorf("Unexpected log message: %s", downloadFinished.Message)
+			}
+
+			for _, entry := range []*logrus.Entry{downloadStarted, downloadFinished} {
+				clientID := entry.Data["client_id"]
+				if clientID != params.ExpectedClientID {
+					t.Errorf("Expected client_id: %s, got: %v", params.ExpectedClientID, clientID)
+				}
+
+				visitID := entry.Data["visit_id"]
+				if visitID != params.ExpectedClientID {
+					t.Errorf("Expected visit_id: %s, got: %v", params.ExpectedClientID, visitID)
+				}
+
+				sessionID := entry.Data["session_id"]
+				if sessionID != params.ExpectedSessionID {
+					t.Errorf("Expected session_id: %s, got: %v", params.ExpectedSessionID, sessionID)
+				}
+			}
+		}
+	}
 }
 
 func TestDirectFull(t *testing.T) {
@@ -245,14 +333,33 @@ func TestDirectFull(t *testing.T) {
 
 	svc := NewStubService(
 		NewDirectHandler(),
-		&attributioncode.Validator{})
+		&attributioncode.Validator{},
+	)
 
-	runTest := func(attributionCode, expectedCode string) {
-		expectedCodeRegexp := regexp.MustCompile(expectedCode)
-		base64Code := base64.URLEncoding.WithPadding('.').EncodeToString([]byte(attributionCode))
-		req := httptest.NewRequest("GET", `http://test/?product=firefox-stub&os=win&lang=en-US&attribution_code=`+url.QueryEscape(base64Code), nil)
+	for _, params := range []struct {
+		AttributionCode string
+		ExpectedCode    string
+	}{
+		{
+			AttributionCode: `campaign=%28not+set%29&content=%28not+set%29&medium=organic&source=www.google.com`,
+			ExpectedCode:    `campaign%3D%2528not%2Bset%2529%26content%3D%2528not%2Bset%2529%26dltoken%3D[\w\d-]+%26medium%3Dorganic%26source%3Dwww.google.com`,
+		},
+		{
+			AttributionCode: `campaign=%28not+set%29&content=%28not+set%29&medium=organic&source=notinthewhitelist.com`,
+			ExpectedCode:    `campaign%3D%2528not%2Bset%2529%26content%3D%2528not%2Bset%2529%26dltoken%3D[\w\d-]+%26medium%3Dorganic%26source%3D%2528other%2529`,
+		},
+	} {
+		testHook.Reset()
+
+		expectedCodeRegexp := regexp.MustCompile(params.ExpectedCode)
 
 		recorder := httptest.NewRecorder()
+		base64Code := base64.URLEncoding.WithPadding('.').EncodeToString([]byte(params.AttributionCode))
+		req := httptest.NewRequest(
+			"GET",
+			`http://test/?product=firefox-stub&os=win&lang=en-US&attribution_code=`+url.QueryEscape(base64Code),
+			nil,
+		)
 		svc.ServeHTTP(recorder, req)
 
 		if recorder.Code != 200 {
@@ -263,27 +370,14 @@ func TestDirectFull(t *testing.T) {
 		if err != nil {
 			t.Fatal("could not read body", err)
 		}
-
 		if len(bodyBytes) != len(testFileBytes) {
 			t.Error("Returned file was not the same length as the original file")
 		}
 
 		if !expectedCodeRegexp.Match(bodyBytes) {
 			t.Error("Returned file did not contain attribution code")
 		}
-		//if !bytes.Contains(bodyBytes, []byte(url.QueryEscape(expectedCode))) {
-		//t.Error("Returned file did not contain attribution code")
-		//}
 	}
-
-	runTest(
-		`campaign=%28not+set%29&content=%28not+set%29&medium=organic&source=www.google.com`,
-		`campaign%3D%2528not%2Bset%2529%26content%3D%2528not%2Bset%2529%26dltoken%3D[\w\d-]+%26medium%3Dorganic%26source%3Dwww.google.com`,
-	)
-	runTest(
-		`campaign=%28not+set%29&content=%28not+set%29&medium=organic&source=notinthewhitelist.com`,
-		`campaign%3D%2528not%2Bset%2529%26content%3D%2528not%2Bset%2529%26dltoken%3D[\w\d-]+%26medium%3Dorganic%26source%3D%2528other%2529`,
-	)
 }
 
 func TestStubServiceErrorCases(t *testing.T) {

stubservice/stubhandlers/stubservice.go

@@ -45,13 +45,12 @@ func (s *stubService) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 		logrus.Fields{
 			"log_type": "download_started",
 			"dltoken":  code.DownloadToken(),
-			// This field should be named `client_id` but, for historical reasons, we
-			// use `visit_id`. It'd be good to be able to rename this field but we
-			// need to work with the Data Science team since that'd be a breaking
-			// change.
+			// We need to keep this field until we are sure that the consumers of
+			// this log statement use the new field (`client_id`).
 			//
-			// See: https://github.com/mozilla-services/stubattribution/issues/153
+			// See: https://github.com/mozilla-services/stubattribution/issues/155
 			"visit_id":   code.ClientID,
+			"client_id":  code.ClientID,
 			"session_id": code.SessionID,
 		},
 	).Info("Download Started")
@@ -89,13 +88,12 @@ func (s *stubService) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 		logrus.Fields{
 			"log_type": "download_finished",
 			"dltoken":  code.DownloadToken(),
-			// This field should be named `client_id` but, for historical reasons, we
-			// use `visit_id`. It'd be good to be able to rename this field but we
-			// need to work with the Data Science team since that'd be a breaking
-			// change.
+			// We need to keep this field until we are sure that the consumers of
+			// this log statement use the new field (`client_id`).
 			//
-			// See: https://github.com/mozilla-services/stubattribution/issues/153
+			// See: https://github.com/mozilla-services/stubattribution/issues/155
 			"visit_id":   code.ClientID,
+			"client_id":  code.ClientID,
 			"session_id": code.SessionID,
 		},
 	).Info("Download Finished")