BED-4153: slog Migration (#1068)

* BED-4153: Begin slog rewrite * chore: convert all formatted string logs to use `fmt.Sprintf` as an intermediate for slog compatibility * BED-4153: Improve context hook * BED-4153: Fix IDResolver name * chore: refactor out slog measure package * chore: reference implementation for supporting runtime level manipulation * BED-4153: Migrate to new LogAndMeasure * BED-4153: Migrate to new Measure * BED-4153: Migrate log.Info * BED-4153: Migrate log.Error * BED-4153: Migrate log.Warn * BED-4153: Migrate log.Debug and log.Panic * BED-4153: Rename log package to bhlog * BED-4153: Update gormlogadapter test * BED-4153: Remove all legacy log functionality * BED-4153: Resolve issues from migration * BED-4153: Resolve lint errors * BED-4153: Resolve lint issues * BED-4153: Add convenience ConfigureDefault function * feat: wire up config for text logging --------- Co-authored-by: Alyx Holms <aholms@specterops.io>
SpecterOps · Jan 10, 2025 · b90fd6c · b90fd6c
1 parent 9e77c99
commit b90fd6c
Show file tree

Hide file tree

Showing 144 changed files with 1,235 additions and 2,320 deletions.
diff --git a/cmd/api/src/analysis/ad/queries.go b/cmd/api/src/analysis/ad/queries.go
@@ -19,6 +19,7 @@ package ad
 import (
 	"context"
 	"fmt"
+	"log/slog"
 	"sync"
 
 	"github.com/gofrs/uuid"
@@ -29,7 +30,6 @@ import (
 	"github.com/specterops/bloodhound/dawgs/query"
 	"github.com/specterops/bloodhound/graphschema/ad"
 	"github.com/specterops/bloodhound/graphschema/common"
-	"github.com/specterops/bloodhound/log"
 	"github.com/specterops/bloodhound/src/database/types/nan"
 	"github.com/specterops/bloodhound/src/model"
 	"github.com/specterops/bloodhound/src/queries"
@@ -87,7 +87,7 @@ func GraphStats(ctx context.Context, db graph.Database) (model.ADDataQualityStat
 		} else {
 			for _, domain := range domains {
 				if domainSID, err := domain.Properties.Get(common.ObjectID.String()).String(); err != nil {
-					log.Errorf("Domain node %d does not have a valid %s property: %v", domain.ID, common.ObjectID, err)
+					slog.ErrorContext(ctx, fmt.Sprintf("Domain node %d does not have a valid %s property: %v", domain.ID, common.ObjectID, err))
 				} else {
 					aggregation.Domains++
 

diff --git a/cmd/api/src/analysis/azure/queries.go b/cmd/api/src/analysis/azure/queries.go
@@ -19,6 +19,7 @@ package azure
 import (
 	"context"
 	"fmt"
+	"log/slog"
 	"sync"
 
 	"github.com/gofrs/uuid"
@@ -28,7 +29,6 @@ import (
 	"github.com/specterops/bloodhound/dawgs/query"
 	"github.com/specterops/bloodhound/graphschema/azure"
 	"github.com/specterops/bloodhound/graphschema/common"
-	"github.com/specterops/bloodhound/log"
 	"github.com/specterops/bloodhound/src/model"
 )
 
@@ -55,7 +55,7 @@ func GraphStats(ctx context.Context, db graph.Database) (model.AzureDataQualityS
 		} else {
 			for _, tenant := range tenants {
 				if tenantObjectID, err := tenant.Properties.Get(common.ObjectID.String()).String(); err != nil {
-					log.Errorf("Tenant node %d does not have a valid %s property: %v", tenant.ID, common.ObjectID, err)
+					slog.ErrorContext(ctx, fmt.Sprintf("Tenant node %d does not have a valid %s property: %v", tenant.ID, common.ObjectID, err))
 				} else {
 					aggregation.Tenants++
 

diff --git a/cmd/api/src/api/auth.go b/cmd/api/src/api/auth.go
@@ -27,6 +27,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log/slog"
 	"net/http"
 	"strconv"
 	"strings"
@@ -36,7 +37,6 @@ import (
 	"github.com/golang-jwt/jwt/v4"
 	"github.com/specterops/bloodhound/crypto"
 	"github.com/specterops/bloodhound/headers"
-	"github.com/specterops/bloodhound/log"
 	"github.com/specterops/bloodhound/src/auth"
 	"github.com/specterops/bloodhound/src/config"
 	"github.com/specterops/bloodhound/src/ctx"
@@ -112,7 +112,7 @@ func (s authenticator) auditLogin(requestContext context.Context, commitID uuid.
 
 	err := s.db.CreateAuditLog(requestContext, auditLog)
 	if err != nil {
-		log.Warnf("failed to write login audit log %+v", err)
+		slog.WarnContext(requestContext, fmt.Sprintf("failed to write login audit log %+v", err))
 	}
 }
 
@@ -140,7 +140,7 @@ func (s authenticator) LoginWithSecret(ctx context.Context, loginRequest LoginRe
 	auditLogFields := types.JSONUntypedObject{"username": loginRequest.Username, "auth_type": auth.ProviderTypeSecret}
 
 	if commitID, err := uuid.NewV4(); err != nil {
-		log.Errorf("Error generating commit ID for login: %s", err)
+		slog.ErrorContext(ctx, fmt.Sprintf("Error generating commit ID for login: %s", err))
 		return LoginDetails{}, err
 	} else {
 		s.auditLogin(ctx, commitID, model.AuditLogStatusIntent, model.User{}, auditLogFields)
@@ -281,7 +281,7 @@ func (s authenticator) ValidateRequestSignature(tokenID uuid.UUID, request *http
 			authToken.LastAccess = time.Now().UTC()
 
 			if err := s.db.UpdateAuthToken(request.Context(), authToken); err != nil {
-				log.Errorf("Error updating last access on AuthToken: %v", err)
+				slog.ErrorContext(request.Context(), fmt.Sprintf("Error updating last access on AuthToken: %v", err))
 			}
 
 			if sdtf, ok := readCloser.(*SelfDestructingTempFile); ok {
@@ -362,7 +362,7 @@ func (s authenticator) CreateSSOSession(request *http.Request, response http.Res
 
 	// Generate commit ID for audit logging
 	if commitID, err = uuid.NewV4(); err != nil {
-		log.Errorf("Error generating commit ID for login: %s", err)
+		slog.ErrorContext(request.Context(), fmt.Sprintf("Error generating commit ID for login: %s", err))
 		WriteErrorResponse(requestCtx, BuildErrorResponse(http.StatusInternalServerError, "audit log creation failure", request), response)
 		return
 	}
@@ -417,7 +417,7 @@ func (s authenticator) CreateSession(ctx context.Context, user model.User, authP
 		return "", ErrUserDisabled
 	}
 
-	log.Infof("Creating session for user: %s(%s)", user.ID, user.PrincipalName)
+	slog.InfoContext(ctx, fmt.Sprintf("Creating session for user: %s(%s)", user.ID, user.PrincipalName))
 
 	userSession := model.UserSession{
 		User:      user,
@@ -475,16 +475,16 @@ func (s authenticator) ValidateSession(ctx context.Context, jwtTokenString strin
 
 		return auth.Context{}, err
 	} else if !token.Valid {
-		log.Infof("Token invalid")
+		slog.InfoContext(ctx, "Token invalid")
 		return auth.Context{}, ErrInvalidAuth
 	} else if sessionID, err := claims.SessionID(); err != nil {
-		log.Infof("Session ID %s invalid: %v", claims.Id, err)
+		slog.InfoContext(ctx, fmt.Sprintf("Session ID %s invalid: %v", claims.Id, err))
 		return auth.Context{}, ErrInvalidAuth
 	} else if session, err := s.db.GetUserSession(ctx, sessionID); err != nil {
-		log.Infof("Unable to find session %d", sessionID)
+		slog.InfoContext(ctx, fmt.Sprintf("Unable to find session %d", sessionID))
 		return auth.Context{}, ErrInvalidAuth
 	} else if session.Expired() {
-		log.Infof("Session %d is expired", sessionID)
+		slog.InfoContext(ctx, fmt.Sprintf("Session %d is expired", sessionID))
 		return auth.Context{}, ErrInvalidAuth
 	} else {
 		authContext := auth.Context{
@@ -493,7 +493,7 @@ func (s authenticator) ValidateSession(ctx context.Context, jwtTokenString strin
 		}
 
 		if session.AuthProviderType == model.SessionAuthProviderSecret && session.User.AuthSecret == nil {
-			log.Infof("No auth secret found for user ID %s", session.UserID.String())
+			slog.InfoContext(ctx, fmt.Sprintf("No auth secret found for user ID %s", session.UserID.String()))
 			return auth.Context{}, ErrNoUserSecret
 		} else if session.AuthProviderType == model.SessionAuthProviderSecret && session.User.AuthSecret.Expired() {
 			var (

diff --git a/cmd/api/src/api/bloodhoundgraph/properties.go b/cmd/api/src/api/bloodhoundgraph/properties.go
@@ -17,13 +17,14 @@
 package bloodhoundgraph
 
 import (
+	"fmt"
+	"log/slog"
 	"strings"
 
 	"github.com/specterops/bloodhound/analysis"
 	"github.com/specterops/bloodhound/dawgs/graph"
 	"github.com/specterops/bloodhound/graphschema/ad"
 	"github.com/specterops/bloodhound/graphschema/common"
-	"github.com/specterops/bloodhound/log"
 )
 
 // We ignore the property lookup errors here since there's no clear path for a caller to handle it. Logging is also
@@ -32,7 +33,7 @@ import (
 
 func getNodeLevel(target *graph.Node) (int, bool) {
 	if startSystemTags, err := target.Properties.Get(common.SystemTags.String()).String(); err == nil {
-		log.Debugf("Unable to find a %s property for node %d with kinds %v", common.SystemTags.String(), target.ID, target.Kinds)
+		slog.Debug(fmt.Sprintf("Unable to find a %s property for node %d with kinds %v", common.SystemTags.String(), target.ID, target.Kinds))
 	} else if strings.Contains(startSystemTags, ad.AdminTierZero) {
 		return 0, true
 	}

diff --git a/cmd/api/src/api/error.go b/cmd/api/src/api/error.go
@@ -20,11 +20,11 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"strings"
 	"time"
 
-	"github.com/specterops/bloodhound/log"
 	"github.com/specterops/bloodhound/src/ctx"
 	"github.com/specterops/bloodhound/src/database"
 )
@@ -129,7 +129,7 @@ func HandleDatabaseError(request *http.Request, response http.ResponseWriter, er
 	} else if errors.Is(err, context.DeadlineExceeded) {
 		WriteErrorResponse(request.Context(), BuildErrorResponse(http.StatusInternalServerError, ErrorResponseRequestTimeout, request), response)
 	} else {
-		log.Errorf("Unexpected database error: %v", err)
+		slog.Error(fmt.Sprintf("Unexpected database error: %v", err))
 		WriteErrorResponse(request.Context(), BuildErrorResponse(http.StatusInternalServerError, ErrorResponseDetailsInternalServerError, request), response)
 	}
 }
@@ -140,7 +140,7 @@ func FormatDatabaseError(err error) error {
 	if errors.Is(err, database.ErrNotFound) {
 		return errors.New(ErrorResponseDetailsResourceNotFound)
 	} else {
-		log.Errorf("Unexpected database error: %v", err)
+		slog.Error(fmt.Sprintf("Unexpected database error: %v", err))
 		return errors.New(ErrorResponseDetailsInternalServerError)
 	}
 }
diff --git a/cmd/api/src/api/marshalling.go b/cmd/api/src/api/marshalling.go
@@ -22,11 +22,11 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log/slog"
 	"net/http"
 	"time"
 
 	"github.com/specterops/bloodhound/headers"
-	"github.com/specterops/bloodhound/log"
 	"github.com/specterops/bloodhound/mediatypes"
 	"github.com/specterops/bloodhound/src/api/stream"
 	"github.com/specterops/bloodhound/src/model"
@@ -76,15 +76,15 @@ type ResponseWrapper struct {
 func WriteErrorResponse(ctx context.Context, untypedError any, response http.ResponseWriter) {
 	switch typedError := untypedError.(type) {
 	case *ErrorResponse: // V1 error handling
-		log.Warnf("Writing API Error. Status: %v. Message: %v", typedError.HTTPStatus, typedError.Error)
+		slog.WarnContext(ctx, fmt.Sprintf("Writing API Error. Status: %v. Message: %v", typedError.HTTPStatus, typedError.Error))
 		WriteJSONResponse(context.Background(), typedError.Error, typedError.HTTPStatus, response)
 
 	case *ErrorWrapper: // V2 error handling
-		log.Warnf("Writing API Error. Status: %v. Message: %v", typedError.HTTPStatus, typedError.Errors)
+		slog.WarnContext(ctx, fmt.Sprintf("Writing API Error. Status: %v. Message: %v", typedError.HTTPStatus, typedError.Errors))
 		WriteJSONResponse(ctx, typedError, typedError.HTTPStatus, response)
 
 	default:
-		log.Warnf("Failure Writing API Error. Status: %v. Message: %v", http.StatusInternalServerError, "Invalid error format returned")
+		slog.WarnContext(ctx, fmt.Sprintf("Failure Writing API Error. Status: %v. Message: %v", http.StatusInternalServerError, "Invalid error format returned"))
 		WriteJSONResponse(ctx, "An internal error has occurred that is preventing the service from servicing this request.", http.StatusInternalServerError, response)
 	}
 }
@@ -94,7 +94,7 @@ func WriteErrorResponse(ctx context.Context, untypedError any, response http.Res
 
 func WriteBasicResponse(ctx context.Context, inputData any, statusCode int, response http.ResponseWriter) {
 	if data, err := ToJSONRawMessage(inputData); err != nil {
-		log.Errorf("Failed marshaling data for basic response: %v", err)
+		slog.ErrorContext(ctx, fmt.Sprintf("Failed marshaling data for basic response: %v", err))
 		response.WriteHeader(http.StatusInternalServerError)
 	} else {
 		WriteJSONResponse(ctx, BasicResponse{
@@ -158,35 +158,35 @@ func WriteResponseWrapperWithTimeWindowAndPagination(ctx context.Context, data a
 	WriteJSONResponse(ctx, wrapper, statusCode, response)
 }
 
-func WriteJSONResponse(_ context.Context, message any, statusCode int, response http.ResponseWriter) {
+func WriteJSONResponse(ctx context.Context, message any, statusCode int, response http.ResponseWriter) {
 	response.Header().Set(headers.ContentType.String(), mediatypes.ApplicationJson.String())
 	if content, err := json.Marshal(message); err != nil {
-		log.Errorf("Failed to marshal value into JSON for request: %v: for message: %+v", err, message)
+		slog.ErrorContext(ctx, fmt.Sprintf("Failed to marshal value into JSON for request: %v: for message: %+v", err, message))
 		response.WriteHeader(http.StatusInternalServerError)
 	} else {
 		response.WriteHeader(statusCode)
 		if written, err := response.Write(content); err != nil {
-			log.Errorf("Writing API Error. Failed to write JSON response with %d bytes written and error: %v", written, err)
+			slog.ErrorContext(ctx, fmt.Sprintf("Writing API Error. Failed to write JSON response with %d bytes written and error: %v", written, err))
 		}
 	}
 }
 
-func WriteCSVResponse(_ context.Context, message model.CSVWriter, statusCode int, response http.ResponseWriter) {
+func WriteCSVResponse(ctx context.Context, message model.CSVWriter, statusCode int, response http.ResponseWriter) {
 	response.Header().Set(headers.ContentType.String(), mediatypes.TextCsv.String())
 	response.WriteHeader(statusCode)
 
 	if err := message.WriteCSV(response); err != nil {
-		log.Errorf("Writing API Error. Failed to write CSV for request: %v", err)
+		slog.ErrorContext(ctx, fmt.Sprintf("Writing API Error. Failed to write CSV for request: %v", err))
 	}
 }
 
-func WriteBinaryResponse(_ context.Context, data []byte, filename string, statusCode int, response http.ResponseWriter) {
+func WriteBinaryResponse(ctx context.Context, data []byte, filename string, statusCode int, response http.ResponseWriter) {
 	response.Header().Set(headers.ContentType.String(), mediatypes.ApplicationOctetStream.String())
 	response.Header().Set(headers.ContentDisposition.String(), fmt.Sprintf(utils.ContentDispositionAttachmentTemplate, filename))
 	response.WriteHeader(statusCode)
 
 	if written, err := response.Write(data); err != nil {
-		log.Errorf("Writing API Error. Failed to write binary response with %d bytes written and error: %v", written, err)
+		slog.ErrorContext(ctx, fmt.Sprintf("Writing API Error. Failed to write binary response with %d bytes written and error: %v", written, err))
 	}
 }
 

diff --git a/cmd/api/src/api/middleware/compression.go b/cmd/api/src/api/middleware/compression.go
@@ -22,11 +22,11 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log/slog"
 	"net/http"
 	"strings"
 
 	"github.com/specterops/bloodhound/headers"
-	"github.com/specterops/bloodhound/log"
 	"github.com/specterops/bloodhound/src/api"
 )
 
@@ -65,7 +65,7 @@ func CompressionMiddleware(next http.Handler) http.Handler {
 				request.Body, err = wrapBody(encoding, request.Body)
 				if err != nil {
 					errMsg := fmt.Sprintf("failed to create reader for %s encoding: %v", encoding, err)
-					log.Warnf(errMsg)
+					slog.WarnContext(request.Context(), errMsg)
 					if errors.Is(err, errUnsupportedEncoding) {
 						api.WriteErrorResponse(request.Context(), api.BuildErrorResponse(http.StatusUnsupportedMediaType, fmt.Sprintf("Error trying to read request: %s", errMsg), request), responseWriter)
 					} else {
@@ -106,7 +106,7 @@ func wrapBody(encoding string, body io.ReadCloser) (io.ReadCloser, error) {
 	case "deflate":
 		newBody, err = zlib.NewReader(body)
 	default:
-		log.Infof("Unsupported encoding detected: %s", encoding)
+		slog.Info(fmt.Sprintf("Unsupported encoding detected: %s", encoding))
 		err = errUnsupportedEncoding
 	}
 	return newBody, err