add log/logger and NewCtxLogger

log/logger.go

@@ -0,0 +1,88 @@
+package log
+
+import (
+	"context"
+	"fmt"
+	"net/http"
+	"os"
+	"time"
+
+	"github.com/CMSgov/bcda-ssas-app/ssas/constants"
+	"github.com/sirupsen/logrus"
+)
+
+// Logger provides a structured logger for this service
+var Logger logrus.FieldLogger
+
+// Event contains the superset of fields that may be included in Logger statements
+type Event struct {
+	UserID     string
+	ClientID   string
+	Elapsed    time.Duration
+	Help       string
+	Op         string
+	TokenID    string
+	TrackingID string
+}
+
+func init() {
+	logInstance := logrus.New()
+	logInstance.SetFormatter(&logrus.JSONFormatter{TimestampFormat: time.RFC3339Nano})
+
+	filePath, success := os.LookupEnv("SSAS_LOG")
+	if success {
+		/* #nosec -- 0664 permissions required for Splunk ingestion */
+		file, err := os.OpenFile(filePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0664)
+
+		if err == nil {
+			logInstance.SetOutput(file)
+		} else {
+			logInstance.Info("Failed to open SSAS log file; using default stderr")
+		}
+	} else {
+		logInstance.Info("No SSAS log location provided; using default stderr")
+	}
+
+	Logger = logInstance.WithFields(logrus.Fields{
+		"application": constants.Application,
+		"environment": os.Getenv("DEPLOYMENT_TARGET"),
+		"version":     constants.Version})
+}
+
+type APILoggerEntry struct {
+	Logger logrus.FieldLogger
+}
+
+func (l *APILoggerEntry) Write(status int, bytes int, header http.Header, elapsed time.Duration, extra interface{}) {
+	l.Logger = l.Logger.WithFields(logrus.Fields{
+		"resp_status": status, "resp_bytes_length": bytes,
+		"resp_elapsed_ms": float64(elapsed.Nanoseconds()) / 1000000.0,
+	})
+
+	l.Logger.Infoln("request complete")
+}
+
+func (l *APILoggerEntry) Panic(v interface{}, stack []byte) {
+	l.Logger = l.Logger.WithFields(logrus.Fields{
+		"stack": string(stack),
+		"panic": fmt.Sprintf("%+v", v),
+	})
+}
+
+// type to create context.Context key
+type CtxLoggerKeyType string
+
+// context.Context key to set/get logrus.FieldLogger value within request context
+const CtxLoggerKey CtxLoggerKeyType = "ctxLogger"
+
+// Gets the logrus.FieldLogger from a context
+func GetCtxLogger(ctx context.Context) logrus.FieldLogger {
+	entry := ctx.Value(CtxLoggerKey).(*APILoggerEntry)
+	return entry.Logger
+}
+
+// Gets the logrus.APILoggerEntry from a context
+func GetCtxEntry(ctx context.Context) *APILoggerEntry {
+	entry := ctx.Value(CtxLoggerKey).(*APILoggerEntry)
+	return entry
+}

ssas/service/admin/router.go

