traefik/pkg/middlewares/accesslog/logger_test.go

package accesslog

import (
	"bytes"
	"crypto/tls"
	"encoding/json"
	"fmt"
	"io"
	"net/http"
	"net/http/httptest"
	"net/url"
	"os"
	"path/filepath"
	"regexp"
	"strconv"
	"strings"
	"testing"
	"time"

	"github.com/containous/alice"
	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	ptypes "github.com/traefik/paerser/types"
	"github.com/traefik/traefik/v2/pkg/middlewares/capture"
	"github.com/traefik/traefik/v2/pkg/types"
)

const delta float64 = 1e-10

var (
	logFileNameSuffix       = "/traefik/logger/test.log"
	testContent             = "Hello, World"
	testServiceName         = "http://127.0.0.1/testService"
	testRouterName          = "testRouter"
	testStatus              = 123
	testContentSize   int64 = 12
	testHostname            = "TestHost"
	testUsername            = "TestUser"
	testPath                = "testpath"
	testPort                = 8181
	testProto               = "HTTP/0.0"
	testScheme              = "http"
	testMethod              = http.MethodPost
	testReferer             = "testReferer"
	testUserAgent           = "testUserAgent"
	testRetryAttempts       = 2
	testStart               = time.Now()
)

func TestLogRotation(t *testing.T) {
	fileName := filepath.Join(t.TempDir(), "traefik.log")
	rotatedFileName := fileName + ".rotated"

	config := &types.AccessLog{FilePath: fileName, Format: CommonFormat}
	logHandler, err := NewHandler(config)
	require.NoError(t, err)
	t.Cleanup(func() {
		err := logHandler.Close()
		require.NoError(t, err)
	})

	chain := alice.New()
	chain = chain.Append(capture.Wrap)
	chain = chain.Append(WrapHandler(logHandler))
	handler, err := chain.Then(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
		rw.WriteHeader(http.StatusOK)
	}))
	require.NoError(t, err)

	recorder := httptest.NewRecorder()
	req := httptest.NewRequest(http.MethodGet, "http://localhost", nil)

	iterations := 20
	halfDone := make(chan bool)
	writeDone := make(chan bool)
	go func() {
		for i := range iterations {
			handler.ServeHTTP(recorder, req)
			if i == iterations/2 {
				halfDone <- true
			}
		}
		writeDone <- true
	}()

	<-halfDone
	err = os.Rename(fileName, rotatedFileName)
	if err != nil {
		t.Fatalf("Error renaming file: %s", err)
	}

	err = logHandler.Rotate()
	if err != nil {
		t.Fatalf("Error rotating file: %s", err)
	}

	select {
	case <-writeDone:
		gotLineCount := lineCount(t, fileName) + lineCount(t, rotatedFileName)
		if iterations != gotLineCount {
			t.Errorf("Wanted %d written log lines, got %d", iterations, gotLineCount)
		}
	case <-time.After(500 * time.Millisecond):
		t.Fatalf("test timed out")
	}

	close(halfDone)
	close(writeDone)
}

func lineCount(t *testing.T, fileName string) int {
	t.Helper()
	fileContents, err := os.ReadFile(fileName)
	if err != nil {
		t.Fatalf("Error reading from file %s: %s", fileName, err)
	}

	count := 0
	for _, line := range strings.Split(string(fileContents), "\n") {
		if strings.TrimSpace(line) == "" {
			continue
		}
		count++
	}

	return count
}

