diff --git a/lib/kconsumer/consumer.go b/lib/kconsumer/consumer.go index 7fff71e..d33403e 100644 --- a/lib/kconsumer/consumer.go +++ b/lib/kconsumer/consumer.go @@ -14,7 +14,7 @@ import ( "go.opentelemetry.io/otel/trace" ) -// The default time that the kafka consumer polls for a new message before +// DefaultPollTimeout is default time that the kafka consumer polls for a new message before // it checks the context for cancellation. var DefaultPollTimeout = 100 * time.Millisecond @@ -43,6 +43,15 @@ type partitionWorker struct { errCh chan error } +// Consume subscribes to the configured topics and dispatches every consumed +// message to handle. Each assigned partition is processed by its own worker +// goroutine, so messages within a partition are handled in order while +// different partitions run concurrently. +// +// Offsets are stored only after a message was handled successfully and are +// flushed to the broker roughly every five seconds (and once more on +// shutdown). Consume blocks until ctx is canceled or a worker fails, in +// which case it shuts the workers down and returns an error. func (c *PartitionConsumer) Consume(ctx context.Context, handle HandleMessage) error { if err := c.Consumer.SubscribeTopics(c.Topics, nil); err != nil { return fmt.Errorf("subscribe to %v: %w", c.Topics, err) @@ -53,6 +62,8 @@ func (c *PartitionConsumer) Consume(ctx context.Context, handle HandleMessage) e Workers: map[int32]*partitionWorker{}, } + defer workers.Shutdown() + slog.Info("Partition consumer started", slog.Any("topics", c.Topics)) lastStored := time.Now() @@ -60,8 +71,6 @@ func (c *PartitionConsumer) Consume(ctx context.Context, handle HandleMessage) e for { if err := ctx.Err(); err != nil { slog.Info("Context closed, shutting consumer down", sl.Error(err)) - workers.Shutdown() - return fmt.Errorf("context: %w", err) } diff --git a/lib/kconsumer/run.go b/lib/kconsumer/run.go new file mode 100644 index 0000000..49ee696 --- /dev/null +++ b/lib/kconsumer/run.go @@ -0,0 +1,50 @@ +package kconsumer + +import ( + "context" + "log/slog" + "runtime/debug" + "time" + + sl "github.com/flachnetz/startup/v2/startup_logging" +) + +// RunConsumer runs partitionConsumer in a supervision loop that keeps it alive +// across failures. If Consume returns an error or panics, the panic is +// recovered, its stack is printed, and the consumer is restarted after a short +// delay. The loop only stops when ctx is canceled or the underlying kafka +// consumer is closed. +func RunConsumer(ctx context.Context, partitionConsumer *PartitionConsumer, handler HandleMessage) { + log := sl.LoggerOf(ctx) + + for { + func() { + defer func() { + if r := recover(); r != nil { + log.ErrorContext(ctx, "Consumer panicked, restarting", slog.Any("panic", r)) + + // printing the stack makes debugging easier + debug.PrintStack() + } + }() + + slog.InfoContext(ctx, "Starting kafka consumer", slog.Any("handler", handler)) + err := partitionConsumer.Consume(ctx, handler) + if err != nil { + log.ErrorContext(ctx, "Consumer stopped with error, restarting", slog.String("error", err.Error())) + } + }() + + if err := ctx.Err(); err != nil { + log.InfoContext(ctx, "Stopping consumer, Context is close", sl.Error(err)) + return + } + + if partitionConsumer.Consumer.IsClosed() { + log.InfoContext(ctx, "Stopping consumer, underlying kafka consumer is close") + return + } + + time.Sleep(5 * time.Second) + } +} diff --git a/lib/testx/kafka.go b/lib/testx/kafka.go index 79fac21..f9c988c 100644 --- a/lib/testx/kafka.go +++ b/lib/testx/kafka.go @@ -33,7 +33,10 @@ func KafkaCluster(t *testing.T) *Kafka { t.Cleanup(cluster.Close) // create a kafka producer - config := &kafka.ConfigMap{"bootstrap.servers": cluster.BootstrapServers()} + servers := cluster.BootstrapServers() + require.NotEmpty(t, servers) + + config := &kafka.ConfigMap{"bootstrap.servers": servers} producer, err := kafka.NewProducer(config) require.NoError(t, err) diff --git a/startup_logging/resty.go b/startup_logging/resty.go index 0a8be38..6fb1d3f 100644 --- a/startup_logging/resty.go +++ b/startup_logging/resty.go @@ -1,23 +1,41 @@ package sl import ( + "context" "fmt" "log/slog" + "strings" ) // RestyAdapter bridges resty.Logger to *slog.Logger. type RestyAdapter struct { - Logger *slog.Logger + Logger *slog.Logger + Multiline bool } func (a RestyAdapter) Errorf(format string, v ...any) { - a.Logger.Error(fmt.Sprintf(format, v...)) + a.log(slog.LevelError, format, v...) } func (a RestyAdapter) Warnf(format string, v ...any) { - a.Logger.Warn(fmt.Sprintf(format, v...)) + a.log(slog.LevelWarn, format, v...) } func (a RestyAdapter) Debugf(format string, v ...any) { - a.Logger.Debug(fmt.Sprintf(format, v...)) + a.log(slog.LevelDebug, format, v...) +} + +// log formats the message and may emit one log record per line. resty often logs +// multi-line request/response dumps in a single call, which we split here so +// each line becomes its own log entry. +func (a RestyAdapter) log(level slog.Level, format string, v ...any) { + msg := fmt.Sprintf(format, v...) + + if a.Multiline { + for line := range strings.SplitSeq(strings.TrimRight(msg, "\n"), "\n") { + a.Logger.Log(context.Background(), level, line) + } + } else { + a.Logger.Log(context.Background(), level, msg) + } }