Logging best practices experiment

go.mod

@@ -5,7 +5,7 @@ go 1.24.2
 toolchain go1.24.3
 
 require (
-	github.com/NYCU-SDC/summer v1.0.0-test
+	github.com/NYCU-SDC/summer v1.0.0-test.0.20260124035608-99432ce125c2
 	github.com/brianvoe/gofakeit/v7 v7.7.3
 	github.com/go-playground/validator/v10 v10.26.0
 	github.com/golang-jwt/jwt/v5 v5.2.2

go.sum

@@ -10,6 +10,8 @@ github.com/Microsoft/go-winio v0.6.2 h1:F2VQgta7ecxGYO8k3ZZz3RS8fVIXVxONVUPlNERo
 github.com/Microsoft/go-winio v0.6.2/go.mod h1:yd8OoFMLzJbo9gZq8j5qaps8bJ9aShtEA8Ipt1oGCvU=
 github.com/NYCU-SDC/summer v1.0.0-test h1:ezpNgVKD62dFXLZ8dL/o+Ii4Qh0KM/EZNeivknGV/V4=
 github.com/NYCU-SDC/summer v1.0.0-test/go.mod h1:v4hv+B6ePNcEItb8oaVQRyN6hvlpj9cgwGoCgD1izyc=
+github.com/NYCU-SDC/summer v1.0.0-test.0.20260124035608-99432ce125c2 h1:xGXxZ81gCWjLGBslQT4MvWqrFSXV3Y2ILQvkYgM4Haw=
+github.com/NYCU-SDC/summer v1.0.0-test.0.20260124035608-99432ce125c2/go.mod h1:v4hv+B6ePNcEItb8oaVQRyN6hvlpj9cgwGoCgD1izyc=
 github.com/Nvveen/Gotty v0.0.0-20120604004816-cd527374f1e5 h1:TngWCqHvy9oXAN6lEVMRuU21PR1EtLVZJmdB18Gu3Rw=
 github.com/Nvveen/Gotty v0.0.0-20120604004816-cd527374f1e5/go.mod h1:lmUJ/7eu/Q8D7ML55dXQrVaamCz2vxCfdQBasLZfHKk=
 github.com/brianvoe/gofakeit/v7 v7.7.3 h1:RWOATEGpJ5EVg2nN8nlaEyaV/aB4d6c3GqYrbqQekss=

internal/distribute/service.go

@@ -1,11 +1,11 @@
 package distribute
 
 import (
-	"NYCU-SDC/core-system-backend/internal"
-	"NYCU-SDC/core-system-backend/internal/user"
 	"context"
+	"fmt"
+
+	"NYCU-SDC/core-system-backend/internal/user"
 
-	databaseutil "github.com/NYCU-SDC/summer/pkg/database"
 	logutil "github.com/NYCU-SDC/summer/pkg/log"
 	"github.com/google/uuid"
 	"go.opentelemetry.io/otel"
@@ -36,18 +36,14 @@ func NewService(logger *zap.Logger, store UnitStore) *Service {
 func (s *Service) GetOrgRecipients(ctx context.Context, orgID uuid.UUID) ([]uuid.UUID, error) {
 	traceCtx, span := s.tracer.Start(ctx, "GetOrgRecipients")
 	defer span.End()
-	logger := internal.WithContext(traceCtx, s.logger)
 
 	recipients, err := s.store.ListMembers(traceCtx, orgID)
 	if err != nil {
-		return nil, err
+		wrappedErr := fmt.Errorf("failed to fetch org members: %w", err)
+		span.RecordError(wrappedErr)
+		return nil, wrappedErr
 	}
 
-	logger.Debug("Organization recipients resolved",
-		zap.String("org_id", orgID.String()),
-		zap.Int("recipients_count", len(recipients)),
-	)
-
 	ids := make([]uuid.UUID, 0, len(recipients))
 	for _, r := range recipients {
 		ids = append(ids, r.ID)
@@ -57,23 +53,32 @@ func (s *Service) GetOrgRecipients(ctx context.Context, orgID uuid.UUID) ([]uuid
 }
 
 func (s *Service) GetRecipients(ctx context.Context, unitIDs []uuid.UUID) ([]uuid.UUID, error) {
-	ctx, span := s.tracer.Start(ctx, "GetRecipients")
+	methodName := "GetRecipients"
+	ctx, span := s.tracer.Start(ctx, methodName)
 	defer span.End()
 	logger := logutil.WithContext(ctx, s.logger)
 
+	tracker := logutil.StartMethod(ctx, logger, methodName, map[string]interface{}{
+		"unit_ids": unitIDs,
+	})
+
 	all := make([]uuid.UUID, 0)
 
 	memberMap, err := s.store.ListUnitsMembers(ctx, unitIDs)
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "list units members")
-		span.RecordError(err)
-		return nil, err
+		wrappedErr := fmt.Errorf("failed to fetch unit members: %w", err)
+		span.RecordError(wrappedErr)
+		return nil, wrappedErr
 	}
 
 	for _, ms := range memberMap {
 		all = append(all, ms...)
 	}
 
+	logger.Debug("Processing recipients calculation",
+		zap.Int("raw_total_count", len(all)),
+	)
+
 	seen := make(map[uuid.UUID]struct{}, len(all))
 	uniq := make([]uuid.UUID, 0, len(all))
 	for _, id := range all {
@@ -84,10 +89,9 @@ func (s *Service) GetRecipients(ctx context.Context, unitIDs []uuid.UUID) ([]uui
 		uniq = append(uniq, id)
 	}
 
-	logger.Debug("Recipients resolved",
-		zap.Int("unit_count", len(unitIDs)),
-		zap.Int("unique_recipients", len(uniq)),
-	)
+	tracker.Complete(map[string]interface{}{
+		"recipients_count": len(uniq),
+	})
 
 	return uniq, nil
 }

internal/form/service.go

@@ -48,6 +48,15 @@ func (s *Service) Create(ctx context.Context, req Request, unitID uuid.UUID, use
 		deadline = pgtype.Timestamptz{Valid: false}
 	}
 
+	dbParams := map[string]interface{}{
+		"title":           req.Title,
+		"description":     req.Description,
+		"preview_message": req.PreviewMessage,
+		"unit_id":         unitID.String(),
+		"last_editor":     userID.String(),
+	}
+	tracker := logutil.StartDBOperation(ctx, logger, "Create", dbParams)
+
 	newForm, err := s.queries.Create(ctx, CreateParams{
 		Title:          req.Title,
 		Description:    pgtype.Text{String: req.Description, Valid: true},
@@ -57,11 +66,13 @@ func (s *Service) Create(ctx context.Context, req Request, unitID uuid.UUID, use
 		Deadline:       deadline,
 	})
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "create form")
+		err = databaseutil.WrapDBErrorWithTracker(err, tracker, "create form")
 		span.RecordError(err)
 		return CreateRow{}, err
 	}
 
+	tracker.SuccessWrite(newForm.ID.String())
+
 	return newForm, nil
 }
 
@@ -77,6 +88,15 @@ func (s *Service) Update(ctx context.Context, id uuid.UUID, request Request, use
 		deadline = pgtype.Timestamptz{Valid: false}
 	}
 
+	dbParams := map[string]interface{}{
+		"id":              id.String(),
+		"title":           request.Title,
+		"description":     request.Description,
+		"preview_message": request.PreviewMessage,
+		"last_editor":     userID.String(),
+	}
+	tracker := logutil.StartDBOperation(ctx, logger, "Update", dbParams)
+
 	updatedForm, err := s.queries.Update(ctx, UpdateParams{
 		ID:             id,
 		Title:          request.Title,
@@ -86,11 +106,13 @@ func (s *Service) Update(ctx context.Context, id uuid.UUID, request Request, use
 		Deadline:       deadline,
 	})
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "update form")
+		err = databaseutil.WrapDBErrorWithTracker(err, tracker, "update form")
 		span.RecordError(err)
 		return UpdateRow{}, err
 	}
 
+	tracker.SuccessWrite(id.String())
+
 	return updatedForm, nil
 }
 