func TestLoggerHeaderFields(t *testing.T) {
	expectedValues := []string{"AAA", "BBB"}

	testCases := []struct {
		desc            string
		accessLogFields types.AccessLogFields
		header          string
		expected        string
	}{
		{
			desc:     "with default mode",
			header:   "User-Agent",
			expected: types.AccessLogDrop,
			accessLogFields: types.AccessLogFields{
				DefaultMode: types.AccessLogDrop,
				Headers: &types.FieldHeaders{
					DefaultMode: types.AccessLogDrop,
					Names:       map[string]string{},
				},
			},
		},
		{
			desc:     "with exact header name",
			header:   "User-Agent",
			expected: types.AccessLogKeep,
			accessLogFields: types.AccessLogFields{
				DefaultMode: types.AccessLogDrop,
				Headers: &types.FieldHeaders{
					DefaultMode: types.AccessLogDrop,
					Names: map[string]string{
						"User-Agent": types.AccessLogKeep,
					},
				},
			},
		},
		{
			desc:     "with case insensitive match on header name",
			header:   "User-Agent",
			expected: types.AccessLogKeep,
			accessLogFields: types.AccessLogFields{
				DefaultMode: types.AccessLogDrop,
				Headers: &types.FieldHeaders{
					DefaultMode: types.AccessLogDrop,
					Names: map[string]string{
						"user-agent": types.AccessLogKeep,
					},
				},
			},
		},
	}

	for _, test := range testCases {
		t.Run(test.desc, func(t *testing.T) {
			logFile, err := os.CreateTemp(t.TempDir(), "*.log")
			require.NoError(t, err)

			config := &types.AccessLog{
				FilePath: logFile.Name(),
				Format:   CommonFormat,
				Fields:   &test.accessLogFields,
			}

			logger, err := NewHandler(config)
			require.NoError(t, err)
			t.Cleanup(func() {
				err := logger.Close()
				require.NoError(t, err)
			})

			if config.FilePath != "" {
				_, err = os.Stat(config.FilePath)
				require.NoErrorf(t, err, "logger should create %s", config.FilePath)
			}

			req := &http.Request{
				Header: map[string][]string{},
				URL: &url.URL{
					Path: testPath,
				},
			}

			for _, s := range expectedValues {
				req.Header.Add(test.header, s)
			}

			chain := alice.New()
			chain = chain.Append(capture.Wrap)
			chain = chain.Append(WrapHandler(logger))
			handler, err := chain.Then(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
				rw.WriteHeader(http.StatusOK)
			}))
			require.NoError(t, err)
			handler.ServeHTTP(httptest.NewRecorder(), req)

			logData, err := os.ReadFile(logFile.Name())
			require.NoError(t, err)

			if test.expected == types.AccessLogDrop {
				assert.NotContains(t, string(logData), strings.Join(expectedValues, ","))
			} else {
				assert.Contains(t, string(logData), strings.Join(expectedValues, ","))
			}
		})
	}
}

func TestLoggerCLF(t *testing.T) {
	logFilePath := filepath.Join(t.TempDir(), logFileNameSuffix)
	config := &types.AccessLog{FilePath: logFilePath, Format: CommonFormat}
	doLogging(t, config)

	logData, err := os.ReadFile(logFilePath)
	require.NoError(t, err)

	expectedLog := ` TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 1 "testRouter" "http://127.0.0.1/testService" 1ms`
	assertValidLogData(t, expectedLog, logData)
}

func TestLoggerCLFWithBufferingSize(t *testing.T) {
	logFilePath := filepath.Join(t.TempDir(), logFileNameSuffix)
	config := &types.AccessLog{FilePath: logFilePath, Format: CommonFormat, BufferingSize: 1024}
	doLogging(t, config)

	// wait a bit for the buffer to be written in the file.
	time.Sleep(50 * time.Millisecond)

	logData, err := os.ReadFile(logFilePath)
	require.NoError(t, err)

	expectedLog := ` TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 1 "testRouter" "http://127.0.0.1/testService" 1ms`
	assertValidLogData(t, expectedLog, logData)
}

func assertString(exp string) func(t *testing.T, actual interface{}) {
	return func(t *testing.T, actual interface{}) {
		t.Helper()

		assert.Equal(t, exp, actual)
	}
}

func assertNotEmpty() func(t *testing.T, actual interface{}) {
	return func(t *testing.T, actual interface{}) {
		t.Helper()

		assert.NotEqual(t, "", actual)
	}
}

func assertFloat64(exp float64) func(t *testing.T, actual interface{}) {
	return func(t *testing.T, actual interface{}) {
		t.Helper()

		assert.InDelta(t, exp, actual, delta)
	}
}

func assertFloat64NotZero() func(t *testing.T, actual interface{}) {
	return func(t *testing.T, actual interface{}) {
		t.Helper()

		assert.NotZero(t, actual)
	}
}

