Add errors middleware; export httpserver.WriteTextResponse

caddyhttp/caddyhttp.go

@@ -6,6 +6,7 @@ import (
 
 	// plug in the standard directives
 	_ "github.com/mholt/caddy/caddyhttp/bind"
+	_ "github.com/mholt/caddy/caddyhttp/errors"
 	_ "github.com/mholt/caddy/caddyhttp/gzip"
 	_ "github.com/mholt/caddy/caddyhttp/log"
 	_ "github.com/mholt/caddy/caddyhttp/root"

caddyhttp/errors/errors.go

@@ -0,0 +1,141 @@
+// Package errors implements an HTTP error handling middleware.
+package errors
+
+import (
+	"fmt"
+	"io"
+	"log"
+	"net/http"
+	"os"
+	"runtime"
+	"strings"
+	"time"
+
+	"github.com/mholt/caddy"
+	"github.com/mholt/caddy/caddyhttp/httpserver"
+)
+
+func init() {
+	caddy.RegisterPlugin(caddy.Plugin{
+		Name:       "errors",
+		ServerType: "http",
+		Action:     setup,
+	})
+}
+
+// ErrorHandler handles HTTP errors (and errors from other middleware).
+type ErrorHandler struct {
+	Next       httpserver.Handler
+	ErrorPages map[int]string // map of status code to filename
+	LogFile    string
+	Log        *log.Logger
+	LogRoller  *httpserver.LogRoller
+	Debug      bool // if true, errors are written out to client rather than to a log
+}
+
+func (h ErrorHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, error) {
+	defer h.recovery(w, r)
+
+	status, err := h.Next.ServeHTTP(w, r)
+
+	if err != nil {
+		errMsg := fmt.Sprintf("%s [ERROR %d %s] %v", time.Now().Format(timeFormat), status, r.URL.Path, err)
+		if h.Debug {
+			// Write error to response instead of to log
+			w.Header().Set("Content-Type", "text/plain; charset=utf-8")
+			w.WriteHeader(status)
+			fmt.Fprintln(w, errMsg)
+			return 0, err // returning 0 signals that a response has been written
+		}
+		h.Log.Println(errMsg)
+	}
+
+	if status >= 400 {
+		h.errorPage(w, r, status)
+		return 0, err
+	}
+
+	return status, err
+}
+
+// errorPage serves a static error page to w according to the status
+// code. If there is an error serving the error page, a plaintext error
+// message is written instead, and the extra error is logged.
+func (h ErrorHandler) errorPage(w http.ResponseWriter, r *http.Request, code int) {
+	// See if an error page for this status code was specified
+	if pagePath, ok := h.ErrorPages[code]; ok {
+		// Try to open it
+		errorPage, err := os.Open(pagePath)
+		if err != nil {
+			// An additional error handling an error... <insert grumpy cat here>
+			h.Log.Printf("%s [NOTICE %d %s] could not load error page: %v",
+				time.Now().Format(timeFormat), code, r.URL.String(), err)
+			httpserver.DefaultErrorFunc(w, r, code)
+			return
+		}
+		defer errorPage.Close()
+
+		// Copy the page body into the response
+		w.Header().Set("Content-Type", "text/html; charset=utf-8")
+		w.WriteHeader(code)
+		_, err = io.Copy(w, errorPage)
+
+		if err != nil {
+			// Epic fail... sigh.
+			h.Log.Printf("%s [NOTICE %d %s] could not respond with %s: %v",
+				time.Now().Format(timeFormat), code, r.URL.String(), pagePath, err)
+			httpserver.DefaultErrorFunc(w, r, code)
+		}
+
+		return
+	}
+
+	// Default error response
+	httpserver.DefaultErrorFunc(w, r, code)
+}
+
+func (h ErrorHandler) recovery(w http.ResponseWriter, r *http.Request) {
+	rec := recover()
+	if rec == nil {
+		return
+	}
+
+	// Obtain source of panic
+	// From: https://gist.github.com/swdunlop/9629168
+	var name, file string // function name, file name
+	var line int
+	var pc [16]uintptr
+	n := runtime.Callers(3, pc[:])
+	for _, pc := range pc[:n] {
+		fn := runtime.FuncForPC(pc)
+		if fn == nil {
+			continue
+		}
+		file, line = fn.FileLine(pc)
+		name = fn.Name()
+		if !strings.HasPrefix(name, "runtime.") {
+			break
+		}
+	}
+
+	// Trim file path
+	delim := "/caddy/"
+	pkgPathPos := strings.Index(file, delim)
+	if pkgPathPos > -1 && len(file) > pkgPathPos+len(delim) {
+		file = file[pkgPathPos+len(delim):]
+	}
+
+	panicMsg := fmt.Sprintf("%s [PANIC %s] %s:%d - %v", time.Now().Format(timeFormat), r.URL.String(), file, line, rec)
+	if h.Debug {
+		// Write error and stack trace to the response rather than to a log
+		var stackBuf [4096]byte
+		stack := stackBuf[:runtime.Stack(stackBuf[:], false)]
+		httpserver.WriteTextResponse(w, http.StatusInternalServerError, fmt.Sprintf("%s\n\n%s", panicMsg, stack))
+	} else {
+		// Currently we don't use the function name, since file:line is more conventional
+		h.Log.Printf(panicMsg)
+		h.errorPage(w, r, http.StatusInternalServerError)
+	}
+}
+
+const timeFormat = "02/Jan/2006:15:04:05 -0700"

caddyhttp/errors/errors_test.go

@@ -0,0 +1,168 @@
+package errors
+
+import (
+	"bytes"
+	"errors"
+	"fmt"
+	"log"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"path/filepath"
+	"strconv"
+	"strings"
+	"testing"
+
+	"github.com/mholt/caddy/caddyhttp/httpserver"
+)
+
+func TestErrors(t *testing.T) {
+	// create a temporary page
+	path := filepath.Join(os.TempDir(), "errors_test.html")
+	f, err := os.Create(path)
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer os.Remove(path)
+
+	const content = "This is a error page"
+	_, err = f.WriteString(content)
+	if err != nil {
+		t.Fatal(err)
+	}
+	f.Close()
+
+	buf := bytes.Buffer{}
+	em := ErrorHandler{
+		ErrorPages: map[int]string{
+			http.StatusNotFound:  path,
+			http.StatusForbidden: "not_exist_file",
+		},
+		Log: log.New(&buf, "", 0),
+	}
+	_, notExistErr := os.Open("not_exist_file")
+
+	testErr := errors.New("test error")
+	tests := []struct {
+		next         httpserver.Handler
+		expectedCode int
+		expectedBody string
+		expectedLog  string
+		expectedErr  error
+	}{
+		{
+			next:         genErrorHandler(http.StatusOK, nil, "normal"),
+			expectedCode: http.StatusOK,
+			expectedBody: "normal",
+			expectedLog:  "",
+			expectedErr:  nil,
+		},
+		{
+			next:         genErrorHandler(http.StatusMovedPermanently, testErr, ""),
+			expectedCode: http.StatusMovedPermanently,
+			expectedBody: "",
+			expectedLog:  fmt.Sprintf("[ERROR %d %s] %v\n", http.StatusMovedPermanently, "/", testErr),
+			expectedErr:  testErr,
+		},
+		{
+			next:         genErrorHandler(http.StatusBadRequest, nil, ""),
+			expectedCode: 0,
+			expectedBody: fmt.Sprintf("%d %s\n", http.StatusBadRequest,
+				http.StatusText(http.StatusBadRequest)),
+			expectedLog: "",
+			expectedErr: nil,
+		},
+		{
+			next:         genErrorHandler(http.StatusNotFound, nil, ""),
+			expectedCode: 0,
+			expectedBody: content,
+			expectedLog:  "",
+			expectedErr:  nil,
+		},
+		{
+			next:         genErrorHandler(http.StatusForbidden, nil, ""),
+			expectedCode: 0,
+			expectedBody: fmt.Sprintf("%d %s\n", http.StatusForbidden,
+				http.StatusText(http.StatusForbidden)),
+			expectedLog: fmt.Sprintf("[NOTICE %d /] could not load error page: %v\n",
+				http.StatusForbidden, notExistErr),
+			expectedErr: nil,
+		},
+	}
+
+	req, err := http.NewRequest("GET", "/", nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	for i, test := range tests {
+		em.Next = test.next
+		buf.Reset()
+		rec := httptest.NewRecorder()
+		code, err := em.ServeHTTP(rec, req)
+
+		if err != test.expectedErr {
+			t.Errorf("Test %d: Expected error %v, but got %v",
+				i, test.expectedErr, err)
+		}
+		if code != test.expectedCode {
+			t.Errorf("Test %d: Expected status code %d, but got %d",
+				i, test.expectedCode, code)
+		}
+		if body := rec.Body.String(); body != test.expectedBody {
+			t.Errorf("Test %d: Expected body %q, but got %q",
+				i, test.expectedBody, body)
+		}
+		if log := buf.String(); !strings.Contains(log, test.expectedLog) {
+			t.Errorf("Test %d: Expected log %q, but got %q",
+				i, test.expectedLog, log)
+		}
+	}
+}
+
+func TestVisibleErrorWithPanic(t *testing.T) {
+	const panicMsg = "I'm a panic"
+	eh := ErrorHandler{
+		ErrorPages: make(map[int]string),
+		Debug:      true,
+		Next: httpserver.HandlerFunc(func(w http.ResponseWriter, r *http.Request) (int, error) {
+			panic(panicMsg)
+		}),
+	}
+
+	req, err := http.NewRequest("GET", "/", nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	rec := httptest.NewRecorder()
+
+	code, err := eh.ServeHTTP(rec, req)
+
+	if code != 0 {
+		t.Errorf("Expected error handler to return 0 (it should write to response), got status %d", code)
+	}
+	if err != nil {
+		t.Errorf("Expected error handler to return nil error (it should panic!), but got '%v'", err)
+	}
+
+	body := rec.Body.String()
+
+	if !strings.Contains(body, "[PANIC /] caddyhttp/errors/errors_test.go") {
+		t.Errorf("Expected response body to contain error log line, but it didn't:\n%s", body)
+	}
+	if !strings.Contains(body, panicMsg) {
+		t.Errorf("Expected response body to contain panic message, but it didn't:\n%s", body)
+	}
+	if len(body) < 500 {
+		t.Errorf("Expected response body to contain stack trace, but it was too short: len=%d", len(body))
+	}
+}
+
+func genErrorHandler(status int, err error, body string) httpserver.Handler {
+	return httpserver.HandlerFunc(func(w http.ResponseWriter, r *http.Request) (int, error) {
+		if len(body) > 0 {
+			w.Header().Set("Content-Length", strconv.Itoa(len(body)))
+			fmt.Fprint(w, body)
+		}
+		return status, err
+	})
+}

caddyhttp/errors/setup.go

@@ -0,0 +1,152 @@
+package errors
+
+import (
+	"io"
+	"log"
+	"os"
+	"path/filepath"
+	"strconv"
+
+	"github.com/hashicorp/go-syslog"
+	"github.com/mholt/caddy"
+	"github.com/mholt/caddy/caddyhttp/httpserver"
+)
+
+// setup configures a new errors middleware instance.
+func setup(c *caddy.Controller) error {
+	handler, err := errorsParse(c)
+	if err != nil {
+		return err
+	}
+
+	// Open the log file for writing when the server starts
+	c.OnStartup(func() error {
+		var err error
+		var writer io.Writer
+
+		switch handler.LogFile {
+		case "visible":
+			handler.Debug = true
+		case "stdout":
+			writer = os.Stdout
+		case "stderr":
+			writer = os.Stderr
+		case "syslog":
+			writer, err = gsyslog.NewLogger(gsyslog.LOG_ERR, "LOCAL0", "caddy")
+			if err != nil {
+				return err
+			}
+		default:
+			if handler.LogFile == "" {
+				writer = os.Stderr // default
+				break
+			}
+
+			var file *os.File
+			file, err = os.OpenFile(handler.LogFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0644)
+			if err != nil {
+				return err
+			}
+			if handler.LogRoller != nil {
+				file.Close()
+
+				handler.LogRoller.Filename = handler.LogFile
+
+				writer = handler.LogRoller.GetLogWriter()
+			} else {
+				writer = file
+			}
+		}
+
+		handler.Log = log.New(writer, "", 0)
+		return nil
+	})
+
+	httpserver.GetConfig(c.Key).AddMiddleware(func(next httpserver.Handler) httpserver.Handler {
+		handler.Next = next
+		return handler
+	})
+
+	return nil
+}
+
+func errorsParse(c *caddy.Controller) (*ErrorHandler, error) {
+	// Very important that we make a pointer because the startup
+	// function that opens the log file must have access to the
+	// same instance of the handler, not a copy.
+	handler := &ErrorHandler{ErrorPages: make(map[int]string)}
+
+	cfg := httpserver.GetConfig(c.Key)
+
+	optionalBlock := func() (bool, error) {
+		var hadBlock bool
+
+		for c.NextBlock() {
+			hadBlock = true
+
+			what := c.Val()
+			if !c.NextArg() {
+				return hadBlock, c.ArgErr()
+			}
+			where := c.Val()
+
+			if what == "log" {
+				if where == "visible" {
+					handler.Debug = true
+				} else {
+					handler.LogFile = where
+					if c.NextArg() {
+						if c.Val() == "{" {
+							c.IncrNest()
+							logRoller, err := httpserver.ParseRoller(c)
+							if err != nil {
+								return hadBlock, err
+							}
+							handler.LogRoller = logRoller
+						}
+					}
+				}
+			} else {
+				// Error page; ensure it exists
+				where = filepath.Join(cfg.Root, where)
+				f, err := os.Open(where)
+				if err != nil {
+					log.Printf("[WARNING] Unable to open error page '%s': %v", where, err)
+				}
+				f.Close()
+
+				whatInt, err := strconv.Atoi(what)
+				if err != nil {
+					return hadBlock, c.Err("Expecting a numeric status code, got '" + what + "'")
+				}
+				handler.ErrorPages[whatInt] = where
+			}
+		}
+		return hadBlock, nil
+	}
+
+	for c.Next() {
+		// weird hack to avoid having the handler values overwritten.
+		if c.Val() == "}" {
+			continue
+		}
+		// Configuration may be in a block
+		hadBlock, err := optionalBlock()
+		if err != nil {
+			return handler, err
+		}
+
+		// Otherwise, the only argument would be an error log file name or 'visible'
+		if !hadBlock {
+			if c.NextArg() {
+				if c.Val() == "visible" {
+					handler.Debug = true
+				} else {
+					handler.LogFile = c.Val()
+				}
+			}
+		}
+	}
+
+	return handler, nil
+}

caddyhttp/errors/setup_test.go

@@ -0,0 +1,154 @@
+package errors
+
+import (
+	"testing"
+
+	"github.com/mholt/caddy"
+	"github.com/mholt/caddy/caddyhttp/httpserver"
+)
+
+func TestSetup(t *testing.T) {
+	err := setup(caddy.NewTestController(`errors`))
+	if err != nil {
+		t.Errorf("Expected no errors, got: %v", err)
+	}
+	mids := httpserver.GetConfig("").Middleware()
+	if len(mids) == 0 {
+		t.Fatal("Expected middlewares, was nil instead")
+	}
+
+	handler := mids[0](httpserver.EmptyNext)
+	myHandler, ok := handler.(*ErrorHandler)
+	if !ok {
+		t.Fatalf("Expected handler to be type ErrorHandler, got: %#v", handler)
+	}
+
+	if myHandler.LogFile != "" {
+		t.Errorf("Expected '%s' as the default LogFile", "")
+	}
+	if myHandler.LogRoller != nil {
+		t.Errorf("Expected LogRoller to be nil, got: %v", *myHandler.LogRoller)
+	}
+	if !httpserver.SameNext(myHandler.Next, httpserver.EmptyNext) {
+		t.Error("'Next' field of handler was not set properly")
+	}
+
+	// Test Startup function -- TODO
+	// if len(c.Startup) == 0 {
+	// 	t.Fatal("Expected 1 startup function, had 0")
+	// }
+	// c.Startup[0]()
+	// if myHandler.Log == nil {
+	// 	t.Error("Expected Log to be non-nil after startup because Debug is not enabled")
+	// }
+}
+
+func TestErrorsParse(t *testing.T) {
+	tests := []struct {
+		inputErrorsRules     string
+		shouldErr            bool
+		expectedErrorHandler ErrorHandler
+	}{
+		{`errors`, false, ErrorHandler{
+			LogFile: "",
+		}},
+		{`errors errors.txt`, false, ErrorHandler{
+			LogFile: "errors.txt",
+		}},
+		{`errors visible`, false, ErrorHandler{
+			LogFile: "",
+			Debug:   true,
+		}},
+		{`errors { log visible }`, false, ErrorHandler{
+			LogFile: "",
+			Debug:   true,
+		}},
+		{`errors { log errors.txt
+        404 404.html
+        500 500.html
+}`, false, ErrorHandler{
+			LogFile: "errors.txt",
+			ErrorPages: map[int]string{
+				404: "404.html",
+				500: "500.html",
+			},
+		}},
+		{`errors { log errors.txt { size 2 age 10 keep 3 } }`, false, ErrorHandler{
+			LogFile: "errors.txt",
+			LogRoller: &httpserver.LogRoller{
+				MaxSize:    2,
+				MaxAge:     10,
+				MaxBackups: 3,
+				LocalTime:  true,
+			},
+		}},
+		{`errors { log errors.txt {
+            size 3
+            age 11
+            keep 5
+        }
+        404 404.html
+        503 503.html
+}`, false, ErrorHandler{
+			LogFile: "errors.txt",
+			ErrorPages: map[int]string{
+				404: "404.html",
+				503: "503.html",
+			},
+			LogRoller: &httpserver.LogRoller{
+				MaxSize:    3,
+				MaxAge:     11,
+				MaxBackups: 5,
+				LocalTime:  true,
+			},
+		}},
+	}
+	for i, test := range tests {
+		actualErrorsRule, err := errorsParse(caddy.NewTestController(test.inputErrorsRules))
+
+		if err == nil && test.shouldErr {
+			t.Errorf("Test %d didn't error, but it should have", i)
+		} else if err != nil && !test.shouldErr {
+			t.Errorf("Test %d errored, but it shouldn't have; got '%v'", i, err)
+		}
+		if actualErrorsRule.LogFile != test.expectedErrorHandler.LogFile {
+			t.Errorf("Test %d expected LogFile to be %s, but got %s",
+				i, test.expectedErrorHandler.LogFile, actualErrorsRule.LogFile)
+		}
+		if actualErrorsRule.Debug != test.expectedErrorHandler.Debug {
+			t.Errorf("Test %d expected Debug to be %v, but got %v",
+				i, test.expectedErrorHandler.Debug, actualErrorsRule.Debug)
+		}
+		if actualErrorsRule.LogRoller != nil && test.expectedErrorHandler.LogRoller == nil || actualErrorsRule.LogRoller == nil && test.expectedErrorHandler.LogRoller != nil {
+			t.Fatalf("Test %d expected LogRoller to be %v, but got %v",
+				i, test.expectedErrorHandler.LogRoller, actualErrorsRule.LogRoller)
+		}
+		if len(actualErrorsRule.ErrorPages) != len(test.expectedErrorHandler.ErrorPages) {
+			t.Fatalf("Test %d expected %d no of Error pages, but got %d ",
+				i, len(test.expectedErrorHandler.ErrorPages), len(actualErrorsRule.ErrorPages))
+		}
+		if actualErrorsRule.LogRoller != nil && test.expectedErrorHandler.LogRoller != nil {
+			if actualErrorsRule.LogRoller.Filename != test.expectedErrorHandler.LogRoller.Filename {
+				t.Fatalf("Test %d expected LogRoller Filename to be %s, but got %s",
+					i, test.expectedErrorHandler.LogRoller.Filename, actualErrorsRule.LogRoller.Filename)
+			}
+			if actualErrorsRule.LogRoller.MaxAge != test.expectedErrorHandler.LogRoller.MaxAge {
+				t.Fatalf("Test %d expected LogRoller MaxAge to be %d, but got %d",
+					i, test.expectedErrorHandler.LogRoller.MaxAge, actualErrorsRule.LogRoller.MaxAge)
+			}
+			if actualErrorsRule.LogRoller.MaxBackups != test.expectedErrorHandler.LogRoller.MaxBackups {
+				t.Fatalf("Test %d expected LogRoller MaxBackups to be %d, but got %d",
+					i, test.expectedErrorHandler.LogRoller.MaxBackups, actualErrorsRule.LogRoller.MaxBackups)
+			}
+			if actualErrorsRule.LogRoller.MaxSize != test.expectedErrorHandler.LogRoller.MaxSize {
+				t.Fatalf("Test %d expected LogRoller MaxSize to be %d, but got %d",
+					i, test.expectedErrorHandler.LogRoller.MaxSize, actualErrorsRule.LogRoller.MaxSize)
+			}
+			if actualErrorsRule.LogRoller.LocalTime != test.expectedErrorHandler.LogRoller.LocalTime {
+				t.Fatalf("Test %d expected LogRoller LocalTime to be %t, but got %t",
+					i, test.expectedErrorHandler.LogRoller.LocalTime, actualErrorsRule.LogRoller.LocalTime)
+			}
+		}
+	}
+
+}

caddyhttp/httpserver/server.go

@@ -214,7 +214,7 @@ func (s *Server) serveHTTP(w http.ResponseWriter, r *http.Request) (int, error)
 		if err != nil {
 			remoteHost = r.RemoteAddr
 		}
-		writeTextResponse(w, http.StatusNotFound, "No such site at "+s.Server.Addr)
+		WriteTextResponse(w, http.StatusNotFound, "No such site at "+s.Server.Addr)
 		log.Printf("[INFO] %s - No such site at %s (Remote: %s, Referer: %s)",
 			hostname, s.Server.Addr, remoteHost, r.Header.Get("Referer"))
 		return 0, nil
@@ -329,7 +329,7 @@ func (s *Server) OnStartupComplete() {
 	}
 	for _, site := range s.sites {
 		output := site.Addr.String()
-		if caddy.IsLocalhost(s.Address()) && !caddy.IsLocalhost(site.Addr.Host) {
+		if caddy.IsLoopback(s.Address()) && !caddy.IsLoopback(site.Addr.Host) {
 			output += " (only accessible on this machine)"
 		}
 		fmt.Println(output)
@@ -365,12 +365,12 @@ func (ln tcpKeepAliveListener) File() (*os.File, error) {
 // DefaultErrorFunc responds to an HTTP request with a simple description
 // of the specified HTTP status code.
 func DefaultErrorFunc(w http.ResponseWriter, r *http.Request, status int) {
-	writeTextResponse(w, status, fmt.Sprintf("%d %s", status, http.StatusText(status)))
+	WriteTextResponse(w, status, fmt.Sprintf("%d %s\n", status, http.StatusText(status)))
 }
 
-// writeTextResponse writes body with code status to w. The body will
+// WriteTextResponse writes body with code status to w. The body will
 // be interpreted as plain text.
-func writeTextResponse(w http.ResponseWriter, status int, body string) {
+func WriteTextResponse(w http.ResponseWriter, status int, body string) {
 	w.Header().Set("Content-Type", "text/plain; charset=utf-8")
 	w.Header().Set("X-Content-Type-Options", "nosniff")
 	w.WriteHeader(status)