Logging improvements, handler extraction.

- rest: improve error logging.
- web: extract handlers/middleware into their own file.
- web: log all requests, not just ones hitting our handlers.
- test: improve integration test logging format.

pkg/rest/client/rest.go

@@ -33,7 +33,7 @@ func (c *restClient) do(method, uri string, body []byte) (*http.Response, error)
 	}
 	req, err := http.NewRequest(method, url.String(), r)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("%s for %q: %v", method, url, err)
 	}
 	return c.client.Do(req)
 }
@@ -56,7 +56,7 @@ func (c *restClient) doJSON(method string, uri string, v interface{}) error {
 		return json.NewDecoder(resp.Body).Decode(v)
 	}
 
-	return fmt.Errorf("Unexpected HTTP response status %v: %s", resp.StatusCode, resp.Status)
+	return fmt.Errorf("%s for %q, unexpected %v: %s", method, uri, resp.StatusCode, resp.Status)
 }
 
 // doJSONBody performs an HTTP request with this client and marshalls the JSON response into v.
@@ -77,5 +77,5 @@ func (c *restClient) doJSONBody(method string, uri string, body []byte, v interf
 		return json.NewDecoder(resp.Body).Decode(v)
 	}
 
-	return fmt.Errorf("Unexpected HTTP response status %v: %s", resp.StatusCode, resp.Status)
+	return fmt.Errorf("%s for %q, unexpected %v: %s", method, uri, resp.StatusCode, resp.Status)
 }

pkg/server/web/handlers.go

@@ -0,0 +1,50 @@
+package web
+
+import (
+	"net/http"
+
+	"github.com/rs/zerolog/log"
+)
+
+// Handler is a function type that handles an HTTP request in Inbucket.
+type Handler func(http.ResponseWriter, *http.Request, *Context) error
+
+// ServeHTTP builds the context and passes onto the real handler.
+func (h Handler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
+	// Create the context.
+	ctx, err := NewContext(req)
+	if err != nil {
+		log.Error().Str("module", "web").Err(err).Msg("HTTP failed to create context")
+		http.Error(w, err.Error(), http.StatusInternalServerError)
+		return
+	}
+	defer ctx.Close()
+
+	// Run the handler, grab the error, and report it.
+	err = h(w, req, ctx)
+	if err != nil {
+		log.Error().Str("module", "web").Str("path", req.RequestURI).Err(err).
+			Msg("Error handling request")
+		http.Error(w, err.Error(), http.StatusInternalServerError)
+		return
+	}
+}
+
+// noMatchHandler creates a handler to log requests that Gorilla mux is unable to route,
+// returning specified statusCode to the client.
+func noMatchHandler(statusCode int, message string) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		log.Warn().Str("module", "web").Str("remote", req.RemoteAddr).Str("proto", req.Proto).
+			Str("method", req.Method).Str("path", req.RequestURI).Msg(message)
+		w.WriteHeader(statusCode)
+	})
+}
+
+// requestLoggingWrapper returns middleware that logs client requests.
+func requestLoggingWrapper(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		log.Debug().Str("module", "web").Str("remote", req.RemoteAddr).Str("proto", req.Proto).
+			Str("method", req.Method).Str("path", req.RequestURI).Msg("Request")
+		next.ServeHTTP(w, req)
+	})
+}

pkg/server/web/server.go

@@ -18,9 +18,6 @@ import (
 	"github.com/rs/zerolog/log"
 )
 
-// Handler is a function type that handles an HTTP request in Inbucket
-type Handler func(http.ResponseWriter, *http.Request, *Context) error
-
 const (
 	staticDir   = "static"
 	templateDir = "templates"
@@ -79,6 +76,9 @@ func Initialize(
 	}
 	// If no other route matches, attempt to service as UI element.
 	Router.PathPrefix("/").Handler(http.StripPrefix("/", http.FileServer(http.Dir(conf.Web.UIDir))))
+	Router.NotFoundHandler = noMatchHandler(http.StatusNotFound, "No route matches URI path")
+	Router.MethodNotAllowedHandler = noMatchHandler(http.StatusMethodNotAllowed,
+		"Method not allowed for URI path")
 
 	// Session cookie setup
 	if conf.Web.CookieAuthKey == "" {
@@ -96,7 +96,7 @@ func Initialize(
 func Start(ctx context.Context) {
 	server = &http.Server{
 		Addr:         rootConfig.Web.Addr,
-		Handler:      Router,
+		Handler:      requestLoggingWrapper(Router),
 		ReadTimeout:  60 * time.Second,
 		WriteTimeout: 60 * time.Second,
 	}
@@ -146,29 +146,6 @@ func serve(ctx context.Context) {
 	}
 }
 
-// ServeHTTP builds the context and passes onto the real handler
-func (h Handler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
-	// Create the context
-	ctx, err := NewContext(req)
-	if err != nil {
-		log.Error().Str("module", "web").Err(err).Msg("HTTP failed to create context")
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
-	defer ctx.Close()
-
-	// Run the handler, grab the error, and report it
-	log.Debug().Str("module", "web").Str("remote", req.RemoteAddr).Str("proto", req.Proto).
-		Str("method", req.Method).Str("path", req.RequestURI).Msg("Request")
-	err = h(w, req, ctx)
-	if err != nil {
-		log.Error().Str("module", "web").Str("path", req.RequestURI).Err(err).
-			Msg("Error handling request")
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
-}
-
 func emergencyShutdown() {
 	// Shutdown Inbucket
 	select {

pkg/test/integration_test.go

@@ -23,6 +23,8 @@ import (
 	"github.com/jhillyerd/inbucket/pkg/storage"
 	"github.com/jhillyerd/inbucket/pkg/storage/mem"
 	"github.com/jhillyerd/inbucket/pkg/webui"
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
 )
 
 const (
@@ -151,6 +153,7 @@ func formatMessage(m *client.Message) []byte {
 
 func startServer() (func(), error) {
 	// TODO Refactor inbucket/main.go so we don't need to repeat all this here.
+	log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, NoColor: true})
 	storage.Constructors["memory"] = mem.New
 	os.Clearenv()
 	conf, err := config.Process()