Filter query-string secrets out of logged URLs

internal/helper/helpers.go

@@ -11,12 +11,15 @@ import (
 	"net/url"
 	"os"
 	"os/exec"
+	"regexp"
 	"strings"
 	"syscall"
 )
 
 const NginxResponseBufferHeader = "X-Accel-Buffering"
 
+var scrubRegexp = regexp.MustCompile(`([\?&](?:private|authenticity|rss)[\-_]token)=[^&]*`)
+
 func Fail500(w http.ResponseWriter, r *http.Request, err error) {
 	http.Error(w, "Internal server error", 500)
 	if err != nil {
@@ -42,7 +45,7 @@ func RequestEntityTooLarge(w http.ResponseWriter, r *http.Request, err error) {
 
 func printError(r *http.Request, err error) {
 	if r != nil {
-		log.Printf("error: %s %q: %v", r.Method, r.RequestURI, err)
+		log.Printf("error: %s %q: %v", r.Method, ScrubURLParams(r.RequestURI), err)
 	} else {
 		log.Printf("error: %v", err)
 	}
@@ -188,3 +191,9 @@ func CloneRequestWithNewBody(r *http.Request, body []byte) *http.Request {
 	newReq.ContentLength = int64(len(body))
 	return &newReq
 }
+
+// ScrubURLParams replaces the content of any sensitive query string parameters
+// in an URL with `[FILTERED]`
+func ScrubURLParams(url string) string {
+	return scrubRegexp.ReplaceAllString(url, "$1=[FILTERED]")
+}

internal/helper/helpers_test.go

@@ -110,3 +110,25 @@ func TestFail500WorksWithNils(t *testing.T) {
 	assert.Equal(t, http.StatusInternalServerError, w.Code)
 	assert.Equal(t, "Internal server error\n", body.String())
 }
+
+func TestScrubURLParams(t *testing.T) {
+	for before, expected := range map[string]string{
+		"http://example.com":                                                "http://example.com",
+		"http://example.com?foo=1":                                          "http://example.com?foo=1",
+		"http://example.com?authenticity_token=1":                           "http://example.com?authenticity_token=[FILTERED]",
+		"http://example.com?private_token=1":                                "http://example.com?private_token=[FILTERED]",
+		"http://example.com?rss_token=1":                                    "http://example.com?rss_token=[FILTERED]",
+		"http://example.com?foo&authenticity_token=blahblah&bar":            "http://example.com?foo&authenticity_token=[FILTERED]&bar",
+		"http://example.com?private-token=1":                                "http://example.com?private-token=[FILTERED]",
+		"http://example.com?foo&private-token=blahblah&bar":                 "http://example.com?foo&private-token=[FILTERED]&bar",
+		"http://example.com?private-token=foo&authenticity_token=bar":       "http://example.com?private-token=[FILTERED]&authenticity_token=[FILTERED]",
+		"https://example.com:8080?private-token=foo&authenticity_token=bar": "https://example.com:8080?private-token=[FILTERED]&authenticity_token=[FILTERED]",
+		"/?private-token=foo&authenticity_token=bar":                        "/?private-token=[FILTERED]&authenticity_token=[FILTERED]",
+		"?private-token=&authenticity_token=&bar":                           "?private-token=[FILTERED]&authenticity_token=[FILTERED]&bar",
+		"?private-token=foo&authenticity_token=bar":                         "?private-token=[FILTERED]&authenticity_token=[FILTERED]",
+		"?private_token=foo&authenticity-token=bar":                         "?private_token=[FILTERED]&authenticity-token=[FILTERED]",
+	} {
+		after := ScrubURLParams(before)
+		assert.Equal(t, expected, after, "Scrubbing %q", before)
+	}
+}

internal/helper/logging.go

@@ -109,8 +109,8 @@ func (l *loggingResponseWriter) Log(r *http.Request) {
 	duration := time.Since(l.started)
 	responseLogger.Printf("%s %s - - [%s] %q %d %d %q %q %f\n",
 		r.Host, r.RemoteAddr, l.started,
-		fmt.Sprintf("%s %s %s", r.Method, r.RequestURI, r.Proto),
-		l.status, l.written, r.Referer(), r.UserAgent(), duration.Seconds(),
+		fmt.Sprintf("%s %s %s", r.Method, ScrubURLParams(r.RequestURI), r.Proto),
+		l.status, l.written, ScrubURLParams(r.Referer()), r.UserAgent(), duration.Seconds(),
 	)
 
 	sessionsActive.Dec()

internal/sendfile/sendfile.go

@@ -104,7 +104,7 @@ func (s *sendFileResponseWriter) WriteHeader(status int) {
 }
 
 func sendFileFromDisk(w http.ResponseWriter, r *http.Request, file string) {
-	log.Printf("Send file %q for %s %q", file, r.Method, r.RequestURI)
+	log.Printf("Send file %q for %s %q", file, r.Method, helper.ScrubURLParams(r.RequestURI))
 	content, fi, err := helper.OpenFile(file)
 	if err != nil {
 		http.NotFound(w, r)

internal/staticpages/servefile.go

@@ -70,7 +70,7 @@ func (s *Static) ServeExisting(prefix urlprefix.Prefix, cache CacheMode, notFoun
 			w.Header().Set("Expires", cacheUntil)
 		}
 
-		log.Printf("Send static file %q (%q) for %s %q", file, w.Header().Get("Content-Encoding"), r.Method, r.RequestURI)
+		log.Printf("Send static file %q (%q) for %s %q", file, w.Header().Get("Content-Encoding"), r.Method, helper.ScrubURLParams(r.RequestURI))
 		http.ServeContent(w, r, filepath.Base(file), fi.ModTime(), content)
 	})
 }

main_test.go

@@ -468,6 +468,67 @@ func TestAPIFalsePositivesAreProxied(t *testing.T) {
 	}
 }
 
+func TestQueryStringLogFiltering(t *testing.T) {
+	// capture the log output
+	buf := bytes.NewBuffer(nil)
+	log.SetOutput(buf)
+	helper.SetCustomResponseLogger(buf)
+
+	defer log.SetOutput(os.Stderr)
+	defer helper.SetCustomResponseLogger(os.Stderr)
+
+	ts := testhelper.TestServerWithHandler(regexp.MustCompile(`.`), func(w http.ResponseWriter, _ *http.Request) {
+		w.WriteHeader(200)
+	})
+	defer ts.Close()
+
+	ws := startWorkhorseServer(ts.URL)
+	defer ws.Close()
+
+	for _, path := range []string{
+		"",
+		"/",
+	} {
+		for _, queryString := range []string{
+			"private-token=should_be_filtered",
+			"authenticity-token=should_be_filtered",
+			"rss-token=should_be_filtered",
+			"private_token=should_be_filtered",
+			"authenticity_token=should_be_filtered",
+			"rss-token=should_be_filtered",
+			"private-token=should_be_filtered&authenticity-token=should_be_filtered",
+			"private_token=should_be_filtered&authenticity_token=should_be_filtered",
+		} {
+			resource := path + "?" + queryString
+
+			// Ensure the Referer is scrubbed too
+			req, err := http.NewRequest("GET", ws.URL+resource, nil)
+			if !assert.NoError(t, err, "GET %q: %v", resource, err) {
+				continue
+			}
+
+			req.Header.Set("Referer", "http://referer.example.com"+resource)
+
+			resp, err := http.DefaultClient.Do(req)
+			if !assert.NoError(t, err, "GET %q: %v", resource, err) {
+				continue
+			}
+
+			resp.Body.Close()
+
+			assert.Equal(t, 200, resp.StatusCode, "GET %q: status code", resource)
+
+			logged := buf.String()
+			buf.Reset()
+
+			assert.NotEqual(t, 0, len(logged), "GET %q: log is empty", resource)
+			assert.Contains(t, logged, path, "GET %q: path not logged", resource)
+			assert.Contains(t, logged, "referer", "GET %q: referer not logged", resource)
+			assert.NotContains(t, logged, "should_be_filtered", "GET %q: log not filtered correctly", resource)
+		}
+	}
+}
+
 func setupStaticFile(fpath, content string) error {
 	cwd, err := os.Getwd()
 	if err != nil {