logging_test.go

// Copyright 2013 The Gorilla Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package handlers

import (
	"bytes"
	"encoding/base64"
	"fmt"
	"io/ioutil"
	"math/rand"
	"mime/multipart"
	"net/http"
	"net/http/httptest"
	"net/url"
	"os"
	"path/filepath"
	"strings"
	"testing"
	"time"
)

func TestMakeLogger(t *testing.T) {
	rec := httptest.NewRecorder()
	logger, w := makeLogger(rec)
	// initial status
	if logger.Status() != http.StatusOK {
		t.Fatalf("wrong status, got %d want %d", logger.Status(), http.StatusOK)
	}
	// WriteHeader
	w.WriteHeader(http.StatusInternalServerError)
	if logger.Status() != http.StatusInternalServerError {
		t.Fatalf("wrong status, got %d want %d", logger.Status(), http.StatusInternalServerError)
	}
	// Write
	w.Write([]byte(ok))
	if logger.Size() != len(ok) {
		t.Fatalf("wrong size, got %d want %d", logger.Size(), len(ok))
	}
	// Header
	w.Header().Set("key", "value")
	if val := w.Header().Get("key"); val != "value" {
		t.Fatalf("wrong header, got %s want %s", val, "value")
	}
}

func TestLoggerCleanup(t *testing.T) {
	rand.Seed(time.Now().UnixNano())

	rbuf := make([]byte, 128)
	if _, err := rand.Read(rbuf); err != nil {
		t.Fatalf("Failed to generate random content: %v", err)
	}
	contents := base64.StdEncoding.EncodeToString(rbuf)

	var body bytes.Buffer
	body.WriteString(fmt.Sprintf(`
--boundary
Content-Disposition: form-data; name="buzz"; filename="example.txt"

%s
--boundary--
`, contents))
	r := multipart.NewReader(&body, "boundary")
	form, err := r.ReadForm(0) // small max memory to force flush to disk
	if err != nil {
		t.Fatalf("Failed to read multipart form: %v", err)
	}

	tmpFiles, err := ioutil.ReadDir(os.TempDir())
	if err != nil {
		t.Fatalf("Failed to list %s: %v", os.TempDir(), err)
	}

	var tmpFile string
	for _, f := range tmpFiles {
		if !strings.HasPrefix(f.Name(), "multipart-") {
			continue
		}

		path := filepath.Join(os.TempDir(), f.Name())
		switch b, err := ioutil.ReadFile(path); {
		case err != nil:
			t.Fatalf("Failed to read %s: %v", path, err)
		case string(b) != contents:
			continue
		default:
			tmpFile = path
			break
		}
	}

	if tmpFile == "" {
		t.Fatal("Could not find multipart form tmp file")
	}

	req := newRequest("GET", "/subdir/asdf")
	req.MultipartForm = form

	var buf bytes.Buffer
	handler := http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
		req.URL.Path = "/" // simulate http.StripPrefix and friends
		w.WriteHeader(200)
	})
	logger := LoggingHandler(&buf, handler)
	logger.ServeHTTP(httptest.NewRecorder(), req)

	if _, err := os.Stat(tmpFile); err == nil || !os.IsNotExist(err) {
		t.Fatalf("Expected %s to not exist, got %v", tmpFile, err)
	}
}

func TestLogPathRewrites(t *testing.T) {
	var buf bytes.Buffer

	handler := http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
		req.URL.Path = "/" // simulate http.StripPrefix and friends
		w.WriteHeader(200)
	})
	logger := LoggingHandler(&buf, handler)

	logger.ServeHTTP(httptest.NewRecorder(), newRequest("GET", "/subdir/asdf"))

	if !strings.Contains(buf.String(), "GET /subdir/asdf HTTP") {
		t.Fatalf("Got log %#v, wanted substring %#v", buf.String(), "GET /subdir/asdf HTTP")
	}
}