func TestLoggerJSON(t *testing.T) {
	testCases := []struct {
		desc     string
		config   *types.AccessLog
		tls      bool
		expected map[string]func(t *testing.T, value interface{})
	}{
		{
			desc: "default config",
			config: &types.AccessLog{
				FilePath: "",
				Format:   JSONFormat,
			},
			expected: map[string]func(t *testing.T, value interface{}){
				RequestContentSize:        assertFloat64(0),
				RequestHost:               assertString(testHostname),
				RequestAddr:               assertString(testHostname),
				RequestMethod:             assertString(testMethod),
				RequestPath:               assertString(testPath),
				RequestProtocol:           assertString(testProto),
				RequestScheme:             assertString(testScheme),
				RequestPort:               assertString("-"),
				DownstreamStatus:          assertFloat64(float64(testStatus)),
				DownstreamContentSize:     assertFloat64(float64(len(testContent))),
				OriginContentSize:         assertFloat64(float64(len(testContent))),
				OriginStatus:              assertFloat64(float64(testStatus)),
				RequestRefererHeader:      assertString(testReferer),
				RequestUserAgentHeader:    assertString(testUserAgent),
				RouterName:                assertString(testRouterName),
				ServiceURL:                assertString(testServiceName),
				ClientUsername:            assertString(testUsername),
				ClientHost:                assertString(testHostname),
				ClientPort:                assertString(strconv.Itoa(testPort)),
				ClientAddr:                assertString(fmt.Sprintf("%s:%d", testHostname, testPort)),
				"level":                   assertString("info"),
				"msg":                     assertString(""),
				"downstream_Content-Type": assertString("text/plain; charset=utf-8"),
				RequestCount:              assertFloat64NotZero(),
				Duration:                  assertFloat64NotZero(),
				Overhead:                  assertFloat64NotZero(),
				RetryAttempts:             assertFloat64(float64(testRetryAttempts)),
				"time":                    assertNotEmpty(),
				"StartLocal":              assertNotEmpty(),
				"StartUTC":                assertNotEmpty(),
			},
		},
		{
			desc: "default config, with TLS request",
			config: &types.AccessLog{
				FilePath: "",
				Format:   JSONFormat,
			},
			tls: true,
			expected: map[string]func(t *testing.T, value interface{}){
				RequestContentSize:        assertFloat64(0),
				RequestHost:               assertString(testHostname),
				RequestAddr:               assertString(testHostname),
				RequestMethod:             assertString(testMethod),
				RequestPath:               assertString(testPath),
				RequestProtocol:           assertString(testProto),
				RequestScheme:             assertString("https"),
				RequestPort:               assertString("-"),
				DownstreamStatus:          assertFloat64(float64(testStatus)),
				DownstreamContentSize:     assertFloat64(float64(len(testContent))),
				OriginContentSize:         assertFloat64(float64(len(testContent))),
				OriginStatus:              assertFloat64(float64(testStatus)),
				RequestRefererHeader:      assertString(testReferer),
				RequestUserAgentHeader:    assertString(testUserAgent),
				RouterName:                assertString(testRouterName),
				ServiceURL:                assertString(testServiceName),
				ClientUsername:            assertString(testUsername),
				ClientHost:                assertString(testHostname),
				ClientPort:                assertString(strconv.Itoa(testPort)),
				ClientAddr:                assertString(fmt.Sprintf("%s:%d", testHostname, testPort)),
				"level":                   assertString("info"),
				"msg":                     assertString(""),
				"downstream_Content-Type": assertString("text/plain; charset=utf-8"),
				RequestCount:              assertFloat64NotZero(),
				Duration:                  assertFloat64NotZero(),
				Overhead:                  assertFloat64NotZero(),
				RetryAttempts:             assertFloat64(float64(testRetryAttempts)),
				TLSVersion:                assertString("1.3"),
				TLSCipher:                 assertString("TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256"),
				"time":                    assertNotEmpty(),
				StartLocal:                assertNotEmpty(),
				StartUTC:                  assertNotEmpty(),
			},
		},
		{
			desc: "default config drop all fields",
			config: &types.AccessLog{
				FilePath: "",
				Format:   JSONFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
				},
			},
			expected: map[string]func(t *testing.T, value interface{}){
				"level":                   assertString("info"),
				"msg":                     assertString(""),
				"time":                    assertNotEmpty(),
				"downstream_Content-Type": assertString("text/plain; charset=utf-8"),
				RequestRefererHeader:      assertString(testReferer),
				RequestUserAgentHeader:    assertString(testUserAgent),
			},
		},
		{
			desc: "default config drop all fields and headers",
			config: &types.AccessLog{
				FilePath: "",
				Format:   JSONFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
					Headers: &types.FieldHeaders{
						DefaultMode: "drop",
					},
				},
			},
			expected: map[string]func(t *testing.T, value interface{}){
				"level": assertString("info"),
				"msg":   assertString(""),
				"time":  assertNotEmpty(),
			},
		},
		{
			desc: "default config drop all fields and redact headers",
			config: &types.AccessLog{
				FilePath: "",
				Format:   JSONFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
					Headers: &types.FieldHeaders{
						DefaultMode: "redact",
					},
				},
			},
			expected: map[string]func(t *testing.T, value interface{}){
				"level":                   assertString("info"),
				"msg":                     assertString(""),
				"time":                    assertNotEmpty(),
				"downstream_Content-Type": assertString("REDACTED"),
				RequestRefererHeader:      assertString("REDACTED"),
				RequestUserAgentHeader:    assertString("REDACTED"),
			},
		},
		{
			desc: "default config drop all fields and headers but kept someone",
			config: &types.AccessLog{
				FilePath: "",
				Format:   JSONFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
					Names: map[string]string{
						RequestHost: "keep",
					},
					Headers: &types.FieldHeaders{
						DefaultMode: "drop",
						Names: map[string]string{
							"Referer": "keep",
						},
					},
				},
			},
			expected: map[string]func(t *testing.T, value interface{}){
				RequestHost:          assertString(testHostname),
				"level":              assertString("info"),
				"msg":                assertString(""),
				"time":               assertNotEmpty(),
				RequestRefererHeader: assertString(testReferer),
			},
		},
		{
			desc: "fields and headers with unconventional letter case",
			config: &types.AccessLog{
				FilePath: "",
				Format:   JSONFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
					Names: map[string]string{
						"rEqUeStHoSt": "keep",
					},
					Headers: &types.FieldHeaders{
						DefaultMode: "drop",
						Names: map[string]string{
							"ReFeReR": "keep",
						},
					},
				},
			},
			expected: map[string]func(t *testing.T, value interface{}){
				RequestHost:          assertString(testHostname),
				"level":              assertString("info"),
				"msg":                assertString(""),
				"time":               assertNotEmpty(),
				RequestRefererHeader: assertString(testReferer),
			},
		},
	}

	for _, test := range testCases {
		t.Run(test.desc, func(t *testing.T) {
			t.Parallel()

			logFilePath := filepath.Join(t.TempDir(), logFileNameSuffix)

			test.config.FilePath = logFilePath
			if test.tls {
				doLoggingTLS(t, test.config)
			} else {
				doLogging(t, test.config)
			}

			logData, err := os.ReadFile(logFilePath)
			require.NoError(t, err)

			jsonData := make(map[string]interface{})
			err = json.Unmarshal(logData, &jsonData)
			require.NoError(t, err)

			assert.Equal(t, len(test.expected), len(jsonData))

			for field, assertion := range test.expected {
				assertion(t, jsonData[field])
			}
		})
	}
}