@@ -99,28 +121,41 @@ func (s *Service) Delete(ctx context.Context, id uuid.UUID) error {
 	defer span.End()
 	logger := logutil.WithContext(ctx, s.logger)
 
+	dbParams := map[string]interface{}{
+		"id": id.String(),
+	}
+	tracker := logutil.StartDBOperation(ctx, logger, "Delete", dbParams)
+
 	err := s.queries.Delete(ctx, id)
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "delete form")
+		err = databaseutil.WrapDBErrorWithTracker(err, tracker, "delete form")
 		span.RecordError(err)
 		return err
 	}
+	tracker.SuccessWrite(id.String())
 
 	return nil
 }
 
 func (s *Service) GetByID(ctx context.Context, id uuid.UUID) (GetByIDRow, error) {
-	ctx, span := s.tracer.Start(ctx, "GetFormByID")
+	ctx, span := s.tracer.Start(ctx, "GetByID")
 	defer span.End()
 	logger := logutil.WithContext(ctx, s.logger)
 
+	dbParams := map[string]interface{}{
+		"id": id.String(),
+	}
+	tracker := logutil.StartDBOperation(ctx, logger, "GetByID", dbParams)
+
 	currentForm, err := s.queries.GetByID(ctx, id)
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "get form by id")
+		err = databaseutil.WrapDBErrorWithTracker(err, tracker, "get form by id")
 		span.RecordError(err)
 		return GetByIDRow{}, err
 	}
 
+	tracker.SuccessRead(1, id.String())
+
 	return currentForm, nil
 }
 