func BenchmarkWriteLog(b *testing.B) {
	loc, err := time.LoadLocation("Europe/Warsaw")
	if err != nil {
		b.Fatalf(err.Error())
	}
	ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc)

	req := newRequest("GET", "http://example.com")
	req.RemoteAddr = "192.168.100.5"

	b.ResetTimer()

	params := LogFormatterParams{
		Request:    req,
		URL:        *req.URL,
		TimeStamp:  ts,
		StatusCode: http.StatusUnauthorized,
		Size:       500,
	}

	buf := &bytes.Buffer{}

	for i := 0; i < b.N; i++ {
		buf.Reset()
		writeLog(buf, params)
	}
}

func TestLogFormatterWriteLog_Scenario1(t *testing.T) {
	formatter := writeLog
	expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100\n"
	LoggingScenario1(t, formatter, expected)
}

func TestLogFormatterCombinedLog_Scenario1(t *testing.T) {
	formatter := writeCombinedLog
	expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100 \"http://example.com\" " +
		"\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " +
		"AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n"
	LoggingScenario1(t, formatter, expected)
}

func TestLogFormatterWriteLog_Scenario2(t *testing.T) {
	formatter := writeLog
	expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"CONNECT www.example.com:443 HTTP/2.0\" 200 100\n"
	LoggingScenario2(t, formatter, expected)
}

func TestLogFormatterCombinedLog_Scenario2(t *testing.T) {
	formatter := writeCombinedLog
	expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"CONNECT www.example.com:443 HTTP/2.0\" 200 100 \"http://example.com\" " +
		"\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " +
		"AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n"
	LoggingScenario2(t, formatter, expected)
}

func TestLogFormatterWriteLog_Scenario3(t *testing.T) {
	formatter := writeLog
	expected := "192.168.100.5 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 401 500\n"
	LoggingScenario3(t, formatter, expected)
}

func TestLogFormatterCombinedLog_Scenario3(t *testing.T) {
	formatter := writeCombinedLog
	expected := "192.168.100.5 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 401 500 \"http://example.com\" " +
		"\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " +
		"AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n"
	LoggingScenario3(t, formatter, expected)
}

func TestLogFormatterWriteLog_Scenario4(t *testing.T) {
	formatter := writeLog
	expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET /test?abc=hello%20world&a=b%3F HTTP/1.1\" 200 100\n"
	LoggingScenario4(t, formatter, expected)
}

func TestLogFormatterCombinedLog_Scenario5(t *testing.T) {
	formatter := writeCombinedLog
	expected := "::1 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100 \"http://example.com\" " +
		"\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " +
		"AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n"
	LoggingScenario5(t, formatter, expected)
}

func TestLogFormatterWriteLog_Scenario6(t *testing.T) {
	formatter := writeLog
	expected := "192.168.100.5 - JohnDoe [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 401 500\n"
	LoggingScenario6(t, formatter, expected)
}

func LoggingScenario1(t *testing.T, formatter LogFormatter, expected string) {
	loc, err := time.LoadLocation("Europe/Warsaw")
	if err != nil {
		panic(err)
	}
	ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc)

	// A typical request with an OK response
	req := constructTypicalRequestOk()

	buf := new(bytes.Buffer)
	params := LogFormatterParams{
		Request:    req,
		URL:        *req.URL,
		TimeStamp:  ts,
		StatusCode: http.StatusOK,
		Size:       100,
	}

	formatter(buf, params)
	log := buf.String()

	if log != expected {
		t.Fatalf("wrong log, got %q want %q", log, expected)
	}
}

func LoggingScenario2(t *testing.T, formatter LogFormatter, expected string) {
	loc, err := time.LoadLocation("Europe/Warsaw")
	if err != nil {
		panic(err)
	}
	ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc)

	// CONNECT request over http/2.0
	req := constructConnectRequest()

	buf := new(bytes.Buffer)
	params := LogFormatterParams{
		Request:    req,
		URL:        *req.URL,
		TimeStamp:  ts,
		StatusCode: http.StatusOK,
		Size:       100,
	}
	formatter(buf, params)
	log := buf.String()

	if log != expected {
		t.Fatalf("wrong log, got %q want %q", log, expected)
	}
}