func TestNewLogHandlerOutputStdout(t *testing.T) {
	testCases := []struct {
		desc        string
		config      *types.AccessLog
		expectedLog string
	}{
		{
			desc: "default config",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
			},
			expectedLog: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testRouter" "http://127.0.0.1/testService" 1ms`,
		},
		{
			desc: "default config with empty filters",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Filters:  &types.AccessLogFilters{},
			},
			expectedLog: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testRouter" "http://127.0.0.1/testService" 1ms`,
		},
		{
			desc: "Status code filter not matching",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Filters: &types.AccessLogFilters{
					StatusCodes: []string{"200"},
				},
			},
			expectedLog: ``,
		},
		{
			desc: "Status code filter matching",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Filters: &types.AccessLogFilters{
					StatusCodes: []string{"123"},
				},
			},
			expectedLog: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testRouter" "http://127.0.0.1/testService" 1ms`,
		},
		{
			desc: "Duration filter not matching",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Filters: &types.AccessLogFilters{
					MinDuration: ptypes.Duration(1 * time.Hour),
				},
			},
			expectedLog: ``,
		},
		{
			desc: "Duration filter matching",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Filters: &types.AccessLogFilters{
					MinDuration: ptypes.Duration(1 * time.Millisecond),
				},
			},
			expectedLog: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testRouter" "http://127.0.0.1/testService" 1ms`,
		},
		{
			desc: "Retry attempts filter matching",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Filters: &types.AccessLogFilters{
					RetryAttempts: true,
				},
			},
			expectedLog: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testRouter" "http://127.0.0.1/testService" 1ms`,
		},
		{
			desc: "Default mode keep",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "keep",
				},
			},
			expectedLog: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testRouter" "http://127.0.0.1/testService" 1ms`,
		},
		{
			desc: "Default mode keep with override",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "keep",
					Names: map[string]string{
						ClientHost: "drop",
					},
				},
			},
			expectedLog: `- - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testRouter" "http://127.0.0.1/testService" 1ms`,
		},
		{
			desc: "Default mode drop",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
				},
			},
			expectedLog: `- - - [-] "- - -" - - "testReferer" "testUserAgent" - "-" "-" 0ms`,
		},
		{
			desc: "Default mode drop with override",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
					Names: map[string]string{
						ClientHost:     "drop",
						ClientUsername: "keep",
					},
				},
			},
			expectedLog: `- - TestUser [-] "- - -" - - "testReferer" "testUserAgent" - "-" "-" 0ms`,
		},
		{
			desc: "Default mode drop with header dropped",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
					Names: map[string]string{
						ClientHost:     "drop",
						ClientUsername: "keep",
					},
					Headers: &types.FieldHeaders{
						DefaultMode: "drop",
					},
				},
			},
			expectedLog: `- - TestUser [-] "- - -" - - "-" "-" - "-" "-" 0ms`,
		},
		{
			desc: "Default mode drop with header redacted",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
					Names: map[string]string{
						ClientHost:     "drop",
						ClientUsername: "keep",
					},
					Headers: &types.FieldHeaders{
						DefaultMode: "redact",
					},
				},
			},
			expectedLog: `- - TestUser [-] "- - -" - - "REDACTED" "REDACTED" - "-" "-" 0ms`,
		},
		{
			desc: "Default mode drop with header redacted",
			config: &types.AccessLog{
				FilePath: "",
				Format:   CommonFormat,
				Fields: &types.AccessLogFields{
					DefaultMode: "drop",
					Names: map[string]string{
						ClientHost:     "drop",
						ClientUsername: "keep",
					},
					Headers: &types.FieldHeaders{
						DefaultMode: "keep",
						Names: map[string]string{
							"Referer": "redact",
						},
					},
				},
			},
			expectedLog: `- - TestUser [-] "- - -" - - "REDACTED" "testUserAgent" - "-" "-" 0ms`,
		},
	}

	for _, test := range testCases {
		t.Run(test.desc, func(t *testing.T) {
			// NOTE: It is not possible to run these cases in parallel because we capture Stdout

			file, restoreStdout := captureStdout(t)
			defer restoreStdout()

			doLogging(t, test.config)

			written, err := os.ReadFile(file.Name())
			require.NoError(t, err, "unable to read captured stdout from file")
			assertValidLogData(t, test.expectedLog, written)
		})
	}
}

