From fb9c85f883b3ee4dbab545931b38c18de9b4faae Mon Sep 17 00:00:00 2001 From: hailin Date: Sat, 6 Dec 2025 02:11:28 -0800 Subject: [PATCH] debug(coordinator): add detailed logging to track concurrent update issue MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add comprehensive debug logs to: 1. report_completion.go - log all participant statuses at key points 2. session_postgres_repo.go - log before/after each participant update This will help identify why server-party-1 status remains 'invited' despite successfully reporting completion. šŸ¤– Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- backend/.claude/settings.local.json | 7 +- .../output/postgres/session_postgres_repo.go | 30 +++++ .../use_cases/report_completion.go | 33 ++++++ backend/mpc-system/test_create_session.go | 111 ++++++++++++++++++ 4 files changed, 180 insertions(+), 1 deletion(-) create mode 100644 backend/mpc-system/test_create_session.go diff --git a/backend/.claude/settings.local.json b/backend/.claude/settings.local.json index 62095519..92387d00 100644 --- a/backend/.claude/settings.local.json +++ b/backend/.claude/settings.local.json @@ -19,7 +19,12 @@ "Bash(git commit:*)", "Bash(git push:*)", "Bash(git pull:*)", - "Bash(del \"api\\proto\\session_coordinator.pb.go\" \"api\\proto\\session_coordinator_grpc.pb.go\" \"api\\proto\\message_router.pb.go\" \"api\\proto\\message_router_grpc.pb.go\")" + "Bash(del \"api\\proto\\session_coordinator.pb.go\" \"api\\proto\\session_coordinator_grpc.pb.go\" \"api\\proto\\message_router.pb.go\" \"api\\proto\\message_router_grpc.pb.go\")", + "Bash(grep:*)", + "Bash(cat:*)", + "Bash(dir:*)", + "Bash(copy /Y \"api\\proto\\session_coordinator.pb.go\" \"api\\grpc\\coordinator\\v1\"\" && copy /Y \"apiprotosession_coordinator_grpc.pb.go\" \"apigrpccoordinatorv1\"\")", + "Bash(timeout /t 10 /nobreak)" ], "deny": [], "ask": [] diff --git a/backend/mpc-system/services/session-coordinator/adapters/output/postgres/session_postgres_repo.go b/backend/mpc-system/services/session-coordinator/adapters/output/postgres/session_postgres_repo.go index 26ec866e..f4c99671 100644 --- a/backend/mpc-system/services/session-coordinator/adapters/output/postgres/session_postgres_repo.go +++ b/backend/mpc-system/services/session-coordinator/adapters/output/postgres/session_postgres_repo.go @@ -8,9 +8,11 @@ import ( "github.com/google/uuid" "github.com/lib/pq" + "github.com/rwadurian/mpc-system/pkg/logger" "github.com/rwadurian/mpc-system/services/session-coordinator/domain/entities" "github.com/rwadurian/mpc-system/services/session-coordinator/domain/repositories" "github.com/rwadurian/mpc-system/services/session-coordinator/domain/value_objects" + "go.uber.org/zap" ) // SessionPostgresRepo implements SessionRepository for PostgreSQL @@ -283,8 +285,23 @@ func (r *SessionPostgresRepo) Update(ctx context.Context, session *entities.MPCS return err } + // DEBUG: Log all participant statuses before update + var participantStatuses []string + for _, p := range session.Participants { + participantStatuses = append(participantStatuses, p.PartyID.String()+":"+p.Status.String()) + } + logger.Debug("repo.Update: updating participants", + zap.String("session_id", session.ID.UUID().String()), + zap.Strings("participant_statuses", participantStatuses)) + // Update each participant individually for _, p := range session.Participants { + // DEBUG: Log before updating each participant + logger.Debug("repo.Update: updating individual participant", + zap.String("session_id", session.ID.UUID().String()), + zap.String("party_id", p.PartyID.String()), + zap.String("new_status", p.Status.String())) + // Try UPDATE first result, err := tx.ExecContext(ctx, ` UPDATE participants SET @@ -317,8 +334,18 @@ func (r *SessionPostgresRepo) Update(ctx context.Context, session *entities.MPCS return err } + // DEBUG: Log rows affected + logger.Debug("repo.Update: participant update result", + zap.String("session_id", session.ID.UUID().String()), + zap.String("party_id", p.PartyID.String()), + zap.Int64("rows_affected", rowsAffected)) + if rowsAffected == 0 { // Participant doesn't exist, INSERT it + logger.Debug("repo.Update: inserting new participant", + zap.String("session_id", session.ID.UUID().String()), + zap.String("party_id", p.PartyID.String())) + _, err = tx.ExecContext(ctx, ` INSERT INTO participants ( id, session_id, party_id, party_index, status, @@ -344,6 +371,9 @@ func (r *SessionPostgresRepo) Update(ctx context.Context, session *entities.MPCS } } + logger.Debug("repo.Update: committing transaction", + zap.String("session_id", session.ID.UUID().String())) + return tx.Commit() } diff --git a/backend/mpc-system/services/session-coordinator/application/use_cases/report_completion.go b/backend/mpc-system/services/session-coordinator/application/use_cases/report_completion.go index 193ae5b3..22ef7f7d 100644 --- a/backend/mpc-system/services/session-coordinator/application/use_cases/report_completion.go +++ b/backend/mpc-system/services/session-coordinator/application/use_cases/report_completion.go @@ -42,12 +42,26 @@ func (uc *ReportCompletionUseCase) Execute( ctx context.Context, inputData input.ReportCompletionInput, ) (*input.ReportCompletionOutput, error) { + logger.Debug("ReportCompletion.Execute: START", + zap.String("session_id", inputData.SessionID.String()), + zap.String("party_id", inputData.PartyID)) + // 1. Load session session, err := uc.sessionRepo.FindByUUID(ctx, inputData.SessionID) if err != nil { return nil, err } + // DEBUG: Log all participant statuses after loading session + var allParticipantStatuses []string + for _, p := range session.Participants { + allParticipantStatuses = append(allParticipantStatuses, p.PartyID.String()+":"+p.Status.String()) + } + logger.Debug("ReportCompletion.Execute: loaded session", + zap.String("session_id", session.ID.String()), + zap.String("party_id", inputData.PartyID), + zap.Strings("all_participant_statuses", allParticipantStatuses)) + // 2. Create party ID value object partyID, err := value_objects.NewPartyID(inputData.PartyID) if err != nil { @@ -60,6 +74,11 @@ func (uc *ReportCompletionUseCase) Execute( return nil, err } + logger.Debug("ReportCompletion.Execute: current participant status", + zap.String("session_id", session.ID.String()), + zap.String("party_id", inputData.PartyID), + zap.String("current_status", participant.Status.String())) + // 3.1 Ensure participant is in Ready state before marking as Completed // The status flow is: Invited -> Joined -> Ready -> Completed // Handle all possible states to reach Ready @@ -139,10 +158,24 @@ func (uc *ReportCompletionUseCase) Execute( } // 6. Save updated session + // DEBUG: Log all participant statuses before calling Update + var beforeUpdateStatuses []string + for _, p := range session.Participants { + beforeUpdateStatuses = append(beforeUpdateStatuses, p.PartyID.String()+":"+p.Status.String()) + } + logger.Debug("ReportCompletion.Execute: BEFORE sessionRepo.Update", + zap.String("session_id", session.ID.String()), + zap.String("party_id", inputData.PartyID), + zap.Strings("all_participant_statuses", beforeUpdateStatuses)) + if err := uc.sessionRepo.Update(ctx, session); err != nil { return nil, err } + logger.Debug("ReportCompletion.Execute: AFTER sessionRepo.Update", + zap.String("session_id", session.ID.String()), + zap.String("party_id", inputData.PartyID)) + // 7. Publish participant completed event event := output.ParticipantCompletedEvent{ SessionID: session.ID.String(), diff --git a/backend/mpc-system/test_create_session.go b/backend/mpc-system/test_create_session.go new file mode 100644 index 00000000..bb7dc2fc --- /dev/null +++ b/backend/mpc-system/test_create_session.go @@ -0,0 +1,111 @@ +package main + +import ( + "bytes" + "encoding/json" + "fmt" + "io" + "net/http" + "os" + "time" + + "github.com/golang-jwt/jwt/v5" + "github.com/google/uuid" +) + +type Claims struct { + SessionID string `json:"session_id"` + PartyID string `json:"party_id"` + TokenType string `json:"token_type"` + jwt.RegisteredClaims +} + +func generateAccessToken(secretKey, userID, username string) (string, error) { + now := time.Now() + claims := Claims{ + PartyID: username, + TokenType: "access", + RegisteredClaims: jwt.RegisteredClaims{ + ID: uuid.New().String(), + Issuer: "mpc-system", + Subject: userID, + IssuedAt: jwt.NewNumericDate(now), + NotBefore: jwt.NewNumericDate(now), + ExpiresAt: jwt.NewNumericDate(now.Add(24 * time.Hour)), + }, + } + + token := jwt.NewWithClaims(jwt.SigningMethodHS256, claims) + return token.SignedString([]byte(secretKey)) +} + +func main() { + // Get JWT secret from environment or use test value + jwtSecret := os.Getenv("JWT_SECRET_KEY") + if jwtSecret == "" { + jwtSecret = "test-jwt-secret-key-please-change-in-production" + } + + // Generate access token + token, err := generateAccessToken(jwtSecret, "admin", "admin") + if err != nil { + fmt.Printf("Failed to generate token: %v\n", err) + os.Exit(1) + } + + fmt.Printf("Generated JWT token: %s\n\n", token) + + // Create keygen session via account-service + sessionData := map[string]interface{}{ + "threshold_n": 3, + "threshold_t": 2, + } + + jsonData, err := json.Marshal(sessionData) + if err != nil { + fmt.Printf("Failed to marshal JSON: %v\n", err) + os.Exit(1) + } + + // Get API key from environment or use test value + apiKey := os.Getenv("MPC_API_KEY") + if apiKey == "" { + apiKey = "test-api-key" + } + + // Call account-service API + req, err := http.NewRequest("POST", "http://localhost:4000/api/v1/mpc/keygen", bytes.NewBuffer(jsonData)) + if err != nil { + fmt.Printf("Failed to create request: %v\n", err) + os.Exit(1) + } + + req.Header.Set("Content-Type", "application/json") + req.Header.Set("X-API-Key", apiKey) + + client := &http.Client{Timeout: 10 * time.Second} + resp, err := client.Do(req) + if err != nil { + fmt.Printf("Failed to send request: %v\n", err) + os.Exit(1) + } + defer resp.Body.Close() + + body, err := io.ReadAll(resp.Body) + if err != nil { + fmt.Printf("Failed to read response: %v\n", err) + os.Exit(1) + } + + fmt.Printf("Response status: %s\n", resp.Status) + fmt.Printf("Response body: %s\n", string(body)) + + if resp.StatusCode == 200 || resp.StatusCode == 201 { + var result map[string]interface{} + if err := json.Unmarshal(body, &result); err == nil { + if sessionID, ok := result["session_id"].(string); ok { + fmt.Printf("\nāœ“ Session created successfully: %s\n", sessionID) + } + } + } +}