254 lines
6.6 KiB
Go
254 lines
6.6 KiB
Go
package logging
|
|
|
|
import (
|
|
"bytes"
|
|
"log"
|
|
"net/http"
|
|
"net/http/httptest"
|
|
"os"
|
|
"path/filepath"
|
|
"regexp"
|
|
"strings"
|
|
"sync"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
func TestLogField(t *testing.T) {
|
|
tests := []struct {
|
|
in, want string
|
|
}{
|
|
{"", "-"},
|
|
{"plain", "plain"},
|
|
{"GET /a?b=c HTTP/1.1", "GET /a?b=c HTTP/1.1"},
|
|
{`say "hi"`, `say \x22hi\x22`},
|
|
{`back\slash`, `back\x5Cslash`},
|
|
{"tab\tnl\n", `tab\x09nl\x0A`},
|
|
{"del\x7f", `del\x7F`},
|
|
{"héllo", "héllo"}, // multi-byte UTF-8 passes through
|
|
}
|
|
for _, tc := range tests {
|
|
if got := logField(tc.in); got != tc.want {
|
|
t.Errorf("logField(%q) = %q, want %q", tc.in, got, tc.want)
|
|
}
|
|
}
|
|
}
|
|
|
|
func TestClientKey(t *testing.T) {
|
|
tests := []struct {
|
|
remote, want string
|
|
}{
|
|
{"192.0.2.1:1234", "192.0.2.1"},
|
|
{"[2001:db8::1]:443", "2001:db8::1"},
|
|
{"no-port", "no-port"},
|
|
{"", ""},
|
|
}
|
|
for _, tc := range tests {
|
|
req := &http.Request{
|
|
RemoteAddr: tc.remote,
|
|
}
|
|
if got := clientKey(req); got != tc.want {
|
|
t.Errorf("clientKey(%q) = %q, want %q", tc.remote, got, tc.want)
|
|
}
|
|
}
|
|
}
|
|
|
|
func TestStatusRecorder(t *testing.T) {
|
|
t.Run("first WriteHeader wins", func(t *testing.T) {
|
|
rec := &statusRecorder{
|
|
ResponseWriter: httptest.NewRecorder(),
|
|
}
|
|
rec.WriteHeader(http.StatusTeapot)
|
|
rec.WriteHeader(http.StatusInternalServerError)
|
|
if rec.status != http.StatusTeapot {
|
|
t.Fatalf("status = %d", rec.status)
|
|
}
|
|
})
|
|
t.Run("Write implies 200 and counts bytes", func(t *testing.T) {
|
|
inner := httptest.NewRecorder()
|
|
rec := &statusRecorder{
|
|
ResponseWriter: inner,
|
|
}
|
|
|
|
rec.Write([]byte("hello"))
|
|
rec.Write([]byte(" world"))
|
|
if rec.status != http.StatusOK || rec.bytes != 11 {
|
|
t.Fatalf("status = %d, bytes = %d", rec.status, rec.bytes)
|
|
}
|
|
if inner.Body.String() != "hello world" {
|
|
t.Fatalf("body = %q", inner.Body.String())
|
|
}
|
|
})
|
|
}
|
|
|
|
var clfTime = `\[\d{2}/[A-Z][a-z]{2}/\d{4}:\d{2}:\d{2}:\d{2} [+-]\d{4}\]`
|
|
|
|
func TestAccessLog(t *testing.T) {
|
|
tests := []struct {
|
|
name string
|
|
combined bool
|
|
handler http.HandlerFunc
|
|
setup func(*http.Request)
|
|
want string // regexp for the whole line
|
|
}{
|
|
{
|
|
name: "no body defaults to 200 and -",
|
|
handler: func(http.ResponseWriter, *http.Request) {
|
|
},
|
|
want: `^192\.0\.2\.1 - - ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 200 -$`,
|
|
},
|
|
{
|
|
name: "status and size",
|
|
handler: func(w http.ResponseWriter, _ *http.Request) {
|
|
w.WriteHeader(http.StatusNotFound)
|
|
w.Write([]byte("nope"))
|
|
},
|
|
want: `^192\.0\.2\.1 - - ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 404 4$`,
|
|
},
|
|
{
|
|
name: "basic auth user is escaped",
|
|
handler: func(w http.ResponseWriter, _ *http.Request) {
|
|
w.Write([]byte("x"))
|
|
},
|
|
setup: func(r *http.Request) {
|
|
r.SetBasicAuth(`bo"b`, "pw")
|
|
},
|
|
want: `^192\.0\.2\.1 - bo\\x22b ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 200 1$`,
|
|
},
|
|
{
|
|
name: "combined adds referer and user agent",
|
|
combined: true,
|
|
handler: func(http.ResponseWriter, *http.Request) {
|
|
},
|
|
setup: func(r *http.Request) {
|
|
r.Header.Set("Referer", "http://ref/")
|
|
r.Header.Set("User-Agent", `ua "1"`)
|
|
},
|
|
want: `^192\.0\.2\.1 - - ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 200 - "http://ref/" "ua \\x221\\x22"$`,
|
|
},
|
|
{
|
|
name: "combined with missing headers",
|
|
combined: true,
|
|
handler: func(http.ResponseWriter, *http.Request) {
|
|
},
|
|
setup: func(r *http.Request) {
|
|
r.Header.Del("User-Agent")
|
|
},
|
|
want: `^192\.0\.2\.1 - - ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 200 - "-" "-"$`,
|
|
},
|
|
}
|
|
for _, tc := range tests {
|
|
t.Run(tc.name, func(t *testing.T) {
|
|
var buf bytes.Buffer
|
|
logger := log.New(&buf, "", 0)
|
|
req := httptest.NewRequest(http.MethodGet, "/path?q=1", nil)
|
|
req.RemoteAddr = "192.0.2.1:5555"
|
|
if tc.setup != nil {
|
|
tc.setup(req)
|
|
}
|
|
w := httptest.NewRecorder()
|
|
AccessLog(logger, tc.combined, tc.handler).ServeHTTP(w, req)
|
|
|
|
line := strings.TrimSuffix(buf.String(), "\n")
|
|
if !regexp.MustCompile(tc.want).MatchString(line) {
|
|
t.Fatalf("log line\n %s\ndoes not match\n %s", line, tc.want)
|
|
}
|
|
})
|
|
}
|
|
}
|
|
|
|
// A handler behind AccessLog can hijack the connection through
|
|
// http.ResponseController, as a WebSocket upgrade does, and the request is
|
|
// still logged.
|
|
func TestAccessLogHijack(t *testing.T) {
|
|
var buffer lockedBuffer
|
|
handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
|
conn, readWriter, err := http.NewResponseController(w).Hijack()
|
|
if err != nil {
|
|
t.Errorf("hijack: %v", err)
|
|
return
|
|
}
|
|
defer conn.Close()
|
|
readWriter.WriteString("HTTP/1.1 204 No Content\r\n\r\n")
|
|
readWriter.Flush()
|
|
})
|
|
server := httptest.NewServer(
|
|
AccessLog(log.New(&buffer, "", 0), true, handler),
|
|
)
|
|
defer server.Close()
|
|
|
|
res, err := http.Get(server.URL + "/hijacked")
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
res.Body.Close()
|
|
if res.StatusCode != http.StatusNoContent {
|
|
t.Errorf("status = %d; want 204 from the hijacked connection", res.StatusCode)
|
|
}
|
|
|
|
// The line is written when the handler returns, after the client has its
|
|
// response.
|
|
deadline := time.Now().Add(time.Second)
|
|
for !strings.Contains(buffer.String(), `"GET /hijacked HTTP/1.1"`) {
|
|
if time.Now().After(deadline) {
|
|
t.Fatalf("request not logged: %q", buffer.String())
|
|
}
|
|
time.Sleep(5 * time.Millisecond)
|
|
}
|
|
}
|
|
|
|
// lockedBuffer is a bytes.Buffer safe to write from the server's goroutine
|
|
// while the test reads it.
|
|
type lockedBuffer struct {
|
|
mu sync.Mutex
|
|
buffer bytes.Buffer
|
|
}
|
|
|
|
func (b *lockedBuffer) Write(data []byte) (int, error) {
|
|
b.mu.Lock()
|
|
defer b.mu.Unlock()
|
|
return b.buffer.Write(data)
|
|
}
|
|
|
|
func (b *lockedBuffer) String() string {
|
|
b.mu.Lock()
|
|
defer b.mu.Unlock()
|
|
return b.buffer.String()
|
|
}
|
|
|
|
// An access log file is created if needed and appended to; "-" is stdout.
|
|
func TestOpenAccessLog(t *testing.T) {
|
|
path := filepath.Join(t.TempDir(), "access.log")
|
|
os.WriteFile(path, []byte("earlier line\n"), 0o600)
|
|
|
|
logger, closeLog, err := OpenAccessLog(path)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
logger.Print("new line")
|
|
if err := closeLog(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
data, err := os.ReadFile(filepath.Clean(path))
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if got := string(data); got != "earlier line\nnew line\n" {
|
|
t.Errorf("access log = %q; want the new line appended", got)
|
|
}
|
|
|
|
logger, closeLog, err = OpenAccessLog("-")
|
|
if err != nil || logger.Writer() != os.Stdout {
|
|
t.Errorf("OpenAccessLog(-) = %v, %v; want stdout", logger, err)
|
|
}
|
|
if err := closeLog(); err != nil {
|
|
t.Errorf("closing stdout's access log: %v", err)
|
|
}
|
|
|
|
_, _, err = OpenAccessLog(filepath.Join(t.TempDir(), "missing", "a.log"))
|
|
if err == nil || !strings.Contains(err.Error(), "opening access log") {
|
|
t.Errorf("missing directory: %v; want an error", err)
|
|
}
|
|
}
|