func assertValidLogData(t *testing.T, expected string, logData []byte) {
	t.Helper()

	if len(expected) == 0 {
		assert.Empty(t, logData)
		t.Log(string(logData))
		return
	}

	result, err := ParseAccessLog(string(logData))
	require.NoError(t, err)

	resultExpected, err := ParseAccessLog(expected)
	require.NoError(t, err)

	formatErrMessage := fmt.Sprintf("Expected:\t%q\nActual:\t%q", expected, string(logData))

	require.Equal(t, len(resultExpected), len(result), formatErrMessage)
	assert.Equal(t, resultExpected[ClientHost], result[ClientHost], formatErrMessage)
	assert.Equal(t, resultExpected[ClientUsername], result[ClientUsername], formatErrMessage)
	assert.Equal(t, resultExpected[RequestMethod], result[RequestMethod], formatErrMessage)
	assert.Equal(t, resultExpected[RequestPath], result[RequestPath], formatErrMessage)
	assert.Equal(t, resultExpected[RequestProtocol], result[RequestProtocol], formatErrMessage)
	assert.Equal(t, resultExpected[OriginStatus], result[OriginStatus], formatErrMessage)
	assert.Equal(t, resultExpected[OriginContentSize], result[OriginContentSize], formatErrMessage)
	assert.Equal(t, resultExpected[RequestRefererHeader], result[RequestRefererHeader], formatErrMessage)
	assert.Equal(t, resultExpected[RequestUserAgentHeader], result[RequestUserAgentHeader], formatErrMessage)
	assert.Regexp(t, regexp.MustCompile(`\d*`), result[RequestCount], formatErrMessage)
	assert.Equal(t, resultExpected[RouterName], result[RouterName], formatErrMessage)
	assert.Equal(t, resultExpected[ServiceURL], result[ServiceURL], formatErrMessage)
	assert.Regexp(t, regexp.MustCompile(`\d*ms`), result[Duration], formatErrMessage)
}

