traefik/pkg/middlewares/accesslog/logger_test.go

829 lines
24 KiB
Go
Raw Normal View History

2017-05-22 19:39:29 +00:00
package accesslog
2016-04-19 23:45:59 +00:00
import (
"bytes"
2020-02-17 09:46:04 +00:00
"crypto/tls"
2017-05-25 11:25:53 +00:00
"encoding/json"
2016-04-19 23:45:59 +00:00
"fmt"
"io"
2016-04-19 23:45:59 +00:00
"net/http"
2017-05-25 11:25:53 +00:00
"net/http/httptest"
2016-04-19 23:45:59 +00:00
"net/url"
"os"
"path/filepath"
"regexp"
2017-09-15 13:02:03 +00:00
"strings"
2016-04-19 23:45:59 +00:00
"testing"
2017-09-15 13:02:03 +00:00
"time"
"github.com/containous/alice"
"github.com/stretchr/testify/assert"
2017-05-22 19:39:29 +00:00
"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"
2016-04-19 23:45:59 +00:00
)
var (
2017-05-25 11:25:53 +00:00
logFileNameSuffix = "/traefik/logger/test.log"
testContent = "Hello, World"
2018-11-14 09:18:03 +00:00
testServiceName = "http://127.0.0.1/testService"
testRouterName = "testRouter"
2016-04-19 23:45:59 +00:00
testStatus = 123
2017-05-22 19:39:29 +00:00
testContentSize int64 = 12
2016-04-19 23:45:59 +00:00
testHostname = "TestHost"
testUsername = "TestUser"
2017-05-22 19:39:29 +00:00
testPath = "testpath"
2016-04-19 23:45:59 +00:00
testPort = 8181
testProto = "HTTP/0.0"
2020-02-17 09:46:04 +00:00
testScheme = "http"
2017-11-20 08:40:03 +00:00
testMethod = http.MethodPost
2016-04-19 23:45:59 +00:00
testReferer = "testReferer"
testUserAgent = "testUserAgent"
testRetryAttempts = 2
2018-06-11 16:40:08 +00:00
testStart = time.Now()
2016-04-19 23:45:59 +00:00
)
2017-09-15 13:02:03 +00:00
func TestLogRotation(t *testing.T) {
2021-03-04 19:08:03 +00:00
fileName := filepath.Join(t.TempDir(), "traefik.log")
2017-09-15 13:02:03 +00:00
rotatedFileName := fileName + ".rotated"
config := &types.AccessLog{FilePath: fileName, Format: CommonFormat}
2018-11-14 09:18:03 +00:00
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.WrapHandler(&capture.Handler{}))
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)
2017-09-15 13:02:03 +00:00
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 := 0; i < iterations; i++ {
handler.ServeHTTP(recorder, req)
2017-09-15 13:02:03 +00:00
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()
2021-03-04 19:08:03 +00:00
fileContents, err := os.ReadFile(fileName)
2017-09-15 13:02:03 +00:00
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 {
test := test
t.Run(test.desc, func(t *testing.T) {
2021-03-04 19:08:03 +00:00
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.NoError(t, err, fmt.Sprintf("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.WrapHandler(&capture.Handler{}))
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)
2021-03-04 19:08:03 +00:00
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, ","))
}
})
}
}
2017-05-25 11:25:53 +00:00
func TestLoggerCLF(t *testing.T) {
2021-03-04 19:08:03 +00:00
logFilePath := filepath.Join(t.TempDir(), logFileNameSuffix)
config := &types.AccessLog{FilePath: logFilePath, Format: CommonFormat}
doLogging(t, config)
2017-05-25 11:25:53 +00:00
2021-03-04 19:08:03 +00:00
logData, err := os.ReadFile(logFilePath)
2017-05-25 11:25:53 +00:00
require.NoError(t, err)
2018-11-14 09:18:03 +00:00
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`
2018-03-14 13:12:04 +00:00
assertValidLogData(t, expectedLog, logData)
}
func TestLoggerCLFWithBufferingSize(t *testing.T) {
2021-03-04 19:08:03 +00:00
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)
2021-03-04 19:08:03 +00:00
logData, err := os.ReadFile(logFilePath)
require.NoError(t, err)
2018-11-14 09:18:03 +00:00
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)
}
2018-03-14 13:12:04 +00:00
func assertString(exp string) func(t *testing.T, actual interface{}) {
return func(t *testing.T, actual interface{}) {
t.Helper()
assert.Equal(t, exp, actual)
}
}
2018-11-14 09:18:03 +00:00
func assertNotEmpty() func(t *testing.T, actual interface{}) {
2018-03-14 13:12:04 +00:00
return func(t *testing.T, actual interface{}) {
t.Helper()
2018-11-14 09:18:03 +00:00
assert.NotEqual(t, "", actual)
2018-03-14 13:12:04 +00:00
}
}
func assertFloat64(exp float64) func(t *testing.T, actual interface{}) {
return func(t *testing.T, actual interface{}) {
t.Helper()
assert.Equal(t, exp, actual)
}
}
func assertFloat64NotZero() func(t *testing.T, actual interface{}) {
return func(t *testing.T, actual interface{}) {
t.Helper()
assert.NotZero(t, actual)
}
2017-05-25 11:25:53 +00:00
}
func TestLoggerJSON(t *testing.T) {
2018-03-14 13:12:04 +00:00
testCases := []struct {
desc string
config *types.AccessLog
2020-02-17 09:46:04 +00:00
tls bool
2018-03-14 13:12:04 +00:00
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),
2018-09-07 07:40:03 +00:00
RequestHost: assertString(testHostname),
RequestAddr: assertString(testHostname),
RequestMethod: assertString(testMethod),
RequestPath: assertString(testPath),
RequestProtocol: assertString(testProto),
2020-02-17 09:46:04 +00:00
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(fmt.Sprintf("%d", 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"),
2018-09-07 07:40:03 +00:00
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),
2018-11-14 09:18:03 +00:00
RouterName: assertString(testRouterName),
ServiceURL: assertString(testServiceName),
2018-09-07 07:40:03 +00:00
ClientUsername: assertString(testUsername),
ClientHost: assertString(testHostname),
ClientPort: assertString(fmt.Sprintf("%d", testPort)),
ClientAddr: assertString(fmt.Sprintf("%s:%d", testHostname, testPort)),
"level": assertString("info"),
"msg": assertString(""),
2018-03-14 13:12:04 +00:00
"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"),
2018-11-14 09:18:03 +00:00
"time": assertNotEmpty(),
StartLocal: assertNotEmpty(),
StartUTC: assertNotEmpty(),
2018-03-14 13:12:04 +00:00
},
},
{
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{}){
2018-09-07 07:40:03 +00:00
"level": assertString("info"),
"msg": assertString(""),
2018-11-14 09:18:03 +00:00
"time": assertNotEmpty(),
2018-03-14 13:12:04 +00:00
"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(""),
2018-11-14 09:18:03 +00:00
"time": assertNotEmpty(),
2018-03-14 13:12:04 +00:00
},
},
{
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{}){
2018-09-07 07:40:03 +00:00
"level": assertString("info"),
"msg": assertString(""),
2018-11-14 09:18:03 +00:00
"time": assertNotEmpty(),
2018-03-14 13:12:04 +00:00
"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{
2018-03-14 13:12:04 +00:00
RequestHost: "keep",
},
Headers: &types.FieldHeaders{
DefaultMode: "drop",
Names: map[string]string{
2018-03-14 13:12:04 +00:00
"Referer": "keep",
},
},
},
},
expected: map[string]func(t *testing.T, value interface{}){
RequestHost: assertString(testHostname),
"level": assertString("info"),
"msg": assertString(""),
2018-11-14 09:18:03 +00:00
"time": assertNotEmpty(),
2018-03-14 13:12:04 +00:00
RequestRefererHeader: assertString(testReferer),
},
},
}
2017-05-25 11:25:53 +00:00
2018-03-14 13:12:04 +00:00
for _, test := range testCases {
test := test
t.Run(test.desc, func(t *testing.T) {
t.Parallel()
2021-03-04 19:08:03 +00:00
logFilePath := filepath.Join(t.TempDir(), logFileNameSuffix)
2018-03-14 13:12:04 +00:00
test.config.FilePath = logFilePath
2020-02-17 09:46:04 +00:00
if test.tls {
doLoggingTLS(t, test.config)
} else {
doLogging(t, test.config)
}
2018-03-14 13:12:04 +00:00
2021-03-04 19:08:03 +00:00
logData, err := os.ReadFile(logFilePath)
2018-03-14 13:12:04 +00:00
require.NoError(t, err)
jsonData := make(map[string]interface{})
err = json.Unmarshal(logData, &jsonData)
require.NoError(t, err)
2017-05-25 11:25:53 +00:00
2018-03-14 13:12:04 +00:00
assert.Equal(t, len(test.expected), len(jsonData))
for field, assertion := range test.expected {
assertion(t, jsonData[field])
}
})
2017-05-25 11:25:53 +00:00
}
}
func TestNewLogHandlerOutputStdout(t *testing.T) {
2018-03-14 13:12:04 +00:00
testCases := []struct {
desc string
config *types.AccessLog
expectedLog string
}{
{
desc: "default config",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
},
2018-11-14 09:18:03 +00:00
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`,
2018-03-14 13:12:04 +00:00
},
{
desc: "default config with empty filters",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Filters: &types.AccessLogFilters{},
},
2018-11-14 09:18:03 +00:00
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`,
},
2018-03-14 13:12:04 +00:00
{
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"},
},
},
2018-11-14 09:18:03 +00:00
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`,
2018-03-14 13:12:04 +00:00
},
2018-06-11 16:40:08 +00:00
{
desc: "Duration filter not matching",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Filters: &types.AccessLogFilters{
MinDuration: ptypes.Duration(1 * time.Hour),
2018-06-11 16:40:08 +00:00
},
},
expectedLog: ``,
},
{
desc: "Duration filter matching",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Filters: &types.AccessLogFilters{
MinDuration: ptypes.Duration(1 * time.Millisecond),
2018-06-11 16:40:08 +00:00
},
},
2018-11-14 09:18:03 +00:00
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`,
2018-06-11 16:40:08 +00:00
},
{
desc: "Retry attempts filter matching",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Filters: &types.AccessLogFilters{
RetryAttempts: true,
},
},
2018-11-14 09:18:03 +00:00
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`,
},
2018-03-14 13:12:04 +00:00
{
desc: "Default mode keep",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "keep",
},
},
2018-11-14 09:18:03 +00:00
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`,
2018-03-14 13:12:04 +00:00
},
{
desc: "Default mode keep with override",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "keep",
Names: map[string]string{
2018-03-14 13:12:04 +00:00
ClientHost: "drop",
},
},
},
2018-11-14 09:18:03 +00:00
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`,
2018-03-14 13:12:04 +00:00
},
{
desc: "Default mode drop",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
},
},
2020-03-17 11:36:04 +00:00
expectedLog: `- - - [-] "- - -" - - "testReferer" "testUserAgent" - "-" "-" 0ms`,
2018-03-14 13:12:04 +00:00
},
{
desc: "Default mode drop with override",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: map[string]string{
2018-03-14 13:12:04 +00:00
ClientHost: "drop",
ClientUsername: "keep",
},
},
},
2020-03-17 11:36:04 +00:00
expectedLog: `- - TestUser [-] "- - -" - - "testReferer" "testUserAgent" - "-" "-" 0ms`,
2018-03-14 13:12:04 +00:00
},
{
desc: "Default mode drop with header dropped",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: map[string]string{
2018-03-14 13:12:04 +00:00
ClientHost: "drop",
ClientUsername: "keep",
},
Headers: &types.FieldHeaders{
DefaultMode: "drop",
},
},
},
2020-03-17 11:36:04 +00:00
expectedLog: `- - TestUser [-] "- - -" - - "-" "-" - "-" "-" 0ms`,
2018-03-14 13:12:04 +00:00
},
{
desc: "Default mode drop with header redacted",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: map[string]string{
2018-03-14 13:12:04 +00:00
ClientHost: "drop",
ClientUsername: "keep",
},
Headers: &types.FieldHeaders{
DefaultMode: "redact",
},
},
},
2020-03-17 11:36:04 +00:00
expectedLog: `- - TestUser [-] "- - -" - - "REDACTED" "REDACTED" - "-" "-" 0ms`,
2018-03-14 13:12:04 +00:00
},
{
desc: "Default mode drop with header redacted",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: map[string]string{
2018-03-14 13:12:04 +00:00
ClientHost: "drop",
ClientUsername: "keep",
},
Headers: &types.FieldHeaders{
DefaultMode: "keep",
Names: map[string]string{
2018-03-14 13:12:04 +00:00
"Referer": "redact",
},
},
},
},
2020-03-17 11:36:04 +00:00
expectedLog: `- - TestUser [-] "- - -" - - "REDACTED" "testUserAgent" - "-" "-" 0ms`,
2018-03-14 13:12:04 +00:00
},
}
2018-03-14 13:12:04 +00:00
for _, test := range testCases {
test := test
t.Run(test.desc, func(t *testing.T) {
// NOTE: It is not possible to run these cases in parallel because we capture Stdout
2017-05-25 11:25:53 +00:00
2018-03-14 13:12:04 +00:00
file, restoreStdout := captureStdout(t)
defer restoreStdout()
2018-03-14 13:12:04 +00:00
doLogging(t, test.config)
2021-03-04 19:08:03 +00:00
written, err := os.ReadFile(file.Name())
2018-03-14 13:12:04 +00:00
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) {
2020-12-29 09:54:03 +00:00
t.Helper()
2018-06-11 16:40:08 +00:00
if len(expected) == 0 {
assert.Zero(t, len(logData))
t.Log(string(logData))
return
2018-03-14 13:12:04 +00:00
}
2018-06-11 16:40:08 +00:00
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))
2018-06-11 16:40:08 +00:00
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)
2021-03-04 08:02:03 +00:00
assert.Regexp(t, regexp.MustCompile(`\d*`), result[RequestCount], formatErrMessage)
2018-11-14 09:18:03 +00:00
assert.Equal(t, resultExpected[RouterName], result[RouterName], formatErrMessage)
assert.Equal(t, resultExpected[ServiceURL], result[ServiceURL], formatErrMessage)
2021-03-04 08:02:03 +00:00
assert.Regexp(t, regexp.MustCompile(`\d*ms`), result[Duration], formatErrMessage)
2017-05-25 11:25:53 +00:00
}
func captureStdout(t *testing.T) (out *os.File, restoreStdout func()) {
2020-12-29 09:54:03 +00:00
t.Helper()
2021-03-04 19:08:03 +00:00
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())
2016-04-19 23:45:59 +00:00
}
2017-04-27 15:36:04 +00:00
return file, restoreStdout
}
2016-04-19 23:45:59 +00:00
2020-02-17 09:46:04 +00:00
func doLoggingTLSOpt(t *testing.T, config *types.AccessLog, enableTLS bool) {
2020-12-29 09:54:03 +00:00
t.Helper()
2018-11-14 09:18:03 +00:00
logger, err := NewHandler(config)
2017-05-25 11:25:53 +00:00
require.NoError(t, err)
t.Cleanup(func() {
err := logger.Close()
require.NoError(t, err)
})
2017-04-27 15:36:04 +00:00
if config.FilePath != "" {
_, err = os.Stat(config.FilePath)
require.NoError(t, err, fmt.Sprintf("logger should create %s", config.FilePath))
2017-04-27 15:36:04 +00:00
}
2017-05-22 19:39:29 +00:00
req := &http.Request{
2016-04-19 23:45:59 +00:00
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{
2018-11-14 09:18:03 +00:00
User: url.UserPassword(testUsername, ""),
2016-04-19 23:45:59 +00:00
Path: testPath,
},
Body: io.NopCloser(bytes.NewReader([]byte("bar"))),
2016-04-19 23:45:59 +00:00
}
2020-02-17 09:46:04 +00:00
if enableTLS {
req.TLS = &tls.ConnectionState{
Version: tls.VersionTLS13,
CipherSuite: tls.TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
}
2020-02-17 09:46:04 +00:00
}
2016-04-19 23:45:59 +00:00
chain := alice.New()
chain = chain.Append(capture.WrapHandler(&capture.Handler{}))
chain = chain.Append(WrapHandler(logger))
handler, err := chain.Then(http.HandlerFunc(logWriterTestHandlerFunc))
require.NoError(t, err)
handler.ServeHTTP(httptest.NewRecorder(), req)
}
2020-02-17 09:46:04 +00:00
func doLoggingTLS(t *testing.T, config *types.AccessLog) {
2020-12-29 09:54:03 +00:00
t.Helper()
2020-02-17 09:46:04 +00:00
doLoggingTLSOpt(t, config, true)
}
func doLogging(t *testing.T, config *types.AccessLog) {
2020-12-29 09:54:03 +00:00
t.Helper()
2020-02-17 09:46:04 +00:00
doLoggingTLSOpt(t, config, false)
}
2017-05-25 11:25:53 +00:00
func logWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) {
2018-08-06 18:00:03 +00:00
if _, err := rw.Write([]byte(testContent)); err != nil {
2018-11-14 09:18:03 +00:00
http.Error(rw, err.Error(), http.StatusInternalServerError)
return
2018-08-06 18:00:03 +00:00
}
2018-11-14 09:18:03 +00:00
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
}
2017-05-22 19:39:29 +00:00
2018-11-14 09:18:03 +00:00
rw.WriteHeader(testStatus)
2016-04-19 23:45:59 +00:00
}