Merge pull request 'Logging on webhooks' (#531) from tg-530 into main

Reviewed-on: #531

api/notification/internal/server/notificationimp/confirmation.go

@@ -58,63 +58,118 @@ func newConfirmationManager(logger mlogger.Logger, tg telegram.Client, outbox ms
 	}
 }
 
+func (m *confirmationManager) logDebug(message string, fields ...zap.Field) {
+	if m == nil || m.logger == nil {
+		return
+	}
+	m.logger.Debug(message, fields...)
+}
+
+func (m *confirmationManager) logInfo(message string, fields ...zap.Field) {
+	if m == nil || m.logger == nil {
+		return
+	}
+	m.logger.Info(message, fields...)
+}
+
+func (m *confirmationManager) logWarn(message string, fields ...zap.Field) {
+	if m == nil || m.logger == nil {
+		return
+	}
+	m.logger.Warn(message, fields...)
+}
+
 func (m *confirmationManager) Stop() {
 	if m == nil {
 		return
 	}
+	m.logInfo("Stopping confirmation manager")
 	m.mu.Lock()
 	defer m.mu.Unlock()
+	pending := len(m.pendingByMessage)
+	m.logDebug("Stopping pending confirmation timers", zap.Int("pending_count", pending))
 	for _, state := range m.pendingByMessage {
 		if state.timer != nil {
-			state.timer.Stop()
+			if !state.timer.Stop() {
+				m.logDebug("Confirmation timer already fired while stopping", zap.String("request_id", state.request.RequestID), zap.String("message_id", state.requestMessageID))
+			}
 		}
 	}
 	m.pendingByMessage = map[string]*confirmationState{}
 	m.pendingByRequest = map[string]*confirmationState{}
+	m.logInfo("Confirmation manager stopped", zap.Int("pending_cleared", pending))
 }
 
 func (m *confirmationManager) HandleRequest(ctx context.Context, request *model.ConfirmationRequest) error {
 	if m == nil {
 		return merrors.Internal("confirmation manager is nil")
 	}
+	m.logDebug("Handling confirmation request", zap.Bool("request_nil", request == nil))
 	if request == nil {
+		m.logWarn("Confirmation request rejected: request is nil")
 		return merrors.InvalidArgument("confirmation request is nil", "request")
 	}
 	if m.tg == nil {
+		m.logWarn("Confirmation request rejected: telegram client is not configured", zap.String("request_id", strings.TrimSpace(request.RequestID)))
 		return merrors.InvalidArgument("telegram client is not configured", "telegram")
 	}
 
 	req := normalizeConfirmationRequest(*request)
+	m.logDebug("Confirmation request normalized",
+		zap.String("request_id", req.RequestID),
+		zap.String("target_chat_id", req.TargetChatID),
+		zap.String("source_service", req.SourceService),
+		zap.String("rail", req.Rail),
+		zap.Int("accepted_users", len(req.AcceptedUserIDs)),
+		zap.Int32("timeout_seconds", req.TimeoutSeconds))
 	if req.RequestID == "" {
+		m.logWarn("Confirmation request rejected: request_id is required", zap.String("target_chat_id", req.TargetChatID))
 		return merrors.InvalidArgument("confirmation request_id is required", "request_id")
 	}
 	if req.TargetChatID == "" {
+		m.logWarn("Confirmation request rejected: target_chat_id is required", zap.String("request_id", req.RequestID))
 		return merrors.InvalidArgument("confirmation target_chat_id is required", "target_chat_id")
 	}
 	if req.RequestedMoney == nil || strings.TrimSpace(req.RequestedMoney.Amount) == "" || strings.TrimSpace(req.RequestedMoney.Currency) == "" {
+		m.logWarn("Confirmation request rejected: requested_money is required", zap.String("request_id", req.RequestID))
 		return merrors.InvalidArgument("confirmation requested_money is required", "requested_money")
 	}
 	if req.SourceService == "" {
+		m.logWarn("Confirmation request rejected: source_service is required", zap.String("request_id", req.RequestID))
 		return merrors.InvalidArgument("confirmation source_service is required", "source_service")
 	}
 
 	m.mu.Lock()
+	pendingBefore := len(m.pendingByMessage)
 	if _, ok := m.pendingByRequest[req.RequestID]; ok {
 		m.mu.Unlock()
-		m.logger.Info("Confirmation request already pending", zap.String("request_id", req.RequestID))
+		m.logInfo("Confirmation request already pending", zap.String("request_id", req.RequestID), zap.Int("pending_count", pendingBefore))
 		return nil
 	}
 	m.mu.Unlock()
+	m.logDebug("Confirmation request accepted for processing",
+		zap.String("request_id", req.RequestID),
+		zap.String("target_chat_id", req.TargetChatID),
+		zap.Int("pending_count_before", pendingBefore))
 
 	message := confirmationPrompt(&req)
+	m.logDebug("Sending confirmation request to Telegram",
+		zap.String("request_id", req.RequestID),
+		zap.String("target_chat_id", req.TargetChatID),
+		zap.Int("prompt_length", len(message)))
 	sent, err := m.tg.SendText(ctx, req.TargetChatID, message, "")
 	if err != nil {
-		m.logger.Warn("Failed to send confirmation request to Telegram", zap.Error(err), zap.String("request_id", req.RequestID))
+		m.logWarn("Failed to send confirmation request to Telegram", zap.Error(err), zap.String("request_id", req.RequestID), zap.String("target_chat_id", req.TargetChatID))
 		return err
 	}
 	if sent == nil || strings.TrimSpace(sent.MessageID) == "" {
+		m.logWarn("Confirmation request send succeeded without message_id", zap.String("request_id", req.RequestID))
 		return merrors.Internal("telegram confirmation message id is missing")
 	}
+	m.logDebug("Confirmation request sent to Telegram",
+		zap.String("request_id", req.RequestID),
+		zap.String("message_id", strings.TrimSpace(sent.MessageID)),
+		zap.String("target_chat_id", req.TargetChatID))
 
 	state := &confirmationState{
 		request:          req,
@@ -124,8 +179,13 @@ func (m *confirmationManager) HandleRequest(ctx context.Context, request *model.
 	}
 	timeout := time.Duration(req.TimeoutSeconds) * time.Second
 	if timeout <= 0 {
+		m.logDebug("Confirmation timeout not provided, using default timeout", zap.String("request_id", req.RequestID), zap.Duration("timeout", defaultConfirmationTimeout))
 		timeout = defaultConfirmationTimeout
 	}
+	m.logDebug("Scheduling confirmation timeout",
+		zap.String("request_id", req.RequestID),
+		zap.String("message_id", state.requestMessageID),
+		zap.Duration("timeout", timeout))
 	state.timer = time.AfterFunc(timeout, func() {
 		m.handleTimeout(state.requestMessageID)
 	})
@@ -133,35 +193,65 @@ func (m *confirmationManager) HandleRequest(ctx context.Context, request *model.
 	m.mu.Lock()
 	m.pendingByMessage[state.requestMessageID] = state
 	m.pendingByRequest[req.RequestID] = state
+	pendingAfter := len(m.pendingByMessage)
 	m.mu.Unlock()
 
-	m.logger.Info("Confirmation request sent", zap.String("request_id", req.RequestID), zap.String("message_id", state.requestMessageID), zap.String("callback_subject", state.callbackSubject))
+	m.logInfo("Confirmation request sent",
+		zap.String("request_id", req.RequestID),
+		zap.String("message_id", state.requestMessageID),
+		zap.String("callback_subject", state.callbackSubject),
+		zap.Int("pending_count", pendingAfter))
 	return nil
 }
 
 func (m *confirmationManager) HandleUpdate(ctx context.Context, update *telegram.Update) {
-	if m == nil || update == nil || update.Message == nil {
+	if m == nil {
+		return
+	}
+	if update == nil {
+		m.logDebug("Telegram update ignored: update is nil")
+		return
+	}
+	if update.Message == nil {
+		m.logDebug("Telegram update ignored: message is nil")
 		return
 	}
 	message := update.Message
 	if message.ReplyToMessage == nil {
+		m.logDebug("Telegram update ignored: message is not a reply", zap.Int64("message_id", message.MessageID))
 		return
 	}
 
 	replyToID := strconv.FormatInt(message.ReplyToMessage.MessageID, 10)
+	m.logDebug("Telegram reply received", zap.String("reply_to_message_id", replyToID))
 	state := m.lookupByMessageID(replyToID)
 	if state == nil {
+		m.logDebug("Telegram reply ignored: no pending confirmation for message", zap.String("reply_to_message_id", replyToID))
 		return
 	}
+	m.logDebug("Telegram reply matched pending confirmation",
+		zap.String("request_id", state.request.RequestID),
+		zap.String("reply_to_message_id", replyToID))
 
 	chatID := strconv.FormatInt(message.Chat.ID, 10)
 	if chatID != state.targetChatID {
-		m.logger.Debug("Telegram reply ignored: chat mismatch", zap.String("expected_chat_id", state.targetChatID), zap.String("chat_id", chatID))
+		m.logDebug("Telegram reply ignored: chat mismatch",
+			zap.String("request_id", state.request.RequestID),
+			zap.String("expected_chat_id", state.targetChatID),
+			zap.String("chat_id", chatID))
 		return
 	}
 
 	rawReply := message.ToModel()
 	if !state.isUserAllowed(message.From) {
+		userID := ""
+		if message.From != nil {
+			userID = strconv.FormatInt(message.From.ID, 10)
+		}
+		m.logWarn("Telegram reply rejected: unauthorized user",
+			zap.String("request_id", state.request.RequestID),
+			zap.String("user_id", userID),
+			zap.String("chat_id", chatID))
 		m.publishResult(state, &model.ConfirmationResult{
 			RequestID:  state.request.RequestID,
 			Status:     model.ConfirmationStatusRejected,
@@ -172,9 +262,14 @@ func (m *confirmationManager) HandleUpdate(ctx context.Context, update *telegram
 		m.removeState(state.requestMessageID)
 		return
 	}
+	m.logDebug("Telegram reply accepted from authorized user", zap.String("request_id", state.request.RequestID))
 
 	money, reason, err := parseConfirmationReply(message.Text)
 	if err != nil {
+		m.logInfo("Telegram reply requires clarification",
+			zap.String("request_id", state.request.RequestID),
+			zap.String("reason", reason),
+			zap.Error(err))
 		m.mu.Lock()
 		state.clarified = true
 		m.mu.Unlock()
@@ -189,6 +284,11 @@ func (m *confirmationManager) HandleUpdate(ctx context.Context, update *telegram
 	if clarified {
 		status = model.ConfirmationStatusClarified
 	}
+	m.logInfo("Telegram confirmation parsed",
+		zap.String("request_id", state.request.RequestID),
+		zap.String("status", string(status)),
+		zap.String("amount", money.Amount),
+		zap.String("currency", money.Currency))
 	m.publishResult(state, &model.ConfirmationResult{
 		RequestID: state.request.RequestID,
 		Money:     money,
@@ -199,16 +299,43 @@ func (m *confirmationManager) HandleUpdate(ctx context.Context, update *telegram
 }
 
 func (m *confirmationManager) lookupByMessageID(messageID string) *confirmationState {
+	if m == nil {
+		return nil
+	}
+	messageID = strings.TrimSpace(messageID)
+	if messageID == "" {
+		m.logDebug("Pending confirmation lookup skipped: message_id is empty")
+		return nil
+	}
 	m.mu.Lock()
-	defer m.mu.Unlock()
-	return m.pendingByMessage[strings.TrimSpace(messageID)]
+	state := m.pendingByMessage[messageID]
+	pendingCount := len(m.pendingByMessage)
+	m.mu.Unlock()
+	if state == nil {
+		m.logDebug("Pending confirmation not found", zap.String("message_id", messageID), zap.Int("pending_count", pendingCount))
+		return nil
+	}
+	m.logDebug("Pending confirmation found",
+		zap.String("message_id", messageID),
+		zap.String("request_id", state.request.RequestID),
+		zap.Int("pending_count", pendingCount))
+	return state
 }
 
 func (m *confirmationManager) handleTimeout(messageID string) {
-	state := m.lookupByMessageID(messageID)
-	if state == nil {
+	if m == nil {
 		return
 	}
+	messageID = strings.TrimSpace(messageID)
+	m.logInfo("Confirmation timeout triggered", zap.String("message_id", messageID))
+	state := m.lookupByMessageID(messageID)
+	if state == nil {
+		m.logDebug("Confirmation timeout ignored: state not found", zap.String("message_id", messageID))
+		return
+	}
+	m.logInfo("Publishing timeout confirmation result",
+		zap.String("request_id", state.request.RequestID),
+		zap.String("message_id", messageID))
 	m.publishResult(state, &model.ConfirmationResult{
 		RequestID: state.request.RequestID,
 		Status:    model.ConfirmationStatusTimeout,
@@ -217,49 +344,96 @@ func (m *confirmationManager) handleTimeout(messageID string) {
 }
 
 func (m *confirmationManager) removeState(messageID string) {
+	if m == nil {
+		return
+	}
 	messageID = strings.TrimSpace(messageID)
 	if messageID == "" {
+		m.logDebug("State removal skipped: message_id is empty")
 		return
 	}
 	m.mu.Lock()
 	state := m.pendingByMessage[messageID]
 	if state != nil && state.timer != nil {
-		state.timer.Stop()
+		if !state.timer.Stop() {
+			m.logDebug("Confirmation timer already fired before state removal", zap.String("message_id", messageID), zap.String("request_id", state.request.RequestID))
+		}
 	}
 	delete(m.pendingByMessage, messageID)
 	if state != nil {
 		delete(m.pendingByRequest, state.request.RequestID)
 	}
+	pendingCount := len(m.pendingByMessage)
 	m.mu.Unlock()
+	if state == nil {
+		m.logDebug("State removal skipped: no state for message", zap.String("message_id", messageID), zap.Int("pending_count", pendingCount))
+		return
+	}
+	m.logInfo("Confirmation state removed",
+		zap.String("message_id", messageID),
+		zap.String("request_id", state.request.RequestID),
+		zap.Int("pending_count", pendingCount))
 }
 
 func (m *confirmationManager) publishResult(state *confirmationState, result *model.ConfirmationResult) {
 	if m == nil || state == nil || result == nil {
+		m.logDebug("Confirmation result publish skipped: missing context",
+			zap.Bool("state_nil", state == nil),
+			zap.Bool("result_nil", result == nil))
 		return
 	}
+	m.logDebug("Publishing confirmation result",
+		zap.String("request_id", state.request.RequestID),
+		zap.String("status", string(result.Status)),
+		zap.String("callback_subject", state.callbackSubject))
 	if m.outbox == nil {
-		m.logger.Warn("Confirmation result skipped: producer not configured", zap.String("request_id", state.request.RequestID))
+		m.logWarn("Confirmation result skipped: producer not configured",
+			zap.String("request_id", state.request.RequestID),
+			zap.String("callback_subject", state.callbackSubject))
 		return
 	}
 	env := confirmations.ConfirmationResult(m.sender, result, state.request.SourceService, state.request.Rail)
+	m.logDebug("Confirmation result envelope prepared",
+		zap.String("request_id", state.request.RequestID),
+		zap.String("sender", m.sender),
+		zap.String("source_service", state.request.SourceService),
+		zap.String("rail", state.request.Rail))
 	if err := m.outbox.SendMessage(env); err != nil {
-		m.logger.Warn("Failed to publish confirmation result", zap.Error(err), zap.String("request_id", state.request.RequestID))
+		m.logWarn("Failed to publish confirmation result", zap.Error(err), zap.String("request_id", state.request.RequestID), zap.String("callback_subject", state.callbackSubject))
 		return
 	}
-	m.logger.Info("Confirmation result published", zap.String("request_id", state.request.RequestID), zap.String("status", string(result.Status)))
+	m.logInfo("Confirmation result published",
+		zap.String("request_id", state.request.RequestID),
+		zap.String("status", string(result.Status)),
+		zap.String("callback_subject", state.callbackSubject))
 }
 
 func (m *confirmationManager) sendNotice(ctx context.Context, state *confirmationState, reply *model.TelegramMessage, text string) {
-	if m == nil || m.tg == nil || state == nil {
+	if m == nil {
+		return
+	}
+	if m.tg == nil {
+		m.logWarn("Clarification notice skipped: telegram client is not configured")
+		return
+	}
+	if state == nil {
+		m.logDebug("Clarification notice skipped: state is nil")
 		return
 	}
 	replyID := ""
 	if reply != nil {
 		replyID = reply.MessageID
 	}
+	m.logDebug("Sending clarification notice",
+		zap.String("request_id", state.request.RequestID),
+		zap.String("target_chat_id", state.targetChatID),
+		zap.String("reply_to_message_id", replyID),
+		zap.Int("text_length", len(text)))
 	if _, err := m.tg.SendText(ctx, state.targetChatID, text, replyID); err != nil {
-		m.logger.Warn("Failed to send clarification notice", zap.Error(err), zap.String("request_id", state.request.RequestID))
+		m.logWarn("Failed to send clarification notice", zap.Error(err), zap.String("request_id", state.request.RequestID))
+		return
 	}
+	m.logInfo("Clarification notice sent", zap.String("request_id", state.request.RequestID), zap.String("target_chat_id", state.targetChatID))
 }
 
 func (s *confirmationState) isUserAllowed(user *telegram.User) bool {