@@ -53,7 +53,7 @@ func routes() *chi.Mux {
 	r := chi.NewRouter()
 	m := monitoring.GetMonitor()
 
-	r.Use(gcmw.RequestID, service.NewAPILogger(), service.ConnectionClose)
+	r.Use(gcmw.RequestID, service.NewAPILogger(), service.ConnectionClose, service.NewCtxLogger)
 	r.With(requireBasicAuth).Post(m.WrapHandler("/group", createGroup))
 	r.With(requireBasicAuth).Get(m.WrapHandler("/group", listGroups))
 	r.With(requireBasicAuth).Put(m.WrapHandler("/group/{id}", updateGroup))

ssas/service/logging.go

@@ -1,6 +1,7 @@
 package service
 
 import (
+	"context"
 	"fmt"
 	"net/http"
 	"regexp"
@@ -10,21 +11,22 @@ import (
 	"github.com/go-chi/chi/v5/middleware"
 	"github.com/sirupsen/logrus"
 
+	"github.com/CMSgov/bcda-ssas-app/log"
 	"github.com/CMSgov/bcda-ssas-app/ssas"
 )
 
 //https://github.com/go-chi/chi/blob/master/_examples/logging/main.go
 
 func NewAPILogger() func(next http.Handler) http.Handler {
-	return middleware.RequestLogger(&APILogger{ssas.Logger})
+	return middleware.RequestLogger(&APILogger{log.Logger})
 }
 
 type APILogger struct {
 	Logger logrus.FieldLogger
 }
 
 func (l *APILogger) NewLogEntry(r *http.Request) middleware.LogEntry {
-	entry := &APILoggerEntry{Logger: l.Logger}
+	entry := &log.APILoggerEntry{Logger: l.Logger}
 	logFields := logrus.Fields{}
 
 	logFields["ts"] = time.Now() // .UTC().Format(time.RFC1123)
@@ -55,26 +57,6 @@ func (l *APILogger) NewLogEntry(r *http.Request) middleware.LogEntry {
 	return entry
 }
 
-type APILoggerEntry struct {
-	Logger logrus.FieldLogger
-}
-
-func (l *APILoggerEntry) Write(status int, bytes int, header http.Header, elapsed time.Duration, extra interface{}) {
-	l.Logger = l.Logger.WithFields(logrus.Fields{
-		"resp_status": status, "resp_bytes_length": bytes,
-		"resp_elapsed_ms": float64(elapsed.Nanoseconds()) / 1000000.0,
-	})
-
-	l.Logger.Infoln("request complete")
-}
-
-func (l *APILoggerEntry) Panic(v interface{}, stack []byte) {
-	l.Logger = l.Logger.WithFields(logrus.Fields{
-		"stack": string(stack),
-		"panic": fmt.Sprintf("%+v", v),
-	})
-}
-
 func Redact(uri string) string {
 	re := regexp.MustCompile(`Bearer%20([^&]+)(?:&|$)`)
 	submatches := re.FindAllStringSubmatch(uri, -1)
@@ -84,19 +66,16 @@ func Redact(uri string) string {
 	return uri
 }
 
-func GetLogEntry(r *http.Request) logrus.FieldLogger {
-	entry := middleware.GetLogEntry(r).(*APILoggerEntry)
-	return entry.Logger
-}
-
-func LogEntrySetField(r *http.Request, key string, value interface{}) {
-	if entry, ok := r.Context().Value(middleware.LogEntryCtxKey).(*APILoggerEntry); ok {
-		entry.Logger = entry.Logger.WithField(key, value)
-	}
-}
-
-func LogEntrySetFields(r *http.Request, fields map[string]interface{}) {
-	if entry, ok := r.Context().Value(middleware.LogEntryCtxKey).(*APILoggerEntry); ok {
-		entry.Logger = entry.Logger.WithFields(fields)
-	}
+// NewCtxLogger adds new key value pair of {CtxLoggerKey: logrus.FieldLogger} to the requests context
+func NewCtxLogger(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		logFields := logrus.Fields{}
+		logFields["request_id"] = middleware.GetReqID(r.Context())
+		if rd, ok := r.Context().Value("rd").(ssas.AuthRegData); ok {
+			logFields["okta_id"] = rd.OktaID
+		}
+		newLogEntry := &log.APILoggerEntry{Logger: log.Logger.WithFields(logFields)}
+		r = r.WithContext(context.WithValue(r.Context(), log.CtxLoggerKey, newLogEntry))
+		next.ServeHTTP(w, r)
+	})
 }

ssas/service/main/main.go

@@ -198,7 +198,7 @@ func start(ps *service.Server, as *service.Server, forwarder *http.Server) {
 
 func newForwardingRouter() http.Handler {
 	r := chi.NewRouter()
-	r.Use(gcmw.RequestID, service.NewAPILogger(), service.ConnectionClose)
+	r.Use(gcmw.RequestID, service.NewAPILogger(), service.ConnectionClose, service.NewCtxLogger)
 	r.Get("/*", http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 		// TODO only forward requests for paths in our own host or resource server
 		url := "https://" + req.Host + req.URL.String()

ssas/service/public/api.go

@@ -14,6 +14,7 @@ import (
 	"net/http"
 	"strconv"
 
+	"github.com/CMSgov/bcda-ssas-app/log"
 	"github.com/CMSgov/bcda-ssas-app/ssas"
 	"github.com/CMSgov/bcda-ssas-app/ssas/constants"
 	"github.com/CMSgov/bcda-ssas-app/ssas/service"
@@ -69,7 +70,7 @@ func ResetSecret(w http.ResponseWriter, r *http.Request) {
 	setHeaders(w)
 
 	if rd, err = readRegData(r); err != nil || rd.GroupID == "" {
-		service.GetLogEntry(r).Println("missing or invalid GroupID")
+		log.Logger.Println("missing or invalid GroupID")
 		service.JSONError(w, http.StatusUnauthorized, http.StatusText(http.StatusUnauthorized), "")
 		return
 	}
@@ -80,7 +81,7 @@ func ResetSecret(w http.ResponseWriter, r *http.Request) {
 	}
 
 	if err = json.Unmarshal(bodyStr, &req); err != nil {
-		service.LogEntrySetField(r, "bodyStr", bodyStr)
+		// service.LogEntrySetField(r, "bodyStr", bodyStr)
 		service.JSONError(w, http.StatusBadRequest, "invalid_client_metadata", "Request body cannot be parsed")
 		return
 	}
@@ -141,7 +142,7 @@ func RegisterSystem(w http.ResponseWriter, r *http.Request) {
 	setHeaders(w)
 
 	if rd, err = readRegData(r); err != nil || rd.GroupID == "" {
-		service.GetLogEntry(r).Println("missing or invalid GroupID")
+		log.Logger.Println("missing or invalid GroupID")
 		// Specified in RFC 7592 https://tools.ietf.org/html/rfc7592#page-6
 		service.JSONError(w, http.StatusUnauthorized, http.StatusText(http.StatusUnauthorized), "")
 		return
@@ -156,7 +157,7 @@ func RegisterSystem(w http.ResponseWriter, r *http.Request) {
 
 	err = json.Unmarshal(bodyStr, &reg)
 	if err != nil {
-		service.LogEntrySetField(r, "bodyStr", bodyStr)
+		// service.LogEntrySetField(r, "bodyStr", bodyStr)
 		service.JSONError(w, http.StatusBadRequest, "invalid_client_metadata", "Request body cannot be parsed")
 		return
 	}
@@ -245,21 +246,21 @@ func token(w http.ResponseWriter, r *http.Request) {
 
 	system, err := ssas.GetSystemByClientID(r.Context(), clientID)
 	if err != nil {
-		ssas.Logger.Errorf("The client id %s is invalid", err.Error())
+		log.Logger.Errorf("The client id %s is invalid", err.Error())
 		service.JSONError(w, http.StatusUnauthorized, http.StatusText(http.StatusUnauthorized), "invalid client id")
 		return
 	}
 	err = ValidateSecret(system, secret, r)
 	if err != nil {
-		ssas.Logger.Error("The client id and secret cannot be validated: ", err.Error())
+		log.Logger.Error("The client id and secret cannot be validated: ", err.Error())
 		service.JSONError(w, http.StatusUnauthorized, http.StatusText(http.StatusUnauthorized), err.Error())
 		return
 	}
 
 	trackingID := uuid.NewRandom().String()
 
 	data, err := ssas.XDataFor(r.Context(), system)
-	ssas.Logger.Infof("public.api.token: XDataFor(%d) returned '%s'", system.ID, data)
+	log.Logger.Infof("public.api.token: XDataFor(%d) returned '%s'", system.ID, data)
 	if err != nil {
 		service.JSONError(w, http.StatusUnauthorized, http.StatusText(http.StatusUnauthorized), "no group for system")
 		return
@@ -371,7 +372,7 @@ func tokenV2(w http.ResponseWriter, r *http.Request) {
 	}
 
 	data, err := ssas.XDataFor(r.Context(), system)
-	ssas.Logger.Infof("public.api.token: XDataFor(%d) returned '%s'", system.ID, data)
+	log.Logger.Infof("public.api.token: XDataFor(%d) returned '%s'", system.ID, data)
 	if err != nil {
 		service.JSONError(w, http.StatusUnauthorized, http.StatusText(http.StatusUnauthorized), "no group for system")
 		return
@@ -482,7 +483,7 @@ func introspect(w http.ResponseWriter, r *http.Request) {
 	var answer = make(map[string]bool)
 	answer["active"] = true
 	if err = tokenValidity(reqV["token"], "AccessToken"); err != nil {
-		ssas.Logger.Infof("token failed tokenValidity")
+		log.Logger.Infof("token failed tokenValidity")
 		answer["active"] = false
 	}
 
@@ -513,12 +514,12 @@ func validateAndParseToken(w http.ResponseWriter, r *http.Request) {
 	var response = make(map[string]interface{})
 
 	if err := tokenValidity(tokenS, "AccessToken"); err != nil {
-		ssas.Logger.Infof("token failed tokenValidity")
+		log.Logger.Infof("token failed tokenValidity")
 		response["valid"] = false
 	} else {
 		claims := jwt.MapClaims{}
 		if _, _, err := new(jwt.Parser).ParseUnverified(tokenS, claims); err != nil {
-			ssas.Logger.Infof("could not unmarshal access token")
+			log.Logger.Infof("could not unmarshal access token")
 			service.JSONError(w, http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError), "internal server error")
 			return
 		}
@@ -527,7 +528,7 @@ func validateAndParseToken(w http.ResponseWriter, r *http.Request) {
 		response["system_data"] = claims["system_data"]
 		sys, err := ssas.GetSystemByID(r.Context(), claims["sys"].(string))
 		if err != nil {
-			ssas.Logger.Infof("could not get system id")
+			log.Logger.Infof("could not get system id")
 			service.JSONError(w, http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError), "internal server error")
 			return
 		}

ssas/service/public/middleware.go

@@ -3,10 +3,12 @@ package public
 import (
 	"context"
 	"fmt"
-	"github.com/CMSgov/bcda-ssas-app/ssas"
-	"github.com/CMSgov/bcda-ssas-app/ssas/service"
 	"net/http"
 	"regexp"
+
+	"github.com/CMSgov/bcda-ssas-app/log"
+	"github.com/CMSgov/bcda-ssas-app/ssas"
+	"github.com/CMSgov/bcda-ssas-app/ssas/service"
 )
 
 func readGroupID(next http.Handler) http.Handler {
@@ -16,25 +18,25 @@ func readGroupID(next http.Handler) http.Handler {
 			err error
 		)
 		if rd, err = readRegData(r); err != nil {
-			service.GetLogEntry(r).Println("no data from token about allowed groups")
+			log.Logger.Println("no data from token about allowed groups")
 			respond(w, http.StatusUnauthorized)
 			return
 		}
 
 		if rd.GroupID = r.Header.Get("x-group-id"); rd.GroupID == "" {
-			service.GetLogEntry(r).Println("missing header x-group-id")
+			log.Logger.Println("missing header x-group-id")
 			respond(w, http.StatusUnauthorized)
 			return
 		}
 
 		if !contains(rd.AllowedGroupIDs, rd.GroupID) {
-			service.GetLogEntry(r).Println("group specified in x-group-id not in token's allowed groups")
+			log.Logger.Println("group specified in x-group-id not in token's allowed groups")
 			respond(w, http.StatusUnauthorized)
 			return
 		}
 
 		ctx := context.WithValue(r.Context(), "rd", rd)
-		service.LogEntrySetField(r, "rd", rd)
+		// service.LogEntrySetField(r, "rd", rd)
 		next.ServeHTTP(w, r.WithContext(ctx))
 	})
 }
@@ -82,7 +84,7 @@ func parseToken(next http.Handler) http.Handler {
 		}
 		ctx := context.WithValue(r.Context(), "ts", tokenString)
 		ctx = context.WithValue(ctx, "rd", rd)
-		service.LogEntrySetField(r, "rd", rd)
+		// service.LogEntrySetField(r, "rd", rd)
 		next.ServeHTTP(w, r.WithContext(ctx))
 	})
 }

ssas/service/public/router.go

@@ -53,7 +53,7 @@ func routes() *chi.Mux {
 	router := chi.NewRouter()
 	m := monitoring.GetMonitor()
 	//v1 Routes
-	router.Use(gcmw.RequestID, service.NewAPILogger(), service.ConnectionClose)
+	router.Use(gcmw.RequestID, service.NewAPILogger(), service.ConnectionClose, service.NewCtxLogger)
 	router.Post(m.WrapHandler("/token", token))
 	router.Post(m.WrapHandler("/introspect", introspect))
 	router.With(parseToken, requireRegTokenAuth, readGroupID).Post(m.WrapHandler("/register", RegisterSystem))

ssas/service/server.go

@@ -240,6 +240,7 @@ func (s *Server) newBaseRouter() *chi.Mux {
 		NewAPILogger(),
 		render.SetContentType(render.ContentTypeJSON),
 		ConnectionClose,
+		NewCtxLogger,
 	)
 	r.Get("/_version", s.getVersion)
 	r.Get("/_health", s.getHealthCheck)