func LoggingScenario3(t *testing.T, formatter LogFormatter, expected string) {
	loc, err := time.LoadLocation("Europe/Warsaw")
	if err != nil {
		panic(err)
	}
	ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc)

	// Request with an unauthorized user
	req := constructTypicalRequestOk()
	req.URL.User = url.User("kamil")

	buf := new(bytes.Buffer)
	params := LogFormatterParams{
		Request:    req,
		URL:        *req.URL,
		TimeStamp:  ts,
		StatusCode: http.StatusUnauthorized,
		Size:       500,
	}
	formatter(buf, params)
	log := buf.String()

	if log != expected {
		t.Fatalf("wrong log, got %q want %q", log, expected)
	}
}

func LoggingScenario4(t *testing.T, formatter LogFormatter, expected string) {
	loc, err := time.LoadLocation("Europe/Warsaw")
	if err != nil {
		panic(err)
	}
	ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc)

	// Request with url encoded parameters
	req := constructEncodedRequest()

	buf := new(bytes.Buffer)
	params := LogFormatterParams{
		Request:    req,
		URL:        *req.URL,
		TimeStamp:  ts,
		StatusCode: http.StatusOK,
		Size:       100,
	}
	formatter(buf, params)
	log := buf.String()

	if log != expected {
		t.Fatalf("wrong log, got %q want %q", log, expected)
	}
}

func LoggingScenario5(t *testing.T, formatter LogFormatter, expected string) {
	loc, err := time.LoadLocation("Europe/Warsaw")
	if err != nil {
		panic(err)
	}
	ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc)

	req := constructTypicalRequestOk()
	req.URL.User = url.User("kamil")
	req.RemoteAddr = "::1"

	buf := new(bytes.Buffer)
	params := LogFormatterParams{
		Request:    req,
		URL:        *req.URL,
		TimeStamp:  ts,
		StatusCode: http.StatusOK,
		Size:       100,
	}
	formatter(buf, params)
	log := buf.String()

	if log != expected {
		t.Fatalf("wrong log, got %q want %q", log, expected)
	}
}
func LoggingScenario6(t *testing.T, formatter LogFormatter, expected string) {
	loc, err := time.LoadLocation("Europe/Warsaw")
	if err != nil {
		panic(err)
	}
	ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc)

	// Request with an unauthorized user
	req := constructTypicalRequestOk()
	// Set user via basic auth
	req.SetBasicAuth("JohnDoe", "some password")

	buf := new(bytes.Buffer)
	params := LogFormatterParams{
		Request:    req,
		URL:        *req.URL,
		TimeStamp:  ts,
		StatusCode: http.StatusUnauthorized,
		Size:       500,
	}
	formatter(buf, params)
	log := buf.String()

	if log != expected {
		t.Fatalf("wrong log, got %q want %q", log, expected)
	}
}

// A typical request with an OK response
func constructTypicalRequestOk() *http.Request {
	req := newRequest("GET", "http://example.com")
	req.RemoteAddr = "192.168.100.5"
	req.Header.Set("Referer", "http://example.com")
	req.Header.Set(
		"User-Agent",
		"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.33 "+
			"(KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33",
	)
	return req
}

// CONNECT request over http/2.0
func constructConnectRequest() *http.Request {
	req := &http.Request{
		Method:     "CONNECT",
		Host:       "www.example.com:443",
		Proto:      "HTTP/2.0",
		ProtoMajor: 2,
		ProtoMinor: 0,
		RemoteAddr: "192.168.100.5",
		Header:     http.Header{},
		URL:        &url.URL{Host: "www.example.com:443"},
	}
	req.Header.Set("Referer", "http://example.com")
	req.Header.Set(
		"User-Agent",
		"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.33 "+
			"(KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33",
	)
	return req
}

func constructEncodedRequest() *http.Request {
	req := constructTypicalRequestOk()
	req.URL, _ = url.Parse("http://example.com/test?abc=hello%20world&a=b%3F")
	return req
}