feat: Better prometheus support (#1056)

docs/modules/ROOT/pages/advanced_configuration/prometheus.adoc

@@ -25,16 +25,60 @@ This will give you metrics available at http://yourserver:1337/metrics. The page
 [source]
 ----
 # HELP olivetin_actions_requested_count The actions requested count
-# TYPE olivetin_actions_requested_count gauge
+# TYPE olivetin_actions_requested_count counter
 olivetin_actions_requested_count 0
+# HELP olivetin_action_executions_total Total number of finished action executions grouped by result.
+# TYPE olivetin_action_executions_total counter
+olivetin_action_executions_total{result="success"} 0
+olivetin_action_executions_total{result="failed"} 0
+olivetin_action_executions_total{result="blocked"} 0
+olivetin_action_executions_total{result="timeout"} 0
+olivetin_action_executions_total{result="error"} 0
+# HELP olivetin_action_execution_duration_seconds Action execution duration in seconds from start to finish.
+# TYPE olivetin_action_execution_duration_seconds histogram
+olivetin_action_execution_duration_seconds_bucket{le="0.1"} 0
 # HELP olivetin_config_action_count Then number of actions in the config file
 # TYPE olivetin_config_action_count gauge
 olivetin_config_action_count 18
 # HELP olivetin_config_reloaded_count The number of times the config has been reloaded
 # TYPE olivetin_config_reloaded_count counter
 olivetin_config_reloaded_count 1
-# HELP olivetin_sv_count The number entries in the sv map
+----
-# TYPE olivetin_sv_count gauge
+
-olivetin_sv_count 49
+=== Failed job monitoring
+
+Finished action executions are counted in `olivetin_action_executions_total` with a `result` label:
+
+[cols="1,2"]
+|===
+| `success` | Command finished with exit code 0
+| `failed` | Command ran but exited with a non-zero code
+| `timeout` | Command exceeded its configured timeout
+| `blocked` | Execution was blocked (ACL, rate limit, concurrency, or queue limit)
+| `error` | Execution failed before the command ran (for example, invalid arguments)
+|===
+
+`olivetin_action_execution_duration_seconds` records how long each finished execution took.
+
+Example Prometheus alert rules:
+
+[source,yaml]
+----
+groups:
+  - name: olivetin
+    rules:
+      - alert: OliveTinActionFailed
+        expr: increase(olivetin_action_executions_total{result="failed"}[15m]) > 0
+        labels:
+          severity: warning
+        annotations:
+          summary: OliveTin action failed with non-zero exit code
+
+      - alert: OliveTinActionTimedOut
+        expr: increase(olivetin_action_executions_total{result="timeout"}[15m]) > 0
+        labels:
+          severity: warning
+        annotations:
+          summary: OliveTin action timed out
 ----
 

integration-tests/tests/prometheus/prometheus.mjs

@@ -8,6 +8,8 @@ import {
 
 let metrics = [
   {'name': 'olivetin_actions_requested_count', 'type': 'counter', 'desc': 'The actions requested count'},
+  {'name': 'olivetin_action_executions_total', 'type': 'counter', 'desc': 'Total number of finished action executions grouped by result\\.'},
+  {'name': 'olivetin_action_execution_duration_seconds', 'type': 'histogram', 'desc': 'Action execution duration in seconds from start to finish\\.'},
   {'name': 'olivetin_config_action_count', 'type': 'gauge', 'desc': 'The number of actions in the config file'},
   {'name': 'olivetin_config_reloaded_count', 'type': 'counter', 'desc': 'The number of times the config has been reloaded'},
 ]

service/internal/executor/executor.go

@@ -11,8 +11,6 @@ import (
 	"github.com/google/uuid"
 	log "github.com/sirupsen/logrus"
 
-	"github.com/prometheus/client_golang/prometheus"
-	"github.com/prometheus/client_golang/prometheus/promauto"
 	"gopkg.in/yaml.v3"
 
 	"bytes"
@@ -40,13 +38,6 @@ func isValidTrackingID(id string) bool {
 	return id != "" && len(id) <= MaxTrackingIDLength && validTrackingIDPattern.MatchString(id)
 }
 
-var (
-	metricActionsRequested = promauto.NewCounter(prometheus.CounterOpts{
-		Name: "olivetin_actions_requested_count",
-		Help: "The actions requested count",
-	})
-)
-
 type ActionBinding struct {
 	ID           string
 	Action       *config.Action
@@ -706,6 +697,8 @@ func (e *Executor) finishExecChain(req *ExecutionRequest) {
 		entry.ExecutionFinished = true
 	})
 
+	recordExecutionMetrics(req.logEntry)
+
 	notifyListenersFinished(req)
 	e.drainGroupQueue()
 }

service/internal/executor/group_concurrency_test.go

@@ -508,36 +508,33 @@ func TestGroupQueueBlocksWhenQueueFull(t *testing.T) {
 		},
 	)
 
-	trackings, waitGroups := execAllGroupActions(t, e, cfg, actions)
+	wg1, tracking1 := e.ExecRequest(&ExecutionRequest{
+		Binding:           e.FindBindingWithNoEntity(actions[0]),
+		Cfg:               cfg,
+		AuthenticatedUser: auth.UserFromSystem(cfg, "testuser"),
+	})
+	waitUntilExecutionStarted(t, e, tracking1)
 
-	require.Eventually(t, func() bool {
+	trackings := []string{tracking1}
-		return countSnapshots(e, trackings, func(snapshot LogEntrySnapshot) bool { return snapshot.Blocked }) == 1 &&
+	waitGroups := []*sync.WaitGroup{wg1}
-			countSnapshots(e, trackings, func(snapshot LogEntrySnapshot) bool { return snapshot.Queued }) == 2 &&
-			countSnapshots(e, trackings, isRunningSnapshot) == 1
-	}, 2*time.Second, 20*time.Millisecond)
 
-	for _, wg := range waitGroups {
+	for _, action := range actions[1:] {
-		wg.Wait()
-	}
-}
-
-func execAllGroupActions(t *testing.T, e *Executor, cfg *config.Config, actions []*config.Action) ([]string, []*sync.WaitGroup) {
-	t.Helper()
-
-	trackings := make([]string, len(actions))
-	waitGroups := make([]*sync.WaitGroup, len(actions))
-
-	for idx, action := range actions {
 		wg, tracking := e.ExecRequest(&ExecutionRequest{
 			Binding:           e.FindBindingWithNoEntity(action),
 			Cfg:               cfg,
 			AuthenticatedUser: auth.UserFromSystem(cfg, "testuser"),
 		})
-		trackings[idx] = tracking
+		trackings = append(trackings, tracking)
-		waitGroups[idx] = wg
+		waitGroups = append(waitGroups, wg)
 	}
 
-	return trackings, waitGroups
+	require.Eventually(t, func() bool {
+		return groupExecutionDistributionMatches(e, trackings, 1, 2, 1)
+	}, 2*time.Second, 20*time.Millisecond)
+
+	for _, wg := range waitGroups {
+		wg.Wait()
+	}
 }
 
 func groupExecutionDistributionMatches(e *Executor, trackings []string, wantRunning, wantQueued, wantBlocked int) bool {

service/internal/executor/prometheus.go

@@ -0,0 +1,95 @@
+package executor
+
+import (
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+)
+
+const (
+	executionResultSuccess = "success"
+	executionResultFailed  = "failed"
+	executionResultBlocked = "blocked"
+	executionResultTimeout = "timeout"
+	executionResultError   = "error"
+)
+
+var (
+	metricActionsRequested = promauto.NewCounter(prometheus.CounterOpts{
+		Name: "olivetin_actions_requested_count",
+		Help: "The actions requested count",
+	})
+
+	metricActionExecutionsTotal = promauto.NewCounterVec(prometheus.CounterOpts{
+		Name: "olivetin_action_executions_total",
+		Help: "Total number of finished action executions grouped by result.",
+	}, []string{"result"})
+
+	metricActionExecutionDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+		Name:    "olivetin_action_execution_duration_seconds",
+		Help:    "Action execution duration in seconds from start to finish.",
+		Buckets: []float64{0.1, 0.5, 1, 2, 5, 10, 30, 60, 120, 300, 600},
+	})
+
+	executionResultLabels = []string{
+		executionResultSuccess,
+		executionResultFailed,
+		executionResultBlocked,
+		executionResultTimeout,
+		executionResultError,
+	}
+)
+
+func init() {
+	for _, result := range executionResultLabels {
+		metricActionExecutionsTotal.WithLabelValues(result)
+	}
+}
+
+func executionResultLabel(entry *InternalLogEntry) string {
+	if entry.Blocked {
+		return executionResultBlocked
+	}
+
+	return finishedExecutionResultLabel(entry)
+}
+
+func finishedExecutionResultLabel(entry *InternalLogEntry) string {
+	if entry.TimedOut {
+		return executionResultTimeout
+	}
+
+	switch {
+	case entry.ExitCode == 0:
+		return executionResultSuccess
+	case isPreExecutionError(entry):
+		return executionResultError
+	default:
+		return executionResultFailed
+	}
+}
+
+func isPreExecutionError(entry *InternalLogEntry) bool {
+	return entry.ExitCode == DefaultExitCodeNotExecuted || !entry.ExecutionStarted
+}
+
+func recordExecutionMetrics(entry *InternalLogEntry) {
+	if entry == nil || entry.Queued {
+		return
+	}
+
+	metricActionExecutionsTotal.WithLabelValues(executionResultLabel(entry)).Inc()
+	recordExecutionDuration(entry)
+}
+
+func recordExecutionDuration(entry *InternalLogEntry) {
+	if entry.DatetimeFinished.IsZero() || entry.DatetimeStarted.IsZero() {
+		return
+	}
+
+	duration := entry.DatetimeFinished.Sub(entry.DatetimeStarted).Seconds()
+	if duration < 0 {
+		return
+	}
+
+	metricActionExecutionDuration.Observe(duration)
+}

