From c6a9da4ea96fa8fad52a8cff3e29d6617a19092c Mon Sep 17 00:00:00 2001 From: erio Date: Mon, 13 Apr 2026 16:20:07 +0800 Subject: [PATCH] debug: add notification path logging for beta investigation Add slog.Info/Debug logs to notifyBalanceLow, notifyAccountQuota, CheckBalanceAfterDeduction, and sendEmails to diagnose why balance and quota notifications are not being sent in beta environment. --- backend/cmd/server/VERSION | 2 +- .../service/balance_notify_service.go | 28 +++++++++++++++++++ backend/internal/service/gateway_service.go | 25 +++++++++++++++++ 3 files changed, 54 insertions(+), 1 deletion(-) diff --git a/backend/cmd/server/VERSION b/backend/cmd/server/VERSION index edd548470c..f03dfd0593 100644 --- a/backend/cmd/server/VERSION +++ b/backend/cmd/server/VERSION @@ -1 +1 @@ -0.1.110.25 +0.1.110.26 diff --git a/backend/internal/service/balance_notify_service.go b/backend/internal/service/balance_notify_service.go index 66629e14a7..a912737f91 100644 --- a/backend/internal/service/balance_notify_service.go +++ b/backend/internal/service/balance_notify_service.go @@ -65,14 +65,21 @@ func resolveBalanceThreshold(threshold float64, thresholdType string, totalRecha // Notification is sent only on first crossing: oldBalance >= threshold && newBalance < threshold. func (s *BalanceNotifyService) CheckBalanceAfterDeduction(ctx context.Context, user *User, oldBalance, cost float64) { if user == nil || s.emailService == nil || s.settingRepo == nil { + slog.Debug("CheckBalanceAfterDeduction: skipped (nil check)", + "user_nil", user == nil, + "email_svc_nil", s.emailService == nil, + "setting_repo_nil", s.settingRepo == nil, + ) return } if !user.BalanceNotifyEnabled { + slog.Debug("CheckBalanceAfterDeduction: user notify disabled", "user_id", user.ID) return } globalEnabled, globalThreshold := s.getBalanceNotifyConfig(ctx) if !globalEnabled { + slog.Info("CheckBalanceAfterDeduction: global notify disabled", "user_id", user.ID) return } @@ -82,18 +89,33 @@ func (s *BalanceNotifyService) CheckBalanceAfterDeduction(ctx context.Context, u threshold = *user.BalanceNotifyThreshold } if threshold <= 0 { + slog.Debug("CheckBalanceAfterDeduction: threshold <= 0", "user_id", user.ID, "threshold", threshold) return } effectiveThreshold := resolveBalanceThreshold(threshold, user.BalanceNotifyThresholdType, user.TotalRecharged) if effectiveThreshold <= 0 { + slog.Debug("CheckBalanceAfterDeduction: effective threshold <= 0", "user_id", user.ID) return } newBalance := oldBalance - cost + slog.Info("CheckBalanceAfterDeduction: crossing check", + "user_id", user.ID, + "old_balance", oldBalance, + "new_balance", newBalance, + "effective_threshold", effectiveThreshold, + "crossed", oldBalance >= effectiveThreshold && newBalance < effectiveThreshold, + ) if oldBalance >= effectiveThreshold && newBalance < effectiveThreshold { siteName := s.getSiteName(ctx) recipients := s.collectBalanceNotifyRecipients(user) + slog.Info("CheckBalanceAfterDeduction: sending notification", + "user_id", user.ID, + "recipients", recipients, + "new_balance", newBalance, + "threshold", effectiveThreshold, + ) go func() { defer func() { if r := recover(); r != nil { @@ -328,11 +350,17 @@ func (s *BalanceNotifyService) collectBalanceNotifyRecipients(user *User) []stri // sendEmails sends an email to all recipients with shared timeout and error logging. func (s *BalanceNotifyService) sendEmails(recipients []string, subject, body string, logAttrs ...any) { + if len(recipients) == 0 { + slog.Warn("sendEmails: no recipients", "subject", subject) + return + } for _, to := range recipients { ctx, cancel := context.WithTimeout(context.Background(), emailSendTimeout) if err := s.emailService.SendEmail(ctx, to, subject, body); err != nil { attrs := append([]any{"to", to, "error", err}, logAttrs...) slog.Error("failed to send notification", attrs...) + } else { + slog.Info("notification email sent successfully", "to", to, "subject", subject) } cancel() } diff --git a/backend/internal/service/gateway_service.go b/backend/internal/service/gateway_service.go index 48b750e860..70f90d4fdd 100644 --- a/backend/internal/service/gateway_service.go +++ b/backend/internal/service/gateway_service.go @@ -7538,10 +7538,24 @@ func finalizePostUsageBilling(p *postUsageBillingParams, deps *billingDeps, resu // to reconstruct oldBalance, avoiding stale Redis reads and concurrent-deduction races. func notifyBalanceLow(p *postUsageBillingParams, deps *billingDeps, result *UsageBillingApplyResult) { if p.IsSubscriptionBill || p.Cost.ActualCost <= 0 || p.User == nil || deps.balanceNotifyService == nil { + slog.Debug("notifyBalanceLow: skipped", + "is_subscription", p.IsSubscriptionBill, + "actual_cost", p.Cost.ActualCost, + "user_nil", p.User == nil, + "service_nil", deps.balanceNotifyService == nil, + ) return } oldBalance := resolveOldBalance(p, result) + slog.Info("notifyBalanceLow: calling CheckBalanceAfterDeduction", + "user_id", p.User.ID, + "old_balance", oldBalance, + "cost", p.Cost.ActualCost, + "notify_enabled", p.User.BalanceNotifyEnabled, + "threshold", p.User.BalanceNotifyThreshold, + "result_has_new_balance", result != nil && result.NewBalance != nil, + ) deps.balanceNotifyService.CheckBalanceAfterDeduction(context.Background(), p.User, oldBalance, p.Cost.ActualCost) } @@ -7560,6 +7574,12 @@ func resolveOldBalance(p *postUsageBillingParams, result *UsageBillingApplyResul // to avoid a separate DB read that may see stale or concurrently-modified data. func notifyAccountQuota(p *postUsageBillingParams, deps *billingDeps, result *UsageBillingApplyResult) { if p.Cost.TotalCost <= 0 || p.Account == nil || !p.Account.IsAPIKeyOrBedrock() || deps.balanceNotifyService == nil { + slog.Debug("notifyAccountQuota: skipped", + "total_cost", p.Cost.TotalCost, + "account_nil", p.Account == nil, + "is_apikey_or_bedrock", p.Account != nil && p.Account.IsAPIKeyOrBedrock(), + "service_nil", deps.balanceNotifyService == nil, + ) return } accountCost := p.Cost.TotalCost * p.AccountRateMultiplier @@ -7567,6 +7587,11 @@ func notifyAccountQuota(p *postUsageBillingParams, deps *billingDeps, result *Us if result != nil { quotaState = result.QuotaState } + slog.Info("notifyAccountQuota: calling CheckAccountQuotaAfterIncrement", + "account_id", p.Account.ID, + "account_cost", accountCost, + "has_quota_state", quotaState != nil, + ) deps.balanceNotifyService.CheckAccountQuotaAfterIncrement(context.Background(), p.Account, accountCost, quotaState) }