WIP: Logging

bootstrap/api.go

@@ -29,7 +29,7 @@ func (b *Bootstrap) startJobAPI() (cleanup func(), err error) {
 		return cleanup, fmt.Errorf("creating job API socket path: %v", err)
 	}
 
-	srv, token, err := jobapi.NewServer(socketPath, b.shell.Env)
+	srv, token, err := jobapi.NewServer(b.shell.Logger, socketPath, b.shell.Env)
 	if err != nil {
 		return cleanup, fmt.Errorf("creating job API server: %v", err)
 	}
@@ -45,8 +45,6 @@ func (b *Bootstrap) startJobAPI() (cleanup func(), err error) {
 		err = srv.Stop()
 		if err != nil {
 			b.shell.Errorf("Error stopping Job API server: %v", err)
-		} else {
-			b.shell.Commentf("Stopped Job API server")
 		}
 	}, nil
 }

jobapi/middleware.go

@@ -4,8 +4,23 @@ import (
 	"errors"
 	"net/http"
 	"strings"
+	"time"
+
+	"github.com/buildkite/agent/v3/bootstrap/shell"
+	"github.com/go-chi/chi/v5/middleware"
 )
 
+func LoggerMiddleware(l shell.Logger) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			t := time.Now()
+			ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+			defer l.Commentf("Job API:\t%s\t%s\t%s (%d) (⬇%d)", r.Method, r.URL.Path, time.Since(t), ww.Status(), ww.BytesWritten())
+			next.ServeHTTP(ww, r)
+		})
+	}
+}
+
 // AuthMiddleware is a middleware that checks the Authorization header of an incoming request for a Bearer token
 // and checks that that token is the correct one.
 func AuthMiddleware(token string) func(http.Handler) http.Handler {
@@ -40,12 +55,10 @@ func AuthMiddleware(token string) func(http.Handler) http.Handler {
 
 // HeadersMiddleware is a middleware that sets the common headers for all responses. At the moment, this is just
 // Content-Type: application/json.
-func HeadersMiddleware() func(http.Handler) http.Handler {
-	return func(next http.Handler) http.Handler {
-		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			defer next.ServeHTTP(w, r)
+func HeadersMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		defer next.ServeHTTP(w, r)
 
-			w.Header().Set("Content-Type", "application/json")
-		})
-	}
+		w.Header().Set("Content-Type", "application/json")
+	})
 }

jobapi/routes.go

@@ -15,9 +15,10 @@ import (
 func (s *Server) router() chi.Router {
 	r := chi.NewRouter()
 	r.Use(
+		// middleware.Logger,
+		LoggerMiddleware(s.Logger),
 		middleware.Recoverer,
-		// middleware.Logger, // REVIEW: Should we log requests to this API? If so, where should we log them to? The job logs?
-		HeadersMiddleware(),
+		HeadersMiddleware,
 		AuthMiddleware(s.token),
 	)
 

jobapi/server.go

@@ -14,6 +14,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/buildkite/agent/v3/bootstrap/shell"
 	"github.com/buildkite/agent/v3/env"
 )
 
@@ -22,6 +23,7 @@ import (
 type Server struct {
 	// SocketPath is the path to the socket that the server is (or will be) listening on
 	SocketPath string
+	Logger     shell.Logger
 
 	environ env.Environment
 	token   string
@@ -33,7 +35,7 @@ type Server struct {
 // NewServer creates a new Job API server
 // socketPath is the path to the socket on which the server will listen
 // environ is the environment which the server will mutate and inspect as part of its operation
-func NewServer(socketPath string, environ env.Environment) (server *Server, token string, err error) {
+func NewServer(logger shell.Logger, socketPath string, environ env.Environment) (server *Server, token string, err error) {
 	if len(socketPath) >= socketPathLength() {
 		return nil, "", fmt.Errorf("socket path %s is too long (path length: %d, max %d characters). This is a limitation of your host OS", socketPath, len(socketPath), socketPathLength())
 	}
@@ -54,6 +56,7 @@ func NewServer(socketPath string, environ env.Environment) (server *Server, toke
 
 	return &Server{
 		SocketPath: socketPath,
+		Logger:     logger,
 		environ:    environ,
 		token:      token,
 	}, token, nil
@@ -77,6 +80,8 @@ func (s *Server) Start() error {
 	}()
 	s.started = true
 
+	s.Logger.Commentf("Job API server listening on %s", s.SocketPath)
+
 	return nil
 }
 
@@ -96,7 +101,7 @@ func (s *Server) Stop() error {
 	go func() {
 		<-shutdownCtx.Done()
 		if shutdownCtx.Err() == context.DeadlineExceeded {
-			// What should we do in this situation? Force a return? Log something?
+			s.Logger.Warningf("Job API server shutdown timed out, forcing server shutdown")
 		}
 	}()
 
@@ -106,6 +111,8 @@ func (s *Server) Stop() error {
 		return fmt.Errorf("shutting down Job API server: %w", err)
 	}
 
+	s.Logger.Commentf("Successfully shut down Job API server")
+
 	return nil
 }