add request logging middleware

api/server/authn/handler.go

@@ -144,7 +144,7 @@ func (authn *AuthN) nextWithUserID(w http.ResponseWriter, r *http.Request, userI
 	ctx := r.Context()
 	ctx = context.WithValue(ctx, types.UserScope, user)
 
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	authn.next.ServeHTTP(w, r)
 }
 

api/server/authz/cluster.go

@@ -61,7 +61,7 @@ func (p *ClusterScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Reque
 	}
 
 	ctx := NewClusterContext(r.Context(), cluster)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	p.next.ServeHTTP(w, r)
 }
 

api/server/authz/git_installation.go

@@ -56,7 +56,7 @@ func (p *GitInstallationScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *ht
 	}
 
 	ctx := NewGitInstallationContext(r.Context(), gitInstallation)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	p.next.ServeHTTP(w, r)
 }
 

api/server/authz/helm_repo.go

@@ -54,7 +54,7 @@ func (p *HelmRepoScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Requ
 	}
 
 	ctx := NewHelmRepoContext(r.Context(), helmRepo)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	p.next.ServeHTTP(w, r)
 }
 

api/server/authz/infra.go

@@ -54,7 +54,7 @@ func (p *InfraScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request
 	}
 
 	ctx := NewInfraContext(r.Context(), infra)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	p.next.ServeHTTP(w, r)
 }
 

api/server/authz/invite.go

@@ -54,7 +54,7 @@ func (p *InviteScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Reques
 	}
 
 	ctx := NewInviteContext(r.Context(), invite)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	p.next.ServeHTTP(w, r)
 }
 

api/server/authz/namespace.go

@@ -34,7 +34,7 @@ func (n *NamespaceScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Req
 	namespace := reqScopes[types.NamespaceScope].Resource.Name
 
 	ctx := NewNamespaceContext(r.Context(), namespace)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	n.next.ServeHTTP(w, r)
 }
 

api/server/authz/policy.go

@@ -74,7 +74,7 @@ func (h *PolicyHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 	// add the set of resource ids to the request context
 	ctx := NewRequestScopeCtx(r.Context(), reqScopes)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	h.next.ServeHTTP(w, r)
 }
 

api/server/authz/project.go

@@ -43,7 +43,7 @@ func (p *ProjectScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Reque
 	}
 
 	ctx := NewProjectContext(r.Context(), project)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	p.next.ServeHTTP(w, r)
 }
 

api/server/authz/registry.go

@@ -54,7 +54,7 @@ func (p *RegistryScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Requ
 	}
 
 	ctx := NewRegistryContext(r.Context(), registry)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	p.next.ServeHTTP(w, r)
 }
 

api/server/authz/release.go

@@ -57,7 +57,7 @@ func (p *ReleaseScopedMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Reque
 	}
 
 	ctx := NewReleaseContext(r.Context(), release)
-	r = r.WithContext(ctx)
+	r = r.Clone(ctx)
 	p.next.ServeHTTP(w, r)
 }
 

api/server/router/router.go