func captureStdout(t *testing.T) (out *os.File, restoreStdout func()) {
	t.Helper()

	file, err := os.CreateTemp("", "testlogger")
	require.NoError(t, err, "failed to create temp file")

	original := os.Stdout
	os.Stdout = file

	restoreStdout = func() {
		os.Stdout = original
		_ = os.RemoveAll(file.Name())
	}

	return file, restoreStdout
}

func doLoggingTLSOpt(t *testing.T, config *types.AccessLog, enableTLS bool) {
	t.Helper()
	logger, err := NewHandler(config)
	require.NoError(t, err)
	t.Cleanup(func() {
		err := logger.Close()
		require.NoError(t, err)
	})

	if config.FilePath != "" {
		_, err = os.Stat(config.FilePath)
		require.NoErrorf(t, err, "logger should create %s", config.FilePath)
	}

	req := &http.Request{
		Header: map[string][]string{
			"User-Agent": {testUserAgent},
			"Referer":    {testReferer},
		},
		Proto:      testProto,
		Host:       testHostname,
		Method:     testMethod,
		RemoteAddr: fmt.Sprintf("%s:%d", testHostname, testPort),
		URL: &url.URL{
			User: url.UserPassword(testUsername, ""),
			Path: testPath,
		},
		Body: io.NopCloser(bytes.NewReader([]byte("bar"))),
	}
	if enableTLS {
		req.TLS = &tls.ConnectionState{
			Version:     tls.VersionTLS13,
			CipherSuite: tls.TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
		}
	}

	chain := alice.New()
	chain = chain.Append(capture.Wrap)
	chain = chain.Append(WrapHandler(logger))
	handler, err := chain.Then(http.HandlerFunc(logWriterTestHandlerFunc))
	require.NoError(t, err)

	handler.ServeHTTP(httptest.NewRecorder(), req)
}

func doLoggingTLS(t *testing.T, config *types.AccessLog) {
	t.Helper()

	doLoggingTLSOpt(t, config, true)
}

func doLogging(t *testing.T, config *types.AccessLog) {
	t.Helper()

	doLoggingTLSOpt(t, config, false)
}

func logWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) {
	if _, err := rw.Write([]byte(testContent)); err != nil {
		http.Error(rw, err.Error(), http.StatusInternalServerError)
		return
	}

	logData := GetLogData(r)
	if logData != nil {
		logData.Core[RouterName] = testRouterName
		logData.Core[ServiceURL] = testServiceName
		logData.Core[OriginStatus] = testStatus
		logData.Core[OriginContentSize] = testContentSize
		logData.Core[RetryAttempts] = testRetryAttempts
		logData.Core[StartUTC] = testStart.UTC()
		logData.Core[StartLocal] = testStart.Local()
	} else {
		http.Error(rw, "LogData is nil", http.StatusInternalServerError)
		return
	}

	rw.WriteHeader(testStatus)
}