service/internal/executor/prometheus_test.go

@@ -0,0 +1,76 @@
+package executor
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestExecutionResultLabel(t *testing.T) {
+	tests := []struct {
+		name  string
+		entry *InternalLogEntry
+		want  string
+	}{
+		{
+			name: "success",
+			entry: &InternalLogEntry{
+				ExecutionStarted:  true,
+				ExecutionFinished: true,
+				ExitCode:          0,
+			},
+			want: executionResultSuccess,
+		},
+		{
+			name: "failed nonzero exit",
+			entry: &InternalLogEntry{
+				ExecutionStarted:  true,
+				ExecutionFinished: true,
+				ExitCode:          1,
+			},
+			want: executionResultFailed,
+		},
+		{
+			name: "blocked",
+			entry: &InternalLogEntry{
+				Blocked:           true,
+				ExecutionFinished: true,
+				ExitCode:          0,
+			},
+			want: executionResultBlocked,
+		},
+		{
+			name: "timeout",
+			entry: &InternalLogEntry{
+				ExecutionStarted:  true,
+				ExecutionFinished: true,
+				TimedOut:          true,
+				ExitCode:          -1,
+			},
+			want: executionResultTimeout,
+		},
+		{
+			name: "error before execution",
+			entry: &InternalLogEntry{
+				ExecutionFinished: true,
+				ExitCode:          DefaultExitCodeNotExecuted,
+			},
+			want: executionResultError,
+		},
+		{
+			name: "error never started",
+			entry: &InternalLogEntry{
+				ExecutionStarted:  false,
+				ExecutionFinished: true,
+				ExitCode:          2,
+			},
+			want: executionResultError,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			assert.Equal(t, tt.want, executionResultLabel(tt.entry))
+		})
+	}
+}