traefik/middlewares/accesslog/logger_test.go

364 lines
10 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 (
2017-05-25 11:25:53 +00:00
"encoding/json"
2016-04-19 23:45:59 +00:00
"fmt"
"io/ioutil"
"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"
2017-05-25 11:25:53 +00:00
"github.com/containous/traefik/types"
shellwords "github.com/mattn/go-shellwords"
"github.com/stretchr/testify/assert"
2017-05-22 19:39:29 +00:00
"github.com/stretchr/testify/require"
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"
2016-04-19 23:45:59 +00:00
testBackendName = "http://127.0.0.1/testBackend"
testFrontendName = "testFrontend"
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"
testMethod = "POST"
testReferer = "testReferer"
testUserAgent = "testUserAgent"
testRetryAttempts = 2
2016-04-19 23:45:59 +00:00
)
2017-09-15 13:02:03 +00:00
func TestLogRotation(t *testing.T) {
tempDir, err := ioutil.TempDir("", "traefik_")
if err != nil {
t.Fatalf("Error setting up temporary directory: %s", err)
}
fileName := tempDir + "traefik.log"
rotatedFileName := fileName + ".rotated"
config := &types.AccessLog{FilePath: fileName, Format: CommonFormat}
logHandler, err := NewLogHandler(config)
if err != nil {
t.Fatalf("Error creating new log handler: %s", err)
}
defer logHandler.Close()
recorder := httptest.NewRecorder()
req := httptest.NewRequest(http.MethodGet, "http://localhost", nil)
next := func(rw http.ResponseWriter, req *http.Request) {
rw.WriteHeader(http.StatusOK)
}
iterations := 20
halfDone := make(chan bool)
writeDone := make(chan bool)
go func() {
for i := 0; i < iterations; i++ {
logHandler.ServeHTTP(recorder, req, next)
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 := ioutil.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
}
2017-05-25 11:25:53 +00:00
func TestLoggerCLF(t *testing.T) {
tmpDir := createTempDir(t, CommonFormat)
2017-05-25 11:25:53 +00:00
defer os.RemoveAll(tmpDir)
logFilePath := filepath.Join(tmpDir, logFileNameSuffix)
config := &types.AccessLog{FilePath: logFilePath, Format: CommonFormat}
doLogging(t, config)
2017-05-25 11:25:53 +00:00
logData, err := ioutil.ReadFile(logFilePath)
2017-05-25 11:25:53 +00:00
require.NoError(t, err)
assertValidLogData(t, logData)
2017-05-25 11:25:53 +00:00
}
func TestLoggerJSON(t *testing.T) {
tmpDir := createTempDir(t, JSONFormat)
2017-05-25 11:25:53 +00:00
defer os.RemoveAll(tmpDir)
logFilePath := filepath.Join(tmpDir, logFileNameSuffix)
config := &types.AccessLog{FilePath: logFilePath, Format: JSONFormat}
doLogging(t, config)
2017-05-25 11:25:53 +00:00
logData, err := ioutil.ReadFile(logFilePath)
require.NoError(t, err)
jsonData := make(map[string]interface{})
err = json.Unmarshal(logData, &jsonData)
require.NoError(t, err)
expectedKeys := []string{
RequestHost,
RequestAddr,
RequestMethod,
RequestPath,
RequestProtocol,
RequestPort,
RequestLine,
DownstreamStatus,
DownstreamStatusLine,
DownstreamContentSize,
OriginContentSize,
OriginStatus,
"request_Referer",
"request_User-Agent",
FrontendName,
BackendURL,
ClientUsername,
ClientHost,
ClientPort,
ClientAddr,
"level",
"msg",
"downstream_Content-Type",
RequestCount,
Duration,
Overhead,
RetryAttempts,
2017-05-25 11:25:53 +00:00
"time",
"StartLocal",
"StartUTC",
}
containsKeys(t, expectedKeys, jsonData)
var assertCount int
assert.Equal(t, testHostname, jsonData[RequestHost])
assertCount++
assert.Equal(t, testHostname, jsonData[RequestAddr])
assertCount++
assert.Equal(t, testMethod, jsonData[RequestMethod])
assertCount++
assert.Equal(t, testPath, jsonData[RequestPath])
assertCount++
assert.Equal(t, testProto, jsonData[RequestProtocol])
assertCount++
assert.Equal(t, "-", jsonData[RequestPort])
assertCount++
assert.Equal(t, fmt.Sprintf("%s %s %s", testMethod, testPath, testProto), jsonData[RequestLine])
assertCount++
assert.Equal(t, float64(testStatus), jsonData[DownstreamStatus])
assertCount++
assert.Equal(t, fmt.Sprintf("%d ", testStatus), jsonData[DownstreamStatusLine])
assertCount++
assert.Equal(t, float64(len(testContent)), jsonData[DownstreamContentSize])
2017-05-25 11:25:53 +00:00
assertCount++
assert.Equal(t, float64(len(testContent)), jsonData[OriginContentSize])
2017-05-25 11:25:53 +00:00
assertCount++
assert.Equal(t, float64(testStatus), jsonData[OriginStatus])
assertCount++
assert.Equal(t, testReferer, jsonData["request_Referer"])
assertCount++
assert.Equal(t, testUserAgent, jsonData["request_User-Agent"])
assertCount++
assert.Equal(t, testFrontendName, jsonData[FrontendName])
assertCount++
assert.Equal(t, testBackendName, jsonData[BackendURL])
assertCount++
assert.Equal(t, testUsername, jsonData[ClientUsername])
assertCount++
assert.Equal(t, testHostname, jsonData[ClientHost])
assertCount++
assert.Equal(t, fmt.Sprintf("%d", testPort), jsonData[ClientPort])
assertCount++
assert.Equal(t, fmt.Sprintf("%s:%d", testHostname, testPort), jsonData[ClientAddr])
assertCount++
assert.Equal(t, "info", jsonData["level"])
assertCount++
assert.Equal(t, "", jsonData["msg"])
assertCount++
assert.Equal(t, "text/plain; charset=utf-8", jsonData["downstream_Content-Type"].(string))
assertCount++
assert.NotZero(t, jsonData[RequestCount].(float64))
assertCount++
assert.NotZero(t, jsonData[Duration].(float64))
assertCount++
assert.NotZero(t, jsonData[Overhead].(float64))
assertCount++
assert.Equal(t, float64(testRetryAttempts), jsonData[RetryAttempts].(float64))
assertCount++
2017-05-25 11:25:53 +00:00
assert.NotEqual(t, "", jsonData["time"].(string))
assertCount++
assert.NotEqual(t, "", jsonData["StartLocal"].(string))
assertCount++
assert.NotEqual(t, "", jsonData["StartUTC"].(string))
assertCount++
assert.Equal(t, len(jsonData), assertCount, string(logData))
}
func TestNewLogHandlerOutputStdout(t *testing.T) {
file, restoreStdout := captureStdout(t)
defer restoreStdout()
config := &types.AccessLog{FilePath: "", Format: CommonFormat}
doLogging(t, config)
written, err := ioutil.ReadFile(file.Name())
require.NoError(t, err, "unable to read captured stdout from file")
require.NotZero(t, len(written), "expected access log message on stdout")
assertValidLogData(t, written)
2017-05-25 11:25:53 +00:00
}
func assertValidLogData(t *testing.T, logData []byte) {
tokens, err := shellwords.Parse(string(logData))
require.NoError(t, err)
formatErrMessage := fmt.Sprintf(`
Expected: TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 1 "testFrontend" "http://127.0.0.1/testBackend" 1ms
Actual: %s
`,
string(logData))
require.Equal(t, 14, len(tokens), formatErrMessage)
assert.Equal(t, testHostname, tokens[0], formatErrMessage)
assert.Equal(t, testUsername, tokens[2], formatErrMessage)
assert.Equal(t, fmt.Sprintf("%s %s %s", testMethod, testPath, testProto), tokens[5], formatErrMessage)
assert.Equal(t, fmt.Sprintf("%d", testStatus), tokens[6], formatErrMessage)
assert.Equal(t, fmt.Sprintf("%d", len(testContent)), tokens[7], formatErrMessage)
assert.Equal(t, testReferer, tokens[8], formatErrMessage)
assert.Equal(t, testUserAgent, tokens[9], formatErrMessage)
assert.Regexp(t, regexp.MustCompile("[0-9]*"), tokens[10], formatErrMessage)
assert.Equal(t, testFrontendName, tokens[11], formatErrMessage)
assert.Equal(t, testBackendName, tokens[12], formatErrMessage)
2017-05-25 11:25:53 +00:00
}
func captureStdout(t *testing.T) (out *os.File, restoreStdout func()) {
file, err := ioutil.TempFile("", "testlogger")
require.NoError(t, err, "failed to create temp file")
original := os.Stdout
os.Stdout = file
restoreStdout = func() {
os.Stdout = original
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
func createTempDir(t *testing.T, prefix string) string {
tmpDir, err := ioutil.TempDir("", prefix)
require.NoError(t, err, "failed to create temp dir")
2017-05-25 11:25:53 +00:00
return tmpDir
}
func doLogging(t *testing.T, config *types.AccessLog) {
logger, err := NewLogHandler(config)
2017-05-25 11:25:53 +00:00
require.NoError(t, err)
2017-08-18 00:18:02 +00:00
defer logger.Close()
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{
User: url.UserPassword(testUsername, ""),
Path: testPath,
},
}
logger.ServeHTTP(httptest.NewRecorder(), req, logWriterTestHandlerFunc)
}
func containsKeys(t *testing.T, expectedKeys []string, data map[string]interface{}) {
for key, value := range data {
if !contains(expectedKeys, key) {
t.Errorf("Unexpected log key: %s [value: %s]", key, value)
}
}
for _, k := range expectedKeys {
if _, ok := data[k]; !ok {
t.Errorf("the expected key '%s' is not present in the map. %+v", k, data)
}
}
2016-04-19 23:45:59 +00:00
}
func contains(values []string, value string) bool {
for _, v := range values {
if value == v {
return true
}
}
return false
2016-04-19 23:45:59 +00:00
}
2017-05-25 11:25:53 +00:00
func logWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) {
rw.Write([]byte(testContent))
2016-04-19 23:45:59 +00:00
rw.WriteHeader(testStatus)
2017-05-22 19:39:29 +00:00
logDataTable := GetLogDataTable(r)
logDataTable.Core[FrontendName] = testFrontendName
logDataTable.Core[BackendURL] = testBackendName
logDataTable.Core[OriginStatus] = testStatus
logDataTable.Core[OriginContentSize] = testContentSize
logDataTable.Core[RetryAttempts] = testRetryAttempts
2016-04-19 23:45:59 +00:00
}