From 4f5a29d6d13e91e052e8a715d571300ec201bb49 Mon Sep 17 00:00:00 2001 From: Matthew Holt Date: Thu, 24 Sep 2015 16:21:28 -0600 Subject: [PATCH] errors: New 'visible' mode to write stack trace to response Also updated change list and added/improved tests --- config/setup/errors.go | 46 ++++++++++++++++++---------- config/setup/errors_test.go | 31 +++++++++++++++---- dist/CHANGES.txt | 2 ++ middleware/errors/errors.go | 46 +++++++++++++++++++--------- middleware/errors/errors_test.go | 51 ++++++++++++++++++++++++++++---- 5 files changed, 134 insertions(+), 42 deletions(-) diff --git a/config/setup/errors.go b/config/setup/errors.go index ae42f381b..bc131976b 100644 --- a/config/setup/errors.go +++ b/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() + } } } } diff --git a/config/setup/errors_test.go b/config/setup/errors_test.go index f161eaf3c..216c5de85 100644 --- a/config/setup/errors_test.go +++ b/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) diff --git a/dist/CHANGES.txt b/dist/CHANGES.txt index bf4c3c23a..9a1c0036f 100644 --- a/dist/CHANGES.txt +++ b/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 diff --git a/middleware/errors/errors.go b/middleware/errors/errors.go index 22209e914..e148899a8 100644 --- a/middleware/errors/errors.go +++ b/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... - 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... + 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" diff --git a/middleware/errors/errors_test.go b/middleware/errors/errors_test.go index e2e82cab1..8afa6bff5 100644 --- a/middleware/errors/errors_test.go +++ b/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)