@@ -5,6 +5,7 @@ import (
 	"os"
 	"path"
 	"strings"
+	"time"
 
 	"github.com/go-chi/chi"
 	"github.com/porter-dev/porter/api/server/authn"
@@ -13,6 +14,7 @@ import (
 	"github.com/porter-dev/porter/api/server/shared"
 	"github.com/porter-dev/porter/api/server/shared/config"
 	"github.com/porter-dev/porter/api/types"
+	"github.com/porter-dev/porter/internal/logger"
 )
 
 func NewAPIRouter(config *config.Config) *chi.Mux {
@@ -45,10 +47,11 @@ func NewAPIRouter(config *config.Config) *chi.Mux {
 		projectOAuthRegisterer,
 		slackIntegrationRegisterer,
 	)
+
 	userRegisterer := NewUserScopedRegisterer(projRegisterer)
 
 	r.Route("/api", func(r chi.Router) {
-		// set the content type for all API endpoints
+		// set the content type for all API endpoints and log all request info
 		r.Use(ContentTypeJSON)
 
 		baseRoutes := baseRegisterer.GetRoutes(
@@ -177,6 +180,9 @@ func registerRoutes(config *config.Config, routes []*Route) {
 	// Policy doc loader loads the policy documents for a specific project.
 	policyDocLoader := policy.NewBasicPolicyDocumentLoader(config.Repo.Project())
 
+	// set up logging middleware to log information about the request
+	loggerMw := &RequestLoggerMiddleware{config.Logger}
+
 	for _, route := range routes {
 		atomicGroup := route.Router.Group(nil)
 
@@ -213,6 +219,8 @@ func registerRoutes(config *config.Config, routes []*Route) {
 			}
 		}
 
+		atomicGroup.Use(loggerMw.Middleware)
+
 		atomicGroup.Method(
 			string(route.Endpoint.Metadata.Method),
 			route.Endpoint.Metadata.Path.RelativePath,
@@ -228,3 +236,39 @@ func ContentTypeJSON(next http.Handler) http.Handler {
 		next.ServeHTTP(w, r)
 	})
 }
+
+type requestLoggerResponseWriter struct {
+	http.ResponseWriter
+	statusCode int
+}
+
+func newRequestLoggerResponseWriter(w http.ResponseWriter) *requestLoggerResponseWriter {
+	return &requestLoggerResponseWriter{w, http.StatusOK}
+}
+
+func (rw *requestLoggerResponseWriter) WriteHeader(code int) {
+	rw.statusCode = code
+	rw.ResponseWriter.WriteHeader(code)
+}
+
+type RequestLoggerMiddleware struct {
+	logger *logger.Logger
+}
+
+func (mw *RequestLoggerMiddleware) Middleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		start := time.Now()
+		rw := newRequestLoggerResponseWriter(w)
+
+		next.ServeHTTP(rw, r)
+
+		latency := time.Since(start)
+
+		event := mw.logger.Info().Dur("latency", latency).Int("status", rw.statusCode)
+
+		logger.AddLoggingContextScopes(r.Context(), event)
+		logger.AddLoggingRequestMeta(r, event)
+
+		event.Send()
+	})
+}

api/server/shared/apierrors/errors.go

@@ -1,14 +1,12 @@
 package apierrors
 
 import (
-	"context"
 	"encoding/json"
 	"net/http"
 
 	"github.com/porter-dev/porter/api/server/shared/config"
 	"github.com/porter-dev/porter/api/types"
-	"github.com/porter-dev/porter/internal/models"
-	"github.com/rs/zerolog"
+	"github.com/porter-dev/porter/internal/logger"
 )
 
 type RequestError interface {
@@ -105,8 +103,8 @@ func HandleAPIError(
 		Str("internal_error", err.InternalError()).
 		Str("external_error", extErrorStr)
 
-	data := addLoggingScopes(r.Context(), event)
-	addLoggingRequestMeta(r, event)
+	data := logger.AddLoggingContextScopes(r.Context(), event)
+	logger.AddLoggingRequestMeta(r, event)
 
 	event.Send()
 
@@ -132,47 +130,11 @@ func HandleAPIError(
 		event := config.Logger.Error().
 			Err(writerErr)
 
-		addLoggingScopes(r.Context(), event)
-		addLoggingRequestMeta(r, event)
+		logger.AddLoggingContextScopes(r.Context(), event)
+		logger.AddLoggingRequestMeta(r, event)
 
 		event.Send()
 	}
 
 	return
 }
-
-func addLoggingScopes(ctx context.Context, event *zerolog.Event) map[string]interface{} {
-	res := make(map[string]interface{})
-
-	// case on the context values that exist, add them to event
-	if userVal := ctx.Value(types.UserScope); userVal != nil {
-		if userModel, ok := userVal.(*models.User); ok {
-			event.Uint("user_id", userModel.ID)
-			res["user_id"] = userModel.ID
-		}
-	}
-
-	// if this is a project-scoped route, add various scopes
-	if reqScopesVal := ctx.Value(types.RequestScopeCtxKey); reqScopesVal != nil {
-		if reqScopes, ok := reqScopesVal.(map[types.PermissionScope]*types.RequestAction); ok {
-			for key, scope := range reqScopes {
-				if scope.Resource.Name != "" {
-					event.Str(string(key), scope.Resource.Name)
-					res[string(key)] = scope.Resource.Name
-				}
-
-				if scope.Resource.UInt != 0 {
-					event.Uint(string(key), scope.Resource.UInt)
-					res[string(key)] = scope.Resource.UInt
-				}
-			}
-		}
-	}
-
-	return res
-}
-
-func addLoggingRequestMeta(r *http.Request, event *zerolog.Event) {
-	event.Str("method", r.Method)
-	event.Str("url", r.URL.String())
-}

docs/developing/backend-refactor.md

@@ -40,7 +40,7 @@ project, _ := p.config.Repo.Project().ReadProject(projID)
 
 // add the project to the request context
 ctx := NewProjectContext(r.Context(), project)
-r = r.WithContext(ctx)
+r = r.Clone(ctx)
 
 // call the next handler
 p.next.ServeHTTP(w, r)

internal/logger/logger.go

@@ -3,8 +3,11 @@ package logger
 import (
 	"context"
 	"io"
+	"net/http"
 	"os"
 
+	"github.com/porter-dev/porter/api/types"
+	"github.com/porter-dev/porter/internal/models"
 	"github.com/rs/zerolog"
 )
 
@@ -137,3 +140,39 @@ func (l *Logger) Printf(format string, v ...interface{}) {
 func (l *Logger) Ctx(ctx context.Context) *Logger {
 	return &Logger{logger: zerolog.Ctx(ctx)}
 }
+
+func AddLoggingContextScopes(ctx context.Context, event *zerolog.Event) map[string]interface{} {
+	res := make(map[string]interface{})
+
+	// case on the context values that exist, add them to event
+	if userVal := ctx.Value(types.UserScope); userVal != nil {
+		if userModel, ok := userVal.(*models.User); ok {
+			event.Uint("user_id", userModel.ID)
+			res["user_id"] = userModel.ID
+		}
+	}
+
+	// if this is a project-scoped route, add various scopes
+	if reqScopesVal := ctx.Value(types.RequestScopeCtxKey); reqScopesVal != nil {
+		if reqScopes, ok := reqScopesVal.(map[types.PermissionScope]*types.RequestAction); ok {
+			for key, scope := range reqScopes {
+				if scope.Resource.Name != "" {
+					event.Str(string(key), scope.Resource.Name)
+					res[string(key)] = scope.Resource.Name
+				}
+
+				if scope.Resource.UInt != 0 {
+					event.Uint(string(key), scope.Resource.UInt)
+					res[string(key)] = scope.Resource.UInt
+				}
+			}
+		}
+	}
+
+	return res
+}
+
+func AddLoggingRequestMeta(r *http.Request, event *zerolog.Event) {
+	event.Str("method", r.Method)
+	event.Str("url", r.URL.String())
+}