Fix duplicate workflow instance and execution ID fields in logs

Co-authored-by: cschleiden <[email protected]>

Author: Copilot

internal/workflowstate/duplicate_fields_test.go

@@ -0,0 +1,71 @@
+package workflowstate
+
+import (
+	"bytes"
+	"log/slog"
+	"strings"
+	"testing"
+
+	"github.com/benbjohnson/clock"
+	"github.com/cschleiden/go-workflows/core"
+	"github.com/cschleiden/go-workflows/internal/log"
+	"github.com/stretchr/testify/assert"
+	"go.opentelemetry.io/otel/trace/noop"
+)
+
+func TestLogFieldDuplication(t *testing.T) {
+	// Create a buffer to capture log output
+	var buf bytes.Buffer
+	
+	// Create JSON logger to easily see field duplication
+	logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
+
+	// Create an instance 
+	instance := &core.WorkflowInstance{
+		InstanceID:  "test-instance-123",
+		ExecutionID: "test-execution-456",
+	}
+
+	// This mimics what happens in executor.go NewExecutor
+	logger = logger.With(
+		slog.String(log.InstanceIDKey, instance.InstanceID),
+		slog.String(log.ExecutionIDKey, instance.ExecutionID),
+	)
+
+	tracer := noop.NewTracerProvider().Tracer("test")
+	clock := clock.New()
+	state := NewWorkflowState(instance, logger, tracer, clock)
+
+	// Log something using the workflow state logger (which currently duplicates fields)
+	state.Logger().Debug("Test message from workflow state")
+	
+	// Parse and analyze the log output
+	logLines := strings.Split(strings.TrimSpace(buf.String()), "\n")
+	
+	foundDuplicates := false
+	for _, line := range logLines {
+		if strings.TrimSpace(line) == "" {
+			continue
+		}
+		
+		t.Logf("Log entry: %s", line)
+		
+		// Count field occurrences in raw JSON string instead of unmarshaling
+		// since JSON unmarshaling overwrites duplicate keys
+		instanceCount := strings.Count(line, `"`+log.InstanceIDKey+`"`)
+		executionCount := strings.Count(line, `"`+log.ExecutionIDKey+`"`)
+		
+		t.Logf("Instance ID field count: %d", instanceCount)
+		t.Logf("Execution ID field count: %d", executionCount)
+		
+		if instanceCount > 1 || executionCount > 1 {
+			foundDuplicates = true
+			t.Logf("❌ DUPLICATE FIELDS DETECTED!")
+		} else {
+			t.Logf("✅ No duplicates found")
+		}
+	}
+	
+	// After fix, we should NOT find duplicates
+	assert.False(t, foundDuplicates, "Should not find duplicate fields after fix")
+}

internal/workflowstate/workflowstate.go

@@ -10,7 +10,6 @@ import (
 	"github.com/cschleiden/go-workflows/backend/payload"
 	"github.com/cschleiden/go-workflows/core"
 	"github.com/cschleiden/go-workflows/internal/command"
-	"github.com/cschleiden/go-workflows/internal/log"
 	"github.com/cschleiden/go-workflows/internal/sync"
 	"go.opentelemetry.io/otel/trace"
 )
@@ -85,9 +84,7 @@ func NewWorkflowState(instance *core.WorkflowInstance, logger *slog.Logger, trac
 		clock: clock,
 	}
 
-	state.logger = NewReplayLogger(state, logger.With(
-		log.InstanceIDKey, instance.InstanceID,
-		log.ExecutionIDKey, instance.ExecutionID))
+	state.logger = NewReplayLogger(state, logger)
 
 	return state
 }

workflow/executor/executor.go

@@ -326,7 +326,7 @@ func (e *executor) executeNewEvents(newEvents []*history.Event) ([]*history.Even
 
 func (e *executor) Close() {
 	if e.workflow != nil {
-		e.logger.Debug("Stopping workflow executor", log.InstanceIDKey, e.workflowState.Instance().InstanceID)
+		e.logger.Debug("Stopping workflow executor")
 
 		// End workflow if running to prevent leaking goroutines
 		e.workflow.Close()
@@ -335,7 +335,6 @@ func (e *executor) Close() {
 
 func (e *executor) executeEvent(event *history.Event) error {
 	fields := []any{
-		log.InstanceIDKey, e.workflowState.Instance().InstanceID,
 		log.EventIDKey, event.ID,
 		log.SeqIDKey, event.SequenceID,
 		log.EventTypeKey, event.Type,