Revert "BCDA-7414: Add Context Logger" (#158)

Reverts #155

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, service.NewCtxLogger)
+	r.Use(gcmw.RequestID, service.NewAPILogger(), service.ConnectionClose)
 	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,7 +1,6 @@
 package service
 
 import (
-	"context"
 	"fmt"
 	"net/http"
 	"regexp"
@@ -11,22 +10,21 @@ 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{log.Logger})
+	return middleware.RequestLogger(&APILogger{ssas.Logger})
 }
 
 type APILogger struct {
 	Logger logrus.FieldLogger
 }
 
 func (l *APILogger) NewLogEntry(r *http.Request) middleware.LogEntry {
-	entry := &log.APILoggerEntry{Logger: l.Logger}
+	entry := &APILoggerEntry{Logger: l.Logger}
 	logFields := logrus.Fields{}
 
 	logFields["ts"] = time.Now() // .UTC().Format(time.RFC1123)
@@ -57,6 +55,26 @@ 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)
@@ -66,16 +84,19 @@ func Redact(uri string) string {
 	return uri
 }
 
-// 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)
-	})
+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)
+	}
 }

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, service.NewCtxLogger)
+	r.Use(gcmw.RequestID, service.NewAPILogger(), service.ConnectionClose)
 	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,7 +14,6 @@ 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"
@@ -70,7 +69,7 @@ func ResetSecret(w http.ResponseWriter, r *http.Request) {
 	setHeaders(w)
 
 	if rd, err = readRegData(r); err != nil || rd.GroupID == "" {
-		log.Logger.Println("missing or invalid GroupID")
+		service.GetLogEntry(r).Println("missing or invalid GroupID")
 		service.JSONError(w, http.StatusUnauthorized, http.StatusText(http.StatusUnauthorized), "")
 		return
 	}
@@ -81,7 +80,7 @@ func ResetSecret(w http.ResponseWriter, r *http.Request) {
 	}
 
 	if err = json.Unmarshal(bodyStr, &req); err != nil {
-		log.SetCtxEntry(r, "bodyStr", bodyStr)
+		service.LogEntrySetField(r, "bodyStr", bodyStr)
 		service.JSONError(w, http.StatusBadRequest, "invalid_client_metadata", "Request body cannot be parsed")
 		return
 	}
@@ -142,7 +141,7 @@ func RegisterSystem(w http.ResponseWriter, r *http.Request) {
 	setHeaders(w)
 
 	if rd, err = readRegData(r); err != nil || rd.GroupID == "" {
-		log.Logger.Println("missing or invalid GroupID")
+		service.GetLogEntry(r).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
@@ -157,7 +156,7 @@ func RegisterSystem(w http.ResponseWriter, r *http.Request) {
 
 	err = json.Unmarshal(bodyStr, &reg)
 	if err != nil {
-		log.SetCtxEntry(r, "bodyStr", bodyStr)
+		service.LogEntrySetField(r, "bodyStr", bodyStr)
 		service.JSONError(w, http.StatusBadRequest, "invalid_client_metadata", "Request body cannot be parsed")
 		return
 	}
@@ -246,21 +245,21 @@ func token(w http.ResponseWriter, r *http.Request) {
 
 	system, err := ssas.GetSystemByClientID(r.Context(), clientID)
 	if err != nil {
-		log.Logger.Errorf("The client id %s is invalid", err.Error())
+		ssas.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 {
-		log.Logger.Error("The client id and secret cannot be validated: ", err.Error())
+		ssas.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)
-	log.Logger.Infof("public.api.token: XDataFor(%d) returned '%s'", system.ID, data)
+	ssas.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
@@ -372,7 +371,7 @@ func tokenV2(w http.ResponseWriter, r *http.Request) {
 	}
 
 	data, err := ssas.XDataFor(r.Context(), system)
-	log.Logger.Infof("public.api.token: XDataFor(%d) returned '%s'", system.ID, data)
+	ssas.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
@@ -483,7 +482,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 {
-		log.Logger.Infof("token failed tokenValidity")
+		ssas.Logger.Infof("token failed tokenValidity")
 		answer["active"] = false
 	}
 
@@ -514,12 +513,12 @@ func validateAndParseToken(w http.ResponseWriter, r *http.Request) {
 	var response = make(map[string]interface{})
 
 	if err := tokenValidity(tokenS, "AccessToken"); err != nil {
-		log.Logger.Infof("token failed tokenValidity")
+		ssas.Logger.Infof("token failed tokenValidity")
 		response["valid"] = false
 	} else {
 		claims := jwt.MapClaims{}
 		if _, _, err := new(jwt.Parser).ParseUnverified(tokenS, claims); err != nil {
-			log.Logger.Infof("could not unmarshal access token")
+			ssas.Logger.Infof("could not unmarshal access token")
 			service.JSONError(w, http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError), "internal server error")
 			return
 		}
@@ -528,7 +527,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 {
-			log.Logger.Infof("could not get system id")
+			ssas.Logger.Infof("could not get system id")
 			service.JSONError(w, http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError), "internal server error")
 			return
 		}