Merge pull request #689 from grnhse/finicky-logging-time-test

Fix time issue causing finicky failures in logging tests

CHANGELOG.md

@@ -11,6 +11,7 @@
 
 ## Changes since v6.0.0
 
+- [#689](https://github.com/oauth2-proxy/oauth2-proxy/pull/689) Fix finicky logging_handler_test from time drift (@NickMeves)
 - [#699](https://github.com/oauth2-proxy/oauth2-proxy/pull/699) Align persistence ginkgo tests with conventions (@NickMeves)
 - [#696](https://github.com/oauth2-proxy/oauth2-proxy/pull/696) Preserve query when building redirect
 - [#561](https://github.com/oauth2-proxy/oauth2-proxy/pull/561) Refactor provider URLs to package level vars (@JoelSpeed)

logging_handler_test.go

@@ -2,37 +2,89 @@ package main
 
 import (
 	"bytes"
-	"fmt"
 	"net/http"
 	"net/http/httptest"
-	"strings"
 	"testing"
-	"time"
 
 	"github.com/oauth2-proxy/oauth2-proxy/pkg/logger"
+	"github.com/stretchr/testify/assert"
 )
 
-func TestLoggingHandler_ServeHTTP(t *testing.T) {
+const RequestLoggingFormatWithoutTime = "{{.Client}} - {{.Username}} [TIMELESS] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}"
-	ts := time.Now()
 
+func TestLoggingHandler_ServeHTTP(t *testing.T) {
 	tests := []struct {
-		Format,
+		Format             string
-		ExpectedLogMessage,
+		ExpectedLogMessage string
 		Path               string
 		ExcludePaths       []string
 	}{
-		{logger.DefaultRequestLoggingFormat, fmt.Sprintf("127.0.0.1 - - [%s] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n", logger.FormatTimestamp(ts)), "/foo/bar", []string{}},
+		{
-		{logger.DefaultRequestLoggingFormat, fmt.Sprintf("127.0.0.1 - - [%s] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n", logger.FormatTimestamp(ts)), "/foo/bar", []string{}},
+			Format:             RequestLoggingFormatWithoutTime,
-		{logger.DefaultRequestLoggingFormat, fmt.Sprintf("127.0.0.1 - - [%s] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n", logger.FormatTimestamp(ts)), "/foo/bar", []string{"/ping"}},
+			ExpectedLogMessage: "127.0.0.1 - - [TIMELESS] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n",
-		{logger.DefaultRequestLoggingFormat, "", "/foo/bar", []string{"/foo/bar"}},
+			Path:               "/foo/bar",
-		{logger.DefaultRequestLoggingFormat, "", "/ping", []string{}},
+			ExcludePaths:       []string{},
-		{logger.DefaultRequestLoggingFormat, "", "/ping", []string{"/ping"}},
+		},
-		{logger.DefaultRequestLoggingFormat, "", "/ping", []string{"/ping"}},
+		{
-		{logger.DefaultRequestLoggingFormat, "", "/ping", []string{"/foo/bar", "/ping"}},
+			Format:             RequestLoggingFormatWithoutTime,
-		{"{{.RequestMethod}}", "GET\n", "/foo/bar", []string{}},
+			ExpectedLogMessage: "127.0.0.1 - - [TIMELESS] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n",
-		{"{{.RequestMethod}}", "GET\n", "/foo/bar", []string{"/ping"}},
+			Path:               "/foo/bar",
-		{"{{.RequestMethod}}", "GET\n", "/ping", []string{}},
+			ExcludePaths:       []string{},
-		{"{{.RequestMethod}}", "", "/ping", []string{"/ping"}},
+		},
+		{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "127.0.0.1 - - [TIMELESS] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{"/ping"},
+		},
+		{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{"/foo/bar"},
+		},
+		{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "127.0.0.1 - - [TIMELESS] test-server GET - \"/ping\" HTTP/1.1 \"\" 200 4 0.000\n",
+			Path:               "/ping",
+			ExcludePaths:       []string{},
+		},
+		{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "",
+			Path:               "/ping",
+			ExcludePaths:       []string{"/ping"},
+		},
+		{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "",
+			Path:               "/ping",
+			ExcludePaths:       []string{"/foo/bar", "/ping"},
+		},
+		{
+			Format:             "{{.RequestMethod}}",
+			ExpectedLogMessage: "GET\n",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{""},
+		},
+		{
+			Format:             "{{.RequestMethod}}",
+			ExpectedLogMessage: "GET\n",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{"/ping"},
+		},
+		{
+			Format:             "{{.RequestMethod}}",
+			ExpectedLogMessage: "GET\n",
+			Path:               "/ping",
+			ExcludePaths:       []string{""},
+		},
+		{
+			Format:             "{{.RequestMethod}}",
+			ExpectedLogMessage: "",
+			Path:               "/ping",
+			ExcludePaths:       []string{"/ping"},
+		},
 	}
 
 	for _, test := range tests {
@@ -43,7 +95,8 @@ func TestLoggingHandler_ServeHTTP(t *testing.T) {
 				t.Error("http.Hijacker is not available")
 			}
 
-			w.Write([]byte("test"))
+			_, err := w.Write([]byte("test"))
+			assert.NoError(t, err)
 		}
 
 		logger.SetOutput(buf)
@@ -58,8 +111,6 @@ func TestLoggingHandler_ServeHTTP(t *testing.T) {
 		h.ServeHTTP(httptest.NewRecorder(), r)
 
 		actual := buf.String()
-		if !strings.Contains(actual, test.ExpectedLogMessage) {
+		assert.Equal(t, test.ExpectedLogMessage, actual)
-			t.Errorf("Log message was\n%s\ninstead of matching \n%s", actual, test.ExpectedLogMessage)
-		}
 	}
 }