errors: New 'visible' mode to write stack trace to response

Also updated change list and added/improved tests

config/setup/errors.go

@@ -25,16 +25,24 @@ func Errors(c *Controller) (middleware.Middleware, error) {
 		var err error
 		var writer io.Writer
 
-		if handler.LogFile == "stdout" {
+		switch handler.LogFile {
+		case "visible":
+			handler.Debug = true
+		case "stdout":
 			writer = os.Stdout
-		} else if handler.LogFile == "stderr" {
+		case "stderr":
 			writer = os.Stderr
-		} else if handler.LogFile == "syslog" {
+		case "syslog":
 			writer, err = gsyslog.NewLogger(gsyslog.LOG_ERR, "LOCAL0", "caddy")
 			if err != nil {
 				return err
 			}
-		} else if handler.LogFile != "" {
+		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 {
@@ -80,15 +88,19 @@ func errorsParse(c *Controller) (*errors.ErrorHandler, error) {
 			where := c.Val()
 
 			if what == "log" {
-				handler.LogFile = where
-				if c.NextArg() {
-					if c.Val() == "{" {
-						c.IncrNest()
-						logRoller, err := parseRoller(c)
-						if err != nil {
-							return hadBlock, err
+				if where == "visible" {
+					handler.Debug = true
+				} else {
+					handler.LogFile = where
+					if c.NextArg() {
+						if c.Val() == "{" {
+							c.IncrNest()
+							logRoller, err := parseRoller(c)
+							if err != nil {
+								return hadBlock, err
+							}
+							handler.LogRoller = logRoller
 						}
-						handler.LogRoller = logRoller
 					}
 				}
 			} else {
@@ -121,12 +133,14 @@ func errorsParse(c *Controller) (*errors.ErrorHandler, error) {
 			return handler, err
 		}
 
-		// Otherwise, the only argument would be an error log file name
+		// Otherwise, the only argument would be an error log file name or 'visible'
 		if !hadBlock {
 			if c.NextArg() {
-				handler.LogFile = c.Val()
-			} else {
-				handler.LogFile = errors.DefaultLogFilename
+				if c.Val() == "visible" {
+					handler.Debug = true
+				} else {
+					handler.LogFile = c.Val()
+				}
 			}
 		}
 	}

config/setup/errors_test.go

@@ -8,9 +8,7 @@ import (
 )
 
 func TestErrors(t *testing.T) {
-
 	c := NewTestController(`errors`)
-
 	mid, err := Errors(c)
 
 	if err != nil {
@@ -28,8 +26,8 @@ func TestErrors(t *testing.T) {
 		t.Fatalf("Expected handler to be type ErrorHandler, got: %#v", handler)
 	}
 
-	if myHandler.LogFile != errors.DefaultLogFilename {
-		t.Errorf("Expected %s as the default LogFile", errors.DefaultLogFilename)
+	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)
@@ -37,6 +35,15 @@ func TestErrors(t *testing.T) {
 	if !SameNext(myHandler.Next, EmptyNext) {
 		t.Error("'Next' field of handler was not set properly")
 	}
+
+	// Test Startup function
+	if len(c.Startup) == 0 {
+		t.Fatal("Expected 1 startup function, had 0")
+	}
+	err = 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) {
@@ -46,11 +53,19 @@ func TestErrorsParse(t *testing.T) {
 		expectedErrorHandler errors.ErrorHandler
 	}{
 		{`errors`, false, errors.ErrorHandler{
-			LogFile: errors.DefaultLogFilename,
+			LogFile: "",
 		}},
 		{`errors errors.txt`, false, errors.ErrorHandler{
 			LogFile: "errors.txt",
 		}},
+		{`errors visible`, false, errors.ErrorHandler{
+			LogFile: "",
+			Debug:   true,
+		}},
+		{`errors { log visible }`, false, errors.ErrorHandler{
+			LogFile: "",
+			Debug:   true,
+		}},
 		{`errors { log errors.txt
         404 404.html
         500 500.html
@@ -101,9 +116,13 @@ func TestErrorsParse(t *testing.T) {
 			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",
+			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)

dist/CHANGES.txt

@@ -4,7 +4,9 @@ CHANGES
 - basicauth: Support for legacy htpasswd files
 - browse: JSON response with file listing given Accept header
 - core: Caddyfile as command line argument
+- errors: Can write full stack trace to HTTP response for debugging
 - errors, log: Roll log files after certain size or age
+- proxy: Fix for 32-bit architectures
 - templates: Added .StripExt and .StripHTML methods
 - Internal improvements and minor bug fixes
 

middleware/errors/errors.go

@@ -14,13 +14,14 @@ import (
 	"github.com/mholt/caddy/middleware"
 )
 
-// ErrorHandler handles HTTP errors (or errors from other middleware).
+// ErrorHandler handles HTTP errors (and errors from other middleware).
 type ErrorHandler struct {
 	Next       middleware.Handler
 	ErrorPages map[int]string // map of status code to filename
 	LogFile    string
 	Log        *log.Logger
 	LogRoller  *middleware.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) {
@@ -29,12 +30,21 @@ func (h ErrorHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, er
 	status, err := h.Next.ServeHTTP(w, r)
 
 	if err != nil {
-		h.Log.Printf("%s [ERROR %d %s] %v", time.Now().Format(timeFormat), status, r.URL.Path, err)
+		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.WriteHeader(status)
+			fmt.Fprintln(w, errMsg)
+			return 0, err // returning < 400 signals that a response has been written
+		} else {
+			h.Log.Println(errMsg)
+		}
 	}
 
 	if status >= 400 {
-		h.errorPage(w, status)
-		return 0, err // status < 400 signals that a response has been written
+		h.errorPage(w, r, status)
+		return 0, err
 	}
 
 	return status, err
@@ -43,7 +53,7 @@ func (h ErrorHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, er
 // 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, code int) {
+func (h ErrorHandler) errorPage(w http.ResponseWriter, r *http.Request, code int) {
 	defaultBody := fmt.Sprintf("%d %s", code, http.StatusText(code))
 
 	// See if an error page for this status code was specified
@@ -52,9 +62,9 @@ func (h ErrorHandler) errorPage(w http.ResponseWriter, code int) {
 		// Try to open it
 		errorPage, err := os.Open(pagePath)
 		if err != nil {
-			// An error handling an error... <insert grumpy cat here>
-			h.Log.Printf("%s [HTTP %d] could not load error page %s: %v",
-				time.Now().Format(timeFormat), code, pagePath, err)
+			// 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)
 			http.Error(w, defaultBody, code)
 			return
 		}
@@ -67,8 +77,8 @@ func (h ErrorHandler) errorPage(w http.ResponseWriter, code int) {
 
 		if err != nil {
 			// Epic fail... sigh.
-			h.Log.Printf("%s [HTTP %d] could not respond with %s: %v",
-				time.Now().Format(timeFormat), code, pagePath, err)
+			h.Log.Printf("%s [NOTICE %d %s] could not respond with %s: %v",
+				time.Now().Format(timeFormat), code, r.URL.String(), pagePath, err)
 			http.Error(w, defaultBody, code)
 		}
 
@@ -110,10 +120,18 @@ func (h ErrorHandler) recovery(w http.ResponseWriter, r *http.Request) {
 		file = file[pkgPathPos+len(delim):]
 	}
 
-	// Currently we don't use the function name, as file:line is more conventional
-	h.Log.Printf("%s [PANIC %s] %s:%d - %v", time.Now().Format(timeFormat), r.URL.String(), file, line, rec)
-	h.errorPage(w, http.StatusInternalServerError)
+	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)]
+		w.WriteHeader(http.StatusInternalServerError)
+		fmt.Fprintf(w, "%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 DefaultLogFilename = "error.log"
 const timeFormat = "02/Jan/2006:15:04:05 -0700"

middleware/errors/errors_test.go

@@ -33,11 +33,12 @@ func TestErrors(t *testing.T) {
 
 	buf := bytes.Buffer{}
 	em := ErrorHandler{
-		ErrorPages: make(map[int]string),
-		Log:        log.New(&buf, "", 0),
+		ErrorPages: map[int]string{
+			http.StatusNotFound:  path,
+			http.StatusForbidden: "not_exist_file",
+		},
+		Log: log.New(&buf, "", 0),
 	}
-	em.ErrorPages[http.StatusNotFound] = path
-	em.ErrorPages[http.StatusForbidden] = "not_exist_file"
 	_, notExistErr := os.Open("not_exist_file")
 
 	testErr := errors.New("test error")
@@ -82,8 +83,8 @@ func TestErrors(t *testing.T) {
 			expectedCode: 0,
 			expectedBody: fmt.Sprintf("%d %s\n", http.StatusForbidden,
 				http.StatusText(http.StatusForbidden)),
-			expectedLog: fmt.Sprintf("[HTTP %d] could not load error page %s: %v\n",
-				http.StatusForbidden, "not_exist_file", notExistErr),
+			expectedLog: fmt.Sprintf("[NOTICE %d /] could not load error page: %v\n",
+				http.StatusForbidden, notExistErr),
 			expectedErr: nil,
 		},
 	}
@@ -117,6 +118,44 @@ func TestErrors(t *testing.T) {
 	}
 }
 
+func TestVisibleErrorWithPanic(t *testing.T) {
+	const panicMsg = "I'm a panic"
+	eh := ErrorHandler{
+		ErrorPages: make(map[int]string),
+		Debug:      true,
+		Next: middleware.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 /] middleware/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) middleware.Handler {
 	return middleware.HandlerFunc(func(w http.ResponseWriter, r *http.Request) (int, error) {
 		fmt.Fprint(w, body)