narco/logger_test.go

package narco

import (
	"bytes"
	"fmt"
	"log"
	"net/http"
	"net/http/httptest"

	. "gopkg.in/check.v1"
)

type LogSuite struct {
	*NarcoSuite

	l             *Logger
	buffer        bytes.Buffer
	rec           *httptest.ResponseRecorder
	req           *http.Request
	URL           string
	RemoteAddress string
	UserAgent     string
}

var _ = Suite(&LogSuite{NarcoSuite: NewNarcoSuite()})

func (s *LogSuite) SetUpSuite(c *C) {

	s.l = NewLogger()
	s.l.Logger = log.New(&s.buffer, "[narco] ", log.LstdFlags)
	s.chain = s.chain.Append(s.l.Wrap())

	c.Assert(s.chain, NotNil)
}

func (s *LogSuite) SetUpTest(c *C) {
	s.buffer.Reset()
	s.rec = httptest.NewRecorder()
	var err error
	s.URL = "http://" + httptest.DefaultRemoteAddr + "/"
	s.req, err = http.NewRequest("GET", s.URL, nil)
	c.Assert(err, IsNil, Commentf("Unexpected error :%s", err))
	s.RemoteAddress = httptest.DefaultRemoteAddr
}

func (s *LogSuite) TestLogAreOnTwoLine(c *C) {
	//when logging first line is the request, second line is the result
	s.ServeHTTP(s.rec, s.req, func(rw http.ResponseWriter, req *http.Request) {
		fmt.Fprintf(rw, "foo")
	})

	c.Assert(s.buffer.String(), Matches, `\[narco\] .* Requested .*
\[narco\] .* returned .*
`)
}

func (s *LogSuite) TestReportTheMethod(c *C) {
	data := []string{
		"GET", "POST", "PUT", "HEAD", "DELETE", "TRACE", "CONNECT",
	}

	for _, m := range data {
		s.req.Method = m
		//when logging first line is the request, second line is the result
		s.ServeHTTP(s.rec, s.req, func(rw http.ResponseWriter, req *http.Request) {
			fmt.Fprintf(rw, "foo")
		})

		c.Assert(s.buffer.String(), Matches, `\A\[narco\] .* Requested `+m+".*\n.*\n")
		s.buffer.Reset()
	}
}

func (s *LogSuite) TestReportTheURI(c *C) {
	data := map[string]string{
		"/":        "/",
		"/foo":     "/foo",
		"/bar/baz": "/bar/baz",
	}
	var err error
	for reqURI, resURI := range data {

		s.req, err = http.NewRequest("GET", "http://"+httptest.DefaultRemoteAddr+reqURI, nil)
		c.Assert(err, IsNil, Commentf("Unexpected error: %s", err))
		//when logging first line is the request, second line is the result
		s.ServeHTTP(s.rec, s.req, func(rw http.ResponseWriter, req *http.Request) {
			fmt.Fprintf(rw, "foo")
		})

		c.Assert(s.buffer.String(), Matches, `\A\[narco\] .* Requested [A-Z]+ on `+resURI+".*\n.*\n")
		s.buffer.Reset()
	}
}

func (s *LogSuite) TestLogReportsRemoteAddress(c *C) {
	data := map[string]string{
		"": `\<unknown\>`,
		httptest.DefaultRemoteAddr: httptest.DefaultRemoteAddr,
	}
	for reqAddress, reported := range data {
		s.req.RemoteAddr = reqAddress
		s.ServeHTTP(s.rec, s.req, func(rw http.ResponseWriter, req *http.Request) {
			fmt.Fprintf(rw, "foo")
		})
		c.Assert(s.buffer.String(), Matches, `\A\[narco\] .* Requested [A-Z]+ on .* from `+reported+` .*`+"\n.*\n")
		s.buffer.Reset()
	}
}

func (s *LogSuite) TestLogReportTheUserAgent(c *C) {

	data := map[string]func(*http.Request){
		`\<unknown\>`:      func(*http.Request) {},
		"golangtest/1.0.0": func(req *http.Request) { req.Header["User-Agent"] = []string{"golangtest/1.0.0"} },
	}

	for uAgent, reqModifier := range data {
		req, err := http.NewRequest("GET", s.URL, nil)
		c.Assert(err, IsNil, Commentf("Unexpected error: %s", err))
		reqModifier(req)
		s.ServeHTTP(s.rec, req, func(rw http.ResponseWriter, req *http.Request) {
			fmt.Fprintf(rw, "foo")
		})
		c.Assert(s.buffer.String(), Matches, `\A\[narco\] .* Requested [A-Z]+ on .* from .* \(User-Agent: `+uAgent+`\)`+"\n.*\n")
		s.buffer.Reset()
	}
}

func (s *LogSuite) TestLogReportsTheStatus(c *C) {
	data := []int{http.StatusOK, http.StatusUnauthorized, http.StatusInternalServerError}

	for _, status := range data {

		s.ServeHTTP(s.rec, s.req, func(rw http.ResponseWriter, req *http.Request) {
			rw.WriteHeader(status)
			fmt.Fprintf(rw, "foo")
		})

		matchString := fmt.Sprintf(`\A\[narco\] .*`+"\n"+`\[narco\] .* returned %d: .*, .*`+"\n", status)

		c.Assert(s.buffer.String(), Matches, matchString)
		s.buffer.Reset()
	}
}

func (s *LogSuite) TestLogReportsTheResponseSize(c *C) {

	data := []string{
		"foo",
		"longer payload",
		`<!doctype html>
<html>
  <head>
    <title>test</title>
  </head>
  <body>
    <h1>Hello World!!</h1>
  </body>
</html>`,
	}

	for _, payload := range data {
		s.ServeHTTP(s.rec, s.req, func(rw http.ResponseWriter, req *http.Request) {
			fmt.Fprintf(rw, "%s", payload)
		})

		matchString := fmt.Sprintf(`\A\[narco\] .*`+"\n"+`\[narco\] .* returned [0-9]+: .*, size: %dB .*`+"\n",
			len(payload))

		c.Assert(s.buffer.String(), Matches, matchString)
		s.buffer.Reset()

	}
}

func (s *LogSuite) TestLogReportsTheResponseTime(c *C) {

	s.ServeHTTP(s.rec, s.req, func(rw http.ResponseWriter, req *http.Request) {
		fmt.Fprintf(rw, "foo")
	})

	matchString := `\A\[narco\] .*` + "\n" + `\[narco\] .* returned [0-9]+: .*, size: 3B in [0-9]+\.[0-9]+.*s` + "\n"

	c.Assert(s.buffer.String(), Matches, matchString)

}