🔧 Update Go version in go.mod and enhance build process with versioning information. Modify Makefile and Taskfile to inject build metadata (version, commit, build time) into the binary. Improve README with instructions for custom version builds and document new build info features. Add benchmarks for message parsing and processing to improve performance testing capabilities.

2025-11-18 14:15:58 +08:00
parent 7f44b5389d
commit 06fc9cb9e0
27 changed files with 3009 additions and 55 deletions
@@ -3,6 +3,8 @@ package nats
 import (
 	"caatsm/internal/app"
 	"caatsm/internal/infra/config"
+	"caatsm/internal/infra/log"
+	obsmetrics "caatsm/internal/infra/metrics"
 	"caatsm/internal/infra/telemetry"
 	"context"
 	"encoding/json"
@@ -11,7 +13,11 @@ import (
 	"strings"
 	"time"

+	"github.com/google/uuid"
 	"github.com/nats-io/nats.go"
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/codes"
 	"go.opentelemetry.io/otel/metric"
 	"go.uber.org/zap"
 )
@@ -167,7 +173,9 @@ func (f *defaultMessageFetcher) HandleFetchError(ctx context.Context, err error,
 		)
 		// Connection closed is fatal - cannot recover subscription
 		if *sub != nil {
-			(*sub).Unsubscribe()
+			if err := (*sub).Unsubscribe(); err != nil {
+				f.logger.Error("Failed to unsubscribe after connection closed", zap.Error(err))
+			}
 			*sub = nil
 		}
 		return false, fmt.Errorf("connection closed: %w", err)
@@ -209,7 +217,9 @@ func (f *defaultMessageFetcher) HandleFetchError(ctx context.Context, err error,
 			}
 			// Unsubscribe old subscription before creating new one
 			if *sub != nil {
-				(*sub).Unsubscribe()
+				if err := (*sub).Unsubscribe(); err != nil {
+					f.logger.Error("Failed to unsubscribe during recovery", zap.Error(err))
+				}
 			}
 			// Create new subscription
 			newSub, subErr := f.consumerManager.CreatePullSubscription()
@@ -229,7 +239,9 @@ func (f *defaultMessageFetcher) HandleFetchError(ctx context.Context, err error,
 			zap.String("consumer", f.config.consumerName),
 		)
 		if *sub != nil {
-			(*sub).Unsubscribe()
+			if err := (*sub).Unsubscribe(); err != nil {
+				f.logger.Error("Failed to unsubscribe after resource not found", zap.Error(err))
+			}
 			*sub = nil
 		}
 		return false, fmt.Errorf("JetStream resource not found: %w", err)
@@ -322,7 +334,9 @@ func (f *defaultMessageFetcher) attemptSubscriptionRecovery(ctx context.Context,

 	// Unsubscribe old subscription if it exists
 	if *sub != nil {
-		(*sub).Unsubscribe()
+		if err := (*sub).Unsubscribe(); err != nil {
+			f.logger.Error("Failed to unsubscribe during recovery", zap.Error(err))
+		}
 		*sub = nil
 	}

@@ -368,10 +382,238 @@ type defaultBatchProcessor struct {
 	errorHandler *ErrorHandler
 	logger       *zap.Logger
 	telemetry    telemetry.Recorder
+	// Configuration needed for processing
+	streamName   string
+	consumerName string
+	mode         string
+	backoff      []time.Duration
+	// Pointer to consecutive errors counter (shared with Consumer)
+	consecutiveProcessErrors *int
 }

 func (p *defaultBatchProcessor) ProcessBatch(ctx context.Context, msgs []*nats.Msg) {
-	// This will be implemented when we refactor the batch processing
+	for _, msg := range msgs {
+		// Check context before processing each message
+		select {
+		case <-ctx.Done():
+			p.logger.Info("Stopping batch processing due to cancellation",
+				zap.Int("remaining_messages", len(msgs)),
+			)
+			return
+		default:
+		}
+		p.processSingleMessage(ctx, msg)
+	}
+}
+
+// processSingleMessage processes a single message with error handling and backpressure.
+func (p *defaultBatchProcessor) processSingleMessage(ctx context.Context, msg *nats.Msg) {
+	start := time.Now()
+
+	if err := p.processMessage(ctx, msg); err != nil {
+		p.handleMessageError(ctx, msg, err, time.Since(start))
+		return
+	}
+
+	// Successful processing resets the error streak.
+	if p.consecutiveProcessErrors != nil && *p.consecutiveProcessErrors > 0 {
+		*p.consecutiveProcessErrors = 0
+	}
+
+	// ACK the message
+	if ackErr := msg.Ack(); ackErr != nil {
+		p.logger.Error("Failed to ACK message", zap.Error(ackErr))
+	} else {
+		elapsed := time.Since(start)
+		p.telemetry.RecordMessageHandled(ctx, p.streamName, p.consumerName, "ok", elapsed)
+	}
+}
+
+// processMessage processes a single message.
+func (p *defaultBatchProcessor) processMessage(ctx context.Context, msg *nats.Msg) error {
+	ctx, span := otel.Tracer("caatsm/nats").Start(ctx, "Consumer.processMessage")
+	defer span.End()
+
+	// Set semantic messaging attributes
+	span.SetAttributes(
+		attribute.String("messaging.system", "nats"),
+		attribute.String("messaging.operation.name", "receive"),
+		attribute.String("messaging.destination.name", msg.Subject),
+		attribute.String("messaging.consumer.group.name", p.consumerName),
+		attribute.String("caatsm.stream", p.streamName),
+	)
+
+	msgID, source, err := p.resolveMsgID(msg)
+	if err != nil {
+		span.RecordError(err)
+		span.SetStatus(codes.Error, err.Error())
+		return fmt.Errorf("unable to resolve message id: %w", err)
+	}
+	if source != "header" {
+		p.logger.Warn("Message missing NATS id header; using fallback",
+			zap.String("subject", msg.Subject),
+			zap.String("msg_id_source", source),
+			zap.String("msg_id", msgID),
+		)
+	}
+
+	// Attach structured logging context including stream/consumer and NATS metadata.
+	jsSeq := uint64(0)
+	if meta, metaErr := msg.Metadata(); metaErr == nil {
+		jsSeq = meta.Sequence.Stream
+		span.SetAttributes(
+			attribute.Int64("nats.js.stream_seq", int64(meta.Sequence.Stream)),
+			attribute.Int64("nats.js.consumer_seq", int64(meta.Sequence.Consumer)),
+		)
+	}
+
+	msgLogger := log.WithMessageContext(p.logger, log.MessageFields{
+		Service:        "caatsm-consumer",
+		TransportMsgID: msgID,
+		Stream:         p.streamName,
+		Consumer:       p.consumerName,
+		Subject:        msg.Subject,
+		JSSequence:     jsSeq,
+	})
+
+	msgLogger.Debug("Processing message",
+		zap.Int("data_size", len(msg.Data)),
+		zap.String("msg_id_source", source),
+	)
+
+	// Call processor
+	if err := p.processor.Handle(ctx, msg.Data, msgID); err != nil {
+		span.RecordError(err)
+		span.SetStatus(codes.Error, err.Error())
+		return fmt.Errorf("processor error: %w", err)
+	}
+
+	span.SetAttributes(attribute.String("telegram.msg_id", msgID))
+	return nil
+}
+
+// resolveMsgID extracts or generates a message ID.
+func (p *defaultBatchProcessor) resolveMsgID(msg *nats.Msg) (string, string, error) {
+	if id := msg.Header.Get("Nats-Msg-Id"); id != "" {
+		return id, "header", nil
+	}
+
+	if p.mode == "core" {
+		return uuid.NewString(), "generated", nil
+	}
+
+	meta, err := msg.Metadata()
+	if err != nil {
+		return "", "", fmt.Errorf("fetch metadata: %w", err)
+	}
+
+	return fmt.Sprintf("js-%d", meta.Sequence.Stream), "metadata", nil
+}
+
+// handleMessageError handles errors that occur during message processing.
+func (p *defaultBatchProcessor) handleMessageError(ctx context.Context, msg *nats.Msg, err error, elapsed time.Duration) {
+	p.logger.Error("Failed to process message",
+		zap.String("subject", msg.Subject),
+		zap.Error(err),
+		zap.Bool("permanent", app.IsPermanent(err)),
+	)
+
+	result := obsmetrics.ResultFail
+	if app.IsPermanent(err) {
+		result = obsmetrics.ResultPermanentFail
+	}
+	p.telemetry.RecordMessageHandled(ctx, p.streamName, p.consumerName, result, elapsed)
+
+	consecutiveErrors := 0
+	if p.consecutiveProcessErrors != nil {
+		consecutiveErrors = *p.consecutiveProcessErrors
+	}
+
+	processingResult := p.errorHandler.HandleProcessingError(consecutiveErrors, err, p.logger, msg.Subject)
+
+	if processingResult.IsPermanent {
+		p.handlePermanentError(ctx, msg, err)
+		return
+	}
+
+	p.handleTransientError(ctx, msg, processingResult)
+}
+
+// handlePermanentError handles permanent/poison messages.
+func (p *defaultBatchProcessor) handlePermanentError(ctx context.Context, msg *nats.Msg, err error) {
+	if p.consecutiveProcessErrors != nil {
+		*p.consecutiveProcessErrors = 0
+	}
+	// Poison/permanent message: route to DLQ if configured, then ACK
+	if p.dlqHandler != nil {
+		if dlqErr := p.dlqHandler.RouteToDLQ(ctx, msg, err); dlqErr != nil {
+			p.logger.Error("Failed to route permanent-error message to DLQ", zap.Error(dlqErr))
+		}
+	}
+	if ackErr := msg.Ack(); ackErr != nil {
+		p.logger.Error("Failed to ACK permanent-error message", zap.Error(ackErr))
+	}
+}
+
+// handleTransientError handles transient errors with backpressure and redelivery.
+func (p *defaultBatchProcessor) handleTransientError(ctx context.Context, msg *nats.Msg, processingResult ProcessingErrorResult) {
+	// Increment error streak
+	if p.consecutiveProcessErrors != nil {
+		if *p.consecutiveProcessErrors < 0 {
+			*p.consecutiveProcessErrors = 0
+		}
+		*p.consecutiveProcessErrors++
+	}
+
+	if processingResult.ShouldApplyBackpressure {
+		consecutiveErrors := 0
+		if p.consecutiveProcessErrors != nil {
+			consecutiveErrors = *p.consecutiveProcessErrors
+		}
+		p.logger.Warn("Applying backpressure due to consecutive processing errors",
+			zap.Int("consecutive_errors", consecutiveErrors),
+			zap.Duration("sleep", processingResult.BackpressureDelay),
+		)
+		// Use context-aware sleep instead of blocking time.Sleep
+		if !sleepWithContext(ctx, processingResult.BackpressureDelay) {
+			// Context canceled, stop processing
+			return
+		}
+	}
+
+	// Transient error: request redelivery with optional delay
+	p.telemetry.RecordRetry(ctx, p.streamName, p.consumerName, obsmetrics.RetryReasonProcessorError)
+	if nakErr := p.nakWithStrategy(msg); nakErr != nil {
+		p.logger.Error("Failed to NAK message", zap.Error(nakErr))
+	}
+}
+
+// nakWithStrategy sends a NAK with appropriate delay based on retry attempt.
+func (p *defaultBatchProcessor) nakWithStrategy(msg *nats.Msg) error {
+	if len(p.backoff) == 0 {
+		return msg.Nak()
+	}
+
+	meta, err := msg.Metadata()
+	if err != nil {
+		p.logger.Warn("Failed to read metadata for backoff strategy", zap.Error(err))
+		return msg.Nak()
+	}
+
+	attempt := int(meta.NumDelivered)
+	index := attempt - 1
+	if index < 0 {
+		index = 0
+	}
+	if index >= len(p.backoff) {
+		index = len(p.backoff) - 1
+	}
+	delay := p.backoff[index]
+	if delay <= 0 {
+		return msg.Nak()
+	}
+
+	return msg.NakWithDelay(delay)
 }

 // defaultDLQHandler implements DLQHandler interface
@@ -454,14 +696,7 @@ func (c *Consumer) initCollaborators() {
 		cfg:             c.cfg,
 	}

-	c.batchProcessor = &defaultBatchProcessor{
-		processor:    c.processor,
-		dlqHandler:   c.dlqHandler,
-		errorHandler: c.errorHandler,
-		logger:       c.logger,
-		telemetry:    c.telemetry,
-	}
-
+	// Initialize DLQ handler first if needed, so batch processor can reference it
 	if c.config.dlqSubject != "" {
 		c.dlqHandler = &defaultDLQHandler{
 			js:           c.js,
@@ -472,6 +707,19 @@ func (c *Consumer) initCollaborators() {
 			telemetry:    c.telemetry,
 		}
 	}
+
+	c.batchProcessor = &defaultBatchProcessor{
+		processor:                c.processor,
+		dlqHandler:               c.dlqHandler,
+		errorHandler:             c.errorHandler,
+		logger:                   c.logger,
+		telemetry:                c.telemetry,
+		streamName:               c.config.streamName,
+		consumerName:             c.config.consumerName,
+		mode:                     c.config.mode,
+		backoff:                  c.cfg.NATS.ConsumerRules.Backoff,
+		consecutiveProcessErrors: &c.consecutiveProcessErrors,
+	}
 }

 // normalizeConsumerConfig extracts and normalizes consumer configuration from the application config.