From 16250da3f0943a5199da8d18cb88cbadc0f3e882 Mon Sep 17 00:00:00 2001 From: Matthew Holt Date: Tue, 24 Jan 2017 19:09:44 -0700 Subject: [PATCH] errors: Fix low risk race condition at server close See issue #1371 for more information. --- caddyhttp/errors/errors.go | 14 ++++++++++++-- caddyhttp/errors/errors_test.go | 8 ++++++-- caddyhttp/errors/setup.go | 5 ++++- caddyhttp/errors/setup_test.go | 14 ++++++++++++-- 4 files changed, 34 insertions(+), 7 deletions(-) diff --git a/caddyhttp/errors/errors.go b/caddyhttp/errors/errors.go index 3425713a..e6060295 100644 --- a/caddyhttp/errors/errors.go +++ b/caddyhttp/errors/errors.go @@ -9,6 +9,7 @@ import ( "os" "runtime" "strings" + "sync" "time" "github.com/mholt/caddy" @@ -30,8 +31,9 @@ type ErrorHandler struct { LogFile string Log *log.Logger LogRoller *httpserver.LogRoller - Debug bool // if true, errors are written out to client rather than to a log - file *os.File // a log file to close when done + Debug bool // if true, errors are written out to client rather than to a log + file *os.File // a log file to close when done + fileMu *sync.RWMutex // like with log middleware, os.File can't "safely" be closed in a different goroutine } func (h ErrorHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, error) { @@ -48,7 +50,9 @@ func (h ErrorHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, er fmt.Fprintln(w, errMsg) return 0, err // returning 0 signals that a response has been written } + h.fileMu.RLock() h.Log.Println(errMsg) + h.fileMu.RUnlock() } if status >= 400 { @@ -69,8 +73,10 @@ func (h ErrorHandler) errorPage(w http.ResponseWriter, r *http.Request, code int errorPage, err := os.Open(pagePath) if err != nil { // An additional error handling an error... + h.fileMu.RLock() h.Log.Printf("%s [NOTICE %d %s] could not load error page: %v", time.Now().Format(timeFormat), code, r.URL.String(), err) + h.fileMu.RUnlock() httpserver.DefaultErrorFunc(w, r, code) return } @@ -83,8 +89,10 @@ func (h ErrorHandler) errorPage(w http.ResponseWriter, r *http.Request, code int if err != nil { // Epic fail... sigh. + h.fileMu.RLock() h.Log.Printf("%s [NOTICE %d %s] could not respond with %s: %v", time.Now().Format(timeFormat), code, r.URL.String(), pagePath, err) + h.fileMu.RUnlock() httpserver.DefaultErrorFunc(w, r, code) } @@ -146,7 +154,9 @@ func (h ErrorHandler) recovery(w http.ResponseWriter, r *http.Request) { 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.fileMu.RLock() h.Log.Printf(panicMsg) + h.fileMu.RUnlock() h.errorPage(w, r, http.StatusInternalServerError) } } diff --git a/caddyhttp/errors/errors_test.go b/caddyhttp/errors/errors_test.go index 2cd02dc6..2b160392 100644 --- a/caddyhttp/errors/errors_test.go +++ b/caddyhttp/errors/errors_test.go @@ -11,6 +11,7 @@ import ( "path/filepath" "strconv" "strings" + "sync" "testing" "github.com/mholt/caddy/caddyhttp/httpserver" @@ -32,7 +33,8 @@ func TestErrors(t *testing.T) { http.StatusNotFound: path, http.StatusForbidden: "not_exist_file", }, - Log: log.New(&buf, "", 0), + Log: log.New(&buf, "", 0), + fileMu: new(sync.RWMutex), } _, notExistErr := os.Open("not_exist_file") @@ -121,6 +123,7 @@ func TestVisibleErrorWithPanic(t *testing.T) { Next: httpserver.HandlerFunc(func(w http.ResponseWriter, r *http.Request) (int, error) { panic(panicMsg) }), + fileMu: new(sync.RWMutex), } req, err := http.NewRequest("GET", "/", nil) @@ -176,7 +179,8 @@ func TestGenericErrorPage(t *testing.T) { ErrorPages: map[int]string{ http.StatusNotFound: notFoundErrorPagePath, }, - Log: log.New(&buf, "", 0), + Log: log.New(&buf, "", 0), + fileMu: new(sync.RWMutex), } tests := []struct { diff --git a/caddyhttp/errors/setup.go b/caddyhttp/errors/setup.go index 3d643e52..db4177c2 100644 --- a/caddyhttp/errors/setup.go +++ b/caddyhttp/errors/setup.go @@ -6,6 +6,7 @@ import ( "os" "path/filepath" "strconv" + "sync" "github.com/hashicorp/go-syslog" "github.com/mholt/caddy" @@ -64,7 +65,9 @@ func setup(c *caddy.Controller) error { // When server stops, close any open log file c.OnShutdown(func() error { if handler.file != nil { + handler.fileMu.Lock() handler.file.Close() + handler.fileMu.Unlock() } return nil }) @@ -81,7 +84,7 @@ 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)} + handler := &ErrorHandler{ErrorPages: make(map[int]string), fileMu: new(sync.RWMutex)} cfg := httpserver.GetConfig(c) diff --git a/caddyhttp/errors/setup_test.go b/caddyhttp/errors/setup_test.go index 9aa861d5..f9e539c2 100644 --- a/caddyhttp/errors/setup_test.go +++ b/caddyhttp/errors/setup_test.go @@ -3,6 +3,7 @@ package errors import ( "path/filepath" "reflect" + "sync" "testing" "github.com/mholt/caddy" @@ -58,18 +59,22 @@ func TestErrorsParse(t *testing.T) { }{ {`errors`, false, ErrorHandler{ ErrorPages: map[int]string{}, + fileMu: new(sync.RWMutex), }}, {`errors errors.txt`, false, ErrorHandler{ ErrorPages: map[int]string{}, LogFile: "errors.txt", + fileMu: new(sync.RWMutex), }}, {`errors visible`, false, ErrorHandler{ ErrorPages: map[int]string{}, Debug: true, + fileMu: new(sync.RWMutex), }}, {`errors { log visible }`, false, ErrorHandler{ ErrorPages: map[int]string{}, Debug: true, + fileMu: new(sync.RWMutex), }}, {`errors { log errors.txt 404 404.html @@ -80,6 +85,7 @@ func TestErrorsParse(t *testing.T) { 404: "404.html", 500: "500.html", }, + fileMu: new(sync.RWMutex), }}, {`errors { log errors.txt { size 2 age 10 keep 3 } }`, false, ErrorHandler{ LogFile: "errors.txt", @@ -90,6 +96,7 @@ func TestErrorsParse(t *testing.T) { LocalTime: true, }, ErrorPages: map[int]string{}, + fileMu: new(sync.RWMutex), }}, {`errors { log errors.txt { size 3 @@ -110,6 +117,7 @@ func TestErrorsParse(t *testing.T) { MaxBackups: 5, LocalTime: true, }, + fileMu: new(sync.RWMutex), }}, {`errors { log errors.txt * generic_error.html @@ -122,6 +130,7 @@ func TestErrorsParse(t *testing.T) { 404: "404.html", 503: "503.html", }, + fileMu: new(sync.RWMutex), }}, // test absolute file path {`errors { @@ -131,16 +140,17 @@ func TestErrorsParse(t *testing.T) { ErrorPages: map[int]string{ 404: testAbs, }, + fileMu: new(sync.RWMutex), }}, // Next two test cases is the detection of duplicate status codes {`errors { 503 503.html 503 503.html -}`, true, ErrorHandler{ErrorPages: map[int]string{}}}, +}`, true, ErrorHandler{ErrorPages: map[int]string{}, fileMu: new(sync.RWMutex)}}, {`errors { * generic_error.html * generic_error.html -}`, true, ErrorHandler{ErrorPages: map[int]string{}}}, +}`, true, ErrorHandler{ErrorPages: map[int]string{}, fileMu: new(sync.RWMutex)}}, } for i, test := range tests { actualErrorsRule, err := errorsParse(caddy.NewTestController("http", test.inputErrorsRules))