fix: eliminate concurrency races (#1117)

.github/workflows/race.yml

@@ -0,0 +1,36 @@
+name: Go race detector
+
+on:
+  push:
+    branches:
+      - main
+      - next
+    paths:
+      - '.github/workflows/race.yml'
+      - 'service/**'
+  pull_request:
+    branches:
+      - next
+    paths:
+      - '.github/workflows/race.yml'
+      - 'service/**'
+
+permissions:
+  contents: read
+
+jobs:
+  race:
+    runs-on: ubuntu-latest
+    steps:
+      - name: Checkout
+        uses: actions/checkout@v4
+
+      - name: Setup Go
+        uses: actions/setup-go@v5
+        with:
+          go-version-file: 'service/go.mod'
+          cache: true
+          cache-dependency-path: 'service/go.mod'
+
+      - name: Run race detector
+        run: make -wC service unittests-race

service/Makefile

@@ -44,6 +44,9 @@ unittests:
 unittests-fast:
 	go test ./... -count=1
 
+unittests-race:
+	go test -race ./... -count=1
+
 find-flakey-tests:
 	echo "Running unittests-fast infinitely"
 	sh -c "while $(MAKE) unittests-fast; do :; done"
@@ -54,7 +57,7 @@ find-flakey-tests-inf:
 go-tools:
 	go install "github.com/golangci/golangci-lint/v2/cmd/golangci-lint@v2.13.2"
 
-.PHONY: codestyle go-tools unittests unittests-fast find-flakey-tests find-flakey-tests-inf
+.PHONY: codestyle go-tools unittests unittests-fast unittests-race find-flakey-tests find-flakey-tests-inf
 
 go-tools-all:
 	go install "github.com/bufbuild/buf/cmd/buf"

service/internal/executor/executor.go

@@ -153,6 +153,30 @@ type InternalLogEntry struct {
 	TimedOut            bool
 }
 
+func cloneActionBinding(binding *ActionBinding) *ActionBinding {
+	if binding == nil {
+		return nil
+	}
+
+	cloned := *binding
+	cloned.OnDashboards = slices.Clone(binding.OnDashboards)
+
+	return &cloned
+}
+
+func cloneInternalLogEntry(entry *InternalLogEntry) *InternalLogEntry {
+	if entry == nil {
+		return nil
+	}
+
+	cloned := *entry
+	cloned.Arguments = maps.Clone(entry.Arguments)
+	cloned.Tags = slices.Clone(entry.Tags)
+	cloned.Binding = cloneActionBinding(entry.Binding)
+
+	return &cloned
+}
+
 // .Binding can be nil, so we need to handle that.
 func (e *InternalLogEntry) GetBindingId() string {
 	if e.Binding == nil {
@@ -273,7 +297,7 @@ func (e *Executor) GetLogTrackingIds(startOffset int64, pageCount int64) ([]*Int
 
 	if totalLogCount > 0 {
 		for i := startIndex; i >= endIndex; i-- {
-			trackingIds = append(trackingIds, e.logs[e.logsTrackingIdsByDate[i]])
+			trackingIds = append(trackingIds, cloneInternalLogEntry(e.logs[e.logsTrackingIdsByDate[i]]))
 		}
 	}
 
@@ -303,7 +327,7 @@ func (e *Executor) filterLogsByACL(cfg *config.Config, user *authpublic.Authenti
 		entry := e.logs[trackingId]
 
 		if shouldIncludeLogEntry(cfg, user, entry, filterDate, hasDateFilter) {
-			filtered = append(filtered, entry)
+			filtered = append(filtered, cloneInternalLogEntry(entry))
 		}
 	}
 
@@ -399,26 +423,28 @@ func (e *Executor) GetLogTrackingIdsACL(cfg *config.Config, user *authpublic.Aut
 
 func (e *Executor) GetLog(trackingID string) (*InternalLogEntry, bool) {
 	e.logmutex.RLock()
+	defer e.logmutex.RUnlock()
 
 	entry, found := e.logs[trackingID]
-
-	e.logmutex.RUnlock()
-
-	return entry, found
+	return cloneInternalLogEntry(entry), found
 }
 
 func (e *Executor) GetLogsByBindingId(bindingId string) []*InternalLogEntry {
 	e.logmutex.RLock()
+	defer e.logmutex.RUnlock()
 
 	logs, found := e.LogsByBindingId[bindingId]
 
-	e.logmutex.RUnlock()
-
 	if !found {
 		return make([]*InternalLogEntry, 0)
 	}
 
-	return logs
+	cloned := make([]*InternalLogEntry, 0, len(logs))
+	for _, entry := range logs {
+		cloned = append(cloned, cloneInternalLogEntry(entry))
+	}
+
+	return cloned
 }
 
 // shouldCountExecution checks if a log entry should be counted for rate limiting.

service/internal/executor/executor_test.go

@@ -38,6 +38,39 @@ func testingExecutor() (*Executor, *config.Config) {
 	return e, cfg
 }
 
+func TestGetLogReturnsDefensiveCopy(t *testing.T) {
+	e := DefaultExecutor(config.DefaultConfig())
+	e.logs["tracking-id"] = &InternalLogEntry{
+		Arguments: map[string]string{"message": "original"},
+		Output:    "original",
+		Tags:      []string{"original"},
+		Binding: &ActionBinding{
+			ID: "original-binding",
+			OnDashboards: []DashboardNavigationTarget{
+				{Title: "original"},
+			},
+		},
+	}
+
+	entry, found := e.GetLog("tracking-id")
+	require.True(t, found)
+
+	entry.Arguments["message"] = "changed"
+	entry.Output = "changed"
+	entry.Tags[0] = "changed"
+	entry.Binding.ID = "changed-binding"
+	entry.Binding.OnDashboards[0].Title = "changed"
+
+	stored, found := e.GetLog("tracking-id")
+	require.True(t, found)
+	assert.Equal(t, "original", stored.Arguments["message"])
+	assert.Equal(t, "original", stored.Output)
+	assert.Equal(t, []string{"original"}, stored.Tags)
+	require.NotNil(t, stored.Binding)
+	assert.Equal(t, "original-binding", stored.Binding.ID)
+	assert.Equal(t, []DashboardNavigationTarget{{Title: "original"}}, stored.Binding.OnDashboards)
+}
+
 func TestCreateExecutorAndExec(t *testing.T) {
 	e, cfg := testingExecutor()
 

service/internal/filehelper/file_change_notify.go

@@ -273,13 +273,17 @@ func processDebounce(ctx *watchContext) {
 	if logEntry.callbackComplete || logEntry.callbackWrapper == nil {
 		log.Debugf("fsnotify event callback queued within debounce delay: %v", ctx.filename)
 
+		callback := ctx.callback
+		eventName := ctx.event.Name
 		logEntry.callbackComplete = false
 		logEntry.callbackWrapper = time.AfterFunc(debounceDelay, func() {
-			log.Debugf("fsnotify event callback being fired: %v", ctx.filename)
+			log.Debugf("fsnotify event callback being fired: %v", eventName)
 
-			ctx.callback(ctx.event.Name)
+			callback(eventName)
 
+			debounceWriteLogMutex.Lock()
 			logEntry.callbackComplete = true
+			debounceWriteLogMutex.Unlock()
 		})
 	} else {
 		log.Debugf("fsnotify event suppressed because it's within the debounce delay: %v", ctx.filename)

service/internal/filehelper/file_change_notify_test.go

@@ -0,0 +1,37 @@
+package filehelper
+
+import (
+	"testing"
+	"time"
+
+	"github.com/fsnotify/fsnotify"
+	"github.com/stretchr/testify/require"
+)
+
+func TestProcessDebounceCapturesEventName(t *testing.T) {
+	debounceWriteLogMutex.Lock()
+	debounceWriteLog = make(map[string]*FsNotifyLogEntry)
+	debounceWriteLogMutex.Unlock()
+
+	callbackNames := make(chan string, 1)
+	firstEvent := fsnotify.Event{Name: "first"}
+	ctx := &watchContext{
+		callback: func(filename string) {
+			callbackNames <- filename
+		},
+		event:    &firstEvent,
+		filename: t.Name(),
+	}
+
+	processDebounce(ctx)
+
+	secondEvent := fsnotify.Event{Name: "second"}
+	ctx.event = &secondEvent
+
+	select {
+	case callbackName := <-callbackNames:
+		require.Equal(t, firstEvent.Name, callbackName)
+	case <-time.After(time.Second):
+		t.Fatal("debounced callback did not run")
+	}
+}