trace ids

cmd/milmove/main.go

@@ -591,6 +591,8 @@ func serveFunction(cmd *cobra.Command, args []string) error {
 
 	root := goji.NewMux()
 	root.Use(middleware.Recovery(logger))
+	root.Use(middleware.Trace(logger))                             // injects http request trace id
+	root.Use(middleware.ContextLogger("milmove_trace_id", logger)) // injects http request logger
 	root.Use(sessionCookieMiddleware)
 	root.Use(middleware.RequestLogger(logger))
 

pkg/auth/authentication/client_cert.go

@@ -23,7 +23,12 @@ func SetClientCertInRequestContext(r *http.Request, clientCert *models.ClientCer
 
 // ClientCertFromRequestContext gets the reference to the ClientCert stored in the request.Context()
 func ClientCertFromRequestContext(r *http.Request) *models.ClientCert {
-	if clientCert, ok := r.Context().Value(clientCertContextKey).(*models.ClientCert); ok {
+	return ClientCertFromContext(r.Context())
+}
+
+// ClientCertFromContext gets the reference to the ClientCert stored in the request.Context()
+func ClientCertFromContext(ctx context.Context) *models.ClientCert {
+	if clientCert, ok := ctx.Value(clientCertContextKey).(*models.ClientCert); ok {
 		return clientCert
 	}
 	return nil

pkg/auth/cookie.go

@@ -12,6 +12,8 @@ import (
 	beeline "github.com/honeycombio/beeline-go"
 	"github.com/pkg/errors"
 	"go.uber.org/zap"
+
+	"github.com/transcom/mymove/pkg/logging"
 )
 
 // ApplicationServername is a collection of all the servernames for the application
@@ -234,15 +236,25 @@ func ApplicationName(hostname string, appnames ApplicationServername) (Applicati
 }
 
 // SessionCookieMiddleware handle serializing and de-serializing the session between the user_session cookie and the request context
-func SessionCookieMiddleware(logger Logger, secret string, noSessionTimeout bool, appnames ApplicationServername, useSecureCookie bool) func(next http.Handler) http.Handler {
-	logger.Info("Creating session",
+func SessionCookieMiddleware(serverLogger Logger, secret string, noSessionTimeout bool, appnames ApplicationServername, useSecureCookie bool) func(next http.Handler) http.Handler {
+	serverLogger.Info("Creating session",
 		zap.String("milServername", appnames.MilServername),
 		zap.String("officeServername", appnames.OfficeServername),
 		zap.String("tspServername", appnames.TspServername),
 		zap.String("adminServername", appnames.AdminServername))
 	return func(next http.Handler) http.Handler {
-		mw := func(w http.ResponseWriter, r *http.Request) {
-			ctx, span := beeline.StartSpan(r.Context(), "SessionCookieMiddleware")
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+
+			ctx := r.Context()
+
+			var logger Logger
+			if requestLogger, ok := logging.FromContext(ctx).(Logger); ok {
+				logger = requestLogger
+			} else {
+				logger = serverLogger
+			}
+
+			ctx, span := beeline.StartSpan(ctx, "SessionCookieMiddleware")
 			defer span.Send()
 
 			// Set up the new session object
@@ -265,18 +277,15 @@ func SessionCookieMiddleware(logger Logger, secret string, noSessionTimeout bool
 			session.ApplicationName = appName
 			session.Hostname = strings.ToLower(hostname)
 
-			// And put the session info into the request context
-			ctx = SetSessionInRequestContext(r.WithContext(ctx), &session)
-
 			// And update the cookie. May get over-ridden later
 			WriteSessionCookie(w, &session, secret, noSessionTimeout, logger, useSecureCookie)
 
 			span.AddTraceField("auth.application_name", session.ApplicationName)
 			span.AddTraceField("auth.hostname", session.Hostname)
 
-			next.ServeHTTP(w, r.WithContext(ctx))
+			// And put the session info into the request context
+			next.ServeHTTP(w, r.WithContext(SetSessionInContext(ctx, &session)))
 
-		}
-		return http.HandlerFunc(mw)
+		})
 	}
 }

pkg/auth/session.go

@@ -67,9 +67,19 @@ func SetSessionInRequestContext(r *http.Request, session *Session) context.Conte
 	return context.WithValue(r.Context(), sessionContextKey, session)
 }
 
+// SetSessionInContext modifies the context to add the session data.
+func SetSessionInContext(ctx context.Context, session *Session) context.Context {
+	return context.WithValue(ctx, sessionContextKey, session)
+}
+
 // SessionFromRequestContext gets the reference to the Session stored in the request.Context()
 func SessionFromRequestContext(r *http.Request) *Session {
-	if session, ok := r.Context().Value(sessionContextKey).(*Session); ok {
+	return SessionFromContext(r.Context())
+}
+
+// SessionFromContext gets the reference to the Session stored in the request.Context()
+func SessionFromContext(ctx context.Context) *Session {
+	if session, ok := ctx.Value(sessionContextKey).(*Session); ok {
 		return session
 	}
 	return nil

pkg/handlers/contexts.go

@@ -2,15 +2,18 @@ package handlers
 
 import (
 	"context"
+	"net/http"
 
 	"github.com/go-openapi/runtime/middleware"
 	"github.com/gobuffalo/pop"
 	"github.com/gobuffalo/validate"
 	"go.uber.org/zap"
 
+	"github.com/transcom/mymove/pkg/auth"
 	"github.com/transcom/mymove/pkg/db/sequence"
 	"github.com/transcom/mymove/pkg/dpsauth"
 	"github.com/transcom/mymove/pkg/iws"
+	"github.com/transcom/mymove/pkg/logging"
 	"github.com/transcom/mymove/pkg/logging/hnyzap"
 	"github.com/transcom/mymove/pkg/notifications"
 	"github.com/transcom/mymove/pkg/route"
@@ -21,7 +24,12 @@ import (
 // HandlerContext provides access to all the contextual references needed by individual handlers
 type HandlerContext interface {
 	DB() *pop.Connection
-	Logger() Logger
+	SessionAndLoggerFromContext(ctx context.Context) (*auth.Session, Logger)
+	SessionAndLoggerFromRequest(r *http.Request) (*auth.Session, Logger)
+	SessionFromRequest(r *http.Request) *auth.Session
+	SessionFromContext(ctx context.Context) *auth.Session
+	LoggerFromContext(ctx context.Context) Logger
+	LoggerFromRequest(r *http.Request) Logger
 	HoneyZapLogger() *hnyzap.Logger
 	FileStorer() storage.FileStorer
 	SetFileStorer(storer storage.FileStorer)
@@ -75,16 +83,38 @@ func NewHandlerContext(db *pop.Connection, logger Logger) HandlerContext {
 	}
 }
 
-// DB returns a POP db connection for the context
-func (hctx *handlerContext) DB() *pop.Connection {
-	return hctx.db
+func (hctx *handlerContext) SessionAndLoggerFromRequest(r *http.Request) (*auth.Session, Logger) {
+	return hctx.SessionAndLoggerFromContext(r.Context())
+}
+
+func (hctx *handlerContext) SessionAndLoggerFromContext(ctx context.Context) (*auth.Session, Logger) {
+	return auth.SessionFromContext(ctx), hctx.LoggerFromContext(ctx)
+}
+
+func (hctx *handlerContext) SessionFromRequest(r *http.Request) *auth.Session {
+	return auth.SessionFromContext(r.Context())
+}
+
+func (hctx *handlerContext) SessionFromContext(ctx context.Context) *auth.Session {
+	return auth.SessionFromContext(ctx)
 }
 
-// Logger returns the logger to use in this context
-func (hctx *handlerContext) Logger() Logger {
+func (hctx *handlerContext) LoggerFromRequest(r *http.Request) Logger {
+	return hctx.LoggerFromContext(r.Context())
+}
+
+func (hctx *handlerContext) LoggerFromContext(ctx context.Context) Logger {
+	if logger, ok := logging.FromContext(ctx).(Logger); ok {
+		return logger
+	}
 	return hctx.logger
 }
 
+// DB returns a POP db connection for the context
+func (hctx *handlerContext) DB() *pop.Connection {
+	return hctx.db
+}
+
 // HoneyZapLogger returns the logger capable of writing to Honeycomb to use in this context
 func (hctx *handlerContext) HoneyZapLogger() *hnyzap.Logger {
 	if zapLogger, ok := hctx.logger.(*zap.Logger); ok {
@@ -96,13 +126,13 @@ func (hctx *handlerContext) HoneyZapLogger() *hnyzap.Logger {
 // RespondAndTraceError uses Honeycomb to trace errors and then passes response to the standard ResponseForError
 func (hctx *handlerContext) RespondAndTraceError(ctx context.Context, err error, msg string, fields ...zap.Field) middleware.Responder {
 	hctx.HoneyZapLogger().TraceError(ctx, msg, fields...)
-	return ResponseForError(hctx.Logger(), err)
+	return ResponseForError(hctx.LoggerFromContext(ctx), err)
 }
 
 // RespondAndTraceVErrors uses Honeycomb to trace errors and then passes response to the standard ResponseForVErrors
 func (hctx *handlerContext) RespondAndTraceVErrors(ctx context.Context, verrs *validate.Errors, err error, msg string, fields ...zap.Field) middleware.Responder {
 	hctx.HoneyZapLogger().TraceError(ctx, msg, fields...)
-	return ResponseForVErrors(hctx.Logger(), verrs, err)
+	return ResponseForVErrors(hctx.LoggerFromContext(ctx), verrs, err)
 }
 
 // FileStorer returns the storage to use in the current context

pkg/handlers/dpsapi/authentication.go

@@ -34,17 +34,22 @@ var affiliationMap = map[models.ServiceMemberAffiliation]dpsmessages.Affiliation
 
 // Handle returns user information given an encrypted token
 func (h GetUserHandler) Handle(params dps.GetUserParams) middleware.Responder {
-	clientCert := authentication.ClientCertFromRequestContext(params.HTTPRequest)
+
+	ctx := params.HTTPRequest.Context()
+
+	logger := h.LoggerFromContext(ctx)
+
+	clientCert := authentication.ClientCertFromContext(ctx)
 	if clientCert == nil || !clientCert.AllowDpsAuthAPI {
-		h.Logger().Info("Client certificate is not authorized to access this API")
+		logger.Info("Client certificate is not authorized to access this API")
 		return dps.NewGetUserUnauthorized()
 	}
 
 	dpsParams := h.DPSAuthParams()
 	token := params.Token
 	loginGovID, err := dpsauth.CookieToLoginGovID(token, dpsParams.CookieSecret)
 	if err != nil {
-		h.Logger().Error("Extracting user ID from token", zap.Error(err))
+		logger.Error("Extracting user ID from token", zap.Error(err))
 
 		switch err.(type) {
 		case *dpsauth.ErrInvalidCookie:
@@ -57,9 +62,9 @@ func (h GetUserHandler) Handle(params dps.GetUserParams) middleware.Responder {
 	if err != nil {
 		switch e := err.(type) {
 		case *errUserMissingData:
-			h.Logger().Error("Fetching user data from user ID", zap.Error(err), zap.String("user", e.userID.String()))
+			logger.Error("Fetching user data from user ID", zap.Error(err), zap.String("user", e.userID.String()))
 		default:
-			h.Logger().Error("Fetching user data from user ID", zap.Error(err))
+			logger.Error("Fetching user data from user ID", zap.Error(err))
 		}
 
 		return dps.NewGetUserInternalServerError()

pkg/handlers/internalapi/backup_contacts.go

@@ -7,7 +7,6 @@ import (
 	"github.com/gofrs/uuid"
 	"github.com/honeycombio/beeline-go"
 
-	"github.com/transcom/mymove/pkg/auth"
 	backupop "github.com/transcom/mymove/pkg/gen/internalapi/internaloperations/backup_contacts"
 	"github.com/transcom/mymove/pkg/gen/internalmessages"
 	"github.com/transcom/mymove/pkg/handlers"
@@ -35,16 +34,19 @@ type CreateBackupContactHandler struct {
 
 // Handle ... creates a new BackupContact from a request payload
 func (h CreateBackupContactHandler) Handle(params backupop.CreateServiceMemberBackupContactParams) middleware.Responder {
-	ctx, span := beeline.StartSpan(params.HTTPRequest.Context(), reflect.TypeOf(h).Name())
+
+	ctx := params.HTTPRequest.Context()
+
+	ctx, span := beeline.StartSpan(ctx, reflect.TypeOf(h).Name())
 	defer span.Send()
 
 	// User should always be populated by middleware
-	session := auth.SessionFromRequestContext(params.HTTPRequest)
+	session, logger := h.SessionAndLoggerFromContext(ctx)
 	/* #nosec UUID is pattern matched by swagger which checks the format */
 	serviceMemberID, _ := uuid.FromString(params.ServiceMemberID.String())
 	serviceMember, err := models.FetchServiceMemberForUser(ctx, h.DB(), session, serviceMemberID)
 	if err != nil {
-		return handlers.ResponseForError(h.Logger(), err)
+		return handlers.ResponseForError(logger, err)
 	}
 
 	newContact, verrs, err := serviceMember.CreateBackupContact(h.DB(),
@@ -53,7 +55,7 @@ func (h CreateBackupContactHandler) Handle(params backupop.CreateServiceMemberBa
 		params.CreateBackupContactPayload.Telephone,
 		models.BackupContactPermission(params.CreateBackupContactPayload.Permission))
 	if err != nil || verrs.HasAny() {
-		return handlers.ResponseForVErrors(h.Logger(), verrs, err)
+		return handlers.ResponseForVErrors(logger, verrs, err)
 	}
 
 	contactPayload := payloadForBackupContactModel(newContact)
@@ -70,13 +72,13 @@ func (h IndexBackupContactsHandler) Handle(params backupop.IndexServiceMemberBac
 	ctx, span := beeline.StartSpan(params.HTTPRequest.Context(), reflect.TypeOf(h).Name())
 	defer span.Send()
 
-	session := auth.SessionFromRequestContext(params.HTTPRequest)
+	session, logger := h.SessionAndLoggerFromRequest(params.HTTPRequest)
 
 	/* #nosec UUID is pattern matched by swagger which checks the format */
 	serviceMemberID, _ := uuid.FromString(params.ServiceMemberID.String())
 	serviceMember, err := models.FetchServiceMemberForUser(ctx, h.DB(), session, serviceMemberID)
 	if err != nil {
-		return handlers.ResponseForError(h.Logger(), err)
+		return handlers.ResponseForError(logger, err)
 	}
 
 	contacts := serviceMember.BackupContacts
@@ -98,12 +100,12 @@ type ShowBackupContactHandler struct {
 // Handle retrieves a backup contact in the system belonging to the logged in user given backup contact ID
 func (h ShowBackupContactHandler) Handle(params backupop.ShowServiceMemberBackupContactParams) middleware.Responder {
 	// User should always be populated by middleware
-	session := auth.SessionFromRequestContext(params.HTTPRequest)
+	session, logger := h.SessionAndLoggerFromRequest(params.HTTPRequest)
 	/* #nosec UUID is pattern matched by swagger which checks the format */
 	contactID, _ := uuid.FromString(params.BackupContactID.String())
 	contact, err := models.FetchBackupContact(h.DB(), session, contactID)
 	if err != nil {
-		return handlers.ResponseForError(h.Logger(), err)
+		return handlers.ResponseForError(logger, err)
 	}
 
 	contactPayload := payloadForBackupContactModel(contact)
@@ -118,12 +120,12 @@ type UpdateBackupContactHandler struct {
 // Handle ... updates a BackupContact from a request payload
 func (h UpdateBackupContactHandler) Handle(params backupop.UpdateServiceMemberBackupContactParams) middleware.Responder {
 	// User should always be populated by middleware
-	session := auth.SessionFromRequestContext(params.HTTPRequest)
+	session, logger := h.SessionAndLoggerFromRequest(params.HTTPRequest)
 	/* #nosec UUID is pattern matched by swagger which checks the format */
 	contactID, _ := uuid.FromString(params.BackupContactID.String())
 	contact, err := models.FetchBackupContact(h.DB(), session, contactID)
 	if err != nil {
-		return handlers.ResponseForError(h.Logger(), err)
+		return handlers.ResponseForError(logger, err)
 	}
 
 	contact.Name = *params.UpdateServiceMemberBackupContactPayload.Name
@@ -132,7 +134,7 @@ func (h UpdateBackupContactHandler) Handle(params backupop.UpdateServiceMemberBa
 	contact.Permission = models.BackupContactPermission(params.UpdateServiceMemberBackupContactPayload.Permission)
 
 	if verrs, err := h.DB().ValidateAndUpdate(&contact); verrs.HasAny() || err != nil {
-		return handlers.ResponseForVErrors(h.Logger(), verrs, err)
+		return handlers.ResponseForVErrors(logger, verrs, err)
 	}
 
 	contactPayload := payloadForBackupContactModel(contact)