@@ -129,13 +164,17 @@ func (s *Service) List(ctx context.Context) ([]ListRow, error) {
 	defer span.End()
 	logger := logutil.WithContext(ctx, s.logger)
 
+	tracker := logutil.StartDBOperation(ctx, logger, "List", nil)
+
 	forms, err := s.queries.List(ctx)
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "list forms")
+		err = databaseutil.WrapDBErrorWithTracker(err, tracker, "list forms")
 		span.RecordError(err)
 		return []ListRow{}, err
 	}
 
+	tracker.SuccessRead(len(forms), "")
+
 	return forms, nil
 }
 
@@ -144,13 +183,20 @@ func (s *Service) ListByUnit(ctx context.Context, unitID uuid.UUID) ([]ListByUni
 	defer span.End()
 	logger := logutil.WithContext(ctx, s.logger)
 
+	dbParams := map[string]interface{}{
+		"unit_id": unitID.String(),
+	}
+	tracker := logutil.StartDBOperation(ctx, logger, "ListByUnit", dbParams)
+
 	forms, err := s.queries.ListByUnit(ctx, pgtype.UUID{Bytes: unitID, Valid: true})
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "list forms by unit")
+		err = databaseutil.WrapDBErrorWithTracker(err, tracker, "list forms by unit")
 		span.RecordError(err)
 		return []ListByUnitRow{}, err
 	}
 
+	tracker.SuccessRead(len(forms), unitID.String())
+
 	return forms, nil
 }
 
@@ -159,16 +205,25 @@ func (s *Service) SetStatus(ctx context.Context, id uuid.UUID, status Status, us
 	defer span.End()
 	logger := logutil.WithContext(ctx, s.logger)
 
+	dbParams := map[string]interface{}{
+		"id":          id.String(),
+		"status":      string(status),
+		"last_editor": userID.String(),
+	}
+	tracker := logutil.StartDBOperation(ctx, logger, "SetStatus", dbParams)
+
 	updated, err := s.queries.SetStatus(ctx, SetStatusParams{
 		ID:         id,
 		Status:     status,
 		LastEditor: userID,
 	})
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "set form status")
+		err = databaseutil.WrapDBErrorWithTracker(err, tracker, "set form status")
 		span.RecordError(err)
 		return Form{}, err
 	}
 
+	tracker.SuccessWrite(id.String())
+
 	return updated, nil
 }

internal/inbox/service.go

@@ -45,31 +45,61 @@ func (s *Service) Create(ctx context.Context, contentType ContentType, contentID
 	defer span.End()
 	logger := logutil.WithContext(traceCtx, s.logger)
 
+	serviceName := "Create"
+
+	entryParams := map[string]interface{}{
+		"content_type":    contentType,
+		"content_id":      contentID.String(),
+		"posted_by":       postByUnitID.String(),
+		"recipient_count": len(userIDs),
+	}
+	tracker := logutil.StartMethod(traceCtx, logger, serviceName, entryParams)
+
+	dbParamsMsg := map[string]interface{}{
+		"type":       contentType,
+		"content_id": contentID.String(),
+		"posted_by":  postByUnitID.String(),
+	}
+	dbOpMsg := "CreateMessage"
+	msgDBTracker := logutil.StartDBOperation(traceCtx, logger, dbOpMsg, dbParamsMsg)
+
 	message, err := s.queries.CreateMessage(traceCtx, CreateMessageParams{
 		Type:      contentType,
 		ContentID: contentID,
 		PostedBy:  postByUnitID,
 	})
+
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "create inbox message")
+		err = databaseutil.WrapDBErrorWithTracker(err, msgDBTracker, "create inbox message")
 		span.RecordError(err)
 		return uuid.Nil, err
 	}
 
+	msgDBTracker.SuccessWrite(message.ID.String())
+
+	dbParamsBulk := map[string]interface{}{
+		"user_ids":   userIDs,
+		"message_id": message.ID.String(),
+	}
+	dbOpBulk := "CreateUserInboxBulk"
+	bulkDBTracker := logutil.StartDBOperation(traceCtx, logger, dbOpBulk, dbParamsBulk)
 	_, err = s.queries.CreateUserInboxBulk(traceCtx, CreateUserInboxBulkParams{
 		UserIds:   userIDs,
 		MessageID: message.ID,
 	})
+
 	if err != nil {
-		err = databaseutil.WrapDBError(err, logger, "create user inbox messages in bulk")
+		err = databaseutil.WrapDBErrorWithTracker(err, bulkDBTracker, "create user inbox messages in bulk")
 		span.RecordError(err)
 		return uuid.Nil, err
 	}
 
-	logger.Info("Created inbox message",
-		zap.String("message_id", message.ID.String()),
-		zap.Int("recipients", len(userIDs)),
-	)
+	bulkDBTracker.SuccessWriteBulk(len(userIDs))
+
+	tracker.Complete(map[string]interface{}{
+		"message_id":      message.ID.String(),
+		"recipient_count": len(userIDs),
+	})
 
 	return message.ID, nil
 }