Add guards on timings so we don't publish incorrect metrics (#4621)

This commit is contained in:
Nikola Jokic
2026-09-08 14:32:24 +02:00
committed by GitHub
parent c3dfb396d3
commit f0d0b1d439
2 changed files with 317 additions and 1 deletions
+15 -1
View File
@@ -485,9 +485,17 @@ func (e *exporter) RecordStatistics(stats *scaleset.RunnerScaleSetStatistic) {
}
func (e *exporter) RecordJobStarted(msg *scaleset.JobStarted) {
if msg.RunnerAssignTime.IsZero() {
return
}
l := e.startedJobLabels(msg)
e.incCounter(MetricStartedJobsTotal, l)
if msg.ScaleSetAssignTime.IsZero() || msg.RunnerAssignTime.Before(msg.ScaleSetAssignTime) {
return
}
startupDuration := msg.RunnerAssignTime.Unix() - msg.ScaleSetAssignTime.Unix()
e.observeHistogram(MetricJobStartupDurationSeconds, l, float64(startupDuration))
}
@@ -499,7 +507,13 @@ func (e *exporter) RecordJobCompleted(msg *scaleset.JobCompleted) {
l := e.completedJobLabels(msg)
e.incCounter(MetricCompletedJobsTotal, l)
e.observeHistogram(MetricJobExecutionDurationSeconds, l, float64(msg.FinishTime.Unix()-msg.RunnerAssignTime.Unix()))
if msg.FinishTime.IsZero() || msg.FinishTime.Before(msg.RunnerAssignTime) {
return
}
finishDuration := msg.FinishTime.Unix() - msg.RunnerAssignTime.Unix()
e.observeHistogram(MetricJobExecutionDurationSeconds, l, float64(finishDuration))
}
func (e *exporter) RecordDesiredRunners(count int) {
+302
View File
@@ -3,9 +3,12 @@ package metrics
import (
"log/slog"
"testing"
"time"
"github.com/actions/actions-runner-controller/apis/actions.github.com/v1alpha1"
"github.com/actions/scaleset"
"github.com/prometheus/client_golang/prometheus"
dto "github.com/prometheus/client_model/go"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
@@ -265,3 +268,302 @@ func TestExporterConfigDefaults(t *testing.T) {
assert.Equal(t, want, config)
}
func newTestExporter(t *testing.T, metricsConfig v1alpha1.MetricsConfig) (*exporter, *prometheus.Registry) {
t.Helper()
reg := prometheus.NewRegistry()
m := installMetrics(metricsConfig, reg, discardLogger)
e := &exporter{
scaleSetLabels: prometheus.Labels{
labelKeyEnterprise: "test-enterprise",
labelKeyOrganization: "test-org",
labelKeyRepository: "test-repo",
labelKeyRunnerScaleSetName: "test-scale-set",
labelKeyRunnerScaleSetNamespace: "test-namespace",
},
metrics: m,
}
return e, reg
}
func gatherMetrics(t *testing.T, reg *prometheus.Registry) map[string]*dto.MetricFamily {
t.Helper()
mfs, err := reg.Gather()
require.NoError(t, err)
result := make(map[string]*dto.MetricFamily, len(mfs))
for _, mf := range mfs {
result[mf.GetName()] = mf
}
return result
}
func counterValue(t *testing.T, metrics map[string]*dto.MetricFamily, name string) float64 {
t.Helper()
mf, ok := metrics[name]
if !ok || len(mf.GetMetric()) == 0 {
return 0
}
return mf.GetMetric()[0].GetCounter().GetValue()
}
func histogramSampleCount(t *testing.T, metrics map[string]*dto.MetricFamily, name string) uint64 {
t.Helper()
mf, ok := metrics[name]
if !ok || len(mf.GetMetric()) == 0 {
return 0
}
return mf.GetMetric()[0].GetHistogram().GetSampleCount()
}
func histogramSampleSum(t *testing.T, metrics map[string]*dto.MetricFamily, name string) float64 {
t.Helper()
mf, ok := metrics[name]
if !ok || len(mf.GetMetric()) == 0 {
return 0
}
return mf.GetMetric()[0].GetHistogram().GetSampleSum()
}
func TestRecordJobStarted(t *testing.T) {
startedMetrics := v1alpha1.MetricsConfig{
Counters: map[string]*v1alpha1.CounterMetric{
MetricStartedJobsTotal: {
Labels: []string{
labelKeyEnterprise, labelKeyOrganization, labelKeyRepository,
labelKeyJobName, labelKeyJobWorkflowRef, labelKeyJobWorkflowName,
labelKeyJobWorkflowTarget, labelKeyEventName,
},
},
},
Histograms: map[string]*v1alpha1.HistogramMetric{
MetricJobStartupDurationSeconds: {
Labels: []string{
labelKeyEnterprise, labelKeyOrganization, labelKeyRepository,
labelKeyJobName, labelKeyJobWorkflowRef, labelKeyJobWorkflowName,
labelKeyJobWorkflowTarget, labelKeyEventName,
},
},
},
}
now := time.Now()
tests := []struct {
name string
msg scaleset.JobStarted
wantCounterValue float64
wantSampleCount uint64
wantSampleSum float64
}{
{
name: "zero RunnerAssignTime and ScaleSetAssignTime",
msg: scaleset.JobStarted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
RunnerAssignTime: time.Time{},
ScaleSetAssignTime: time.Time{},
},
},
wantCounterValue: 0,
wantSampleCount: 0,
},
{
name: "zero RunnerAssignTime",
msg: scaleset.JobStarted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
RunnerAssignTime: time.Time{},
ScaleSetAssignTime: now,
},
},
wantCounterValue: 0,
wantSampleCount: 0,
},
{
name: "zero ScaleSetAssignTime still counts the started job but skips the duration",
msg: scaleset.JobStarted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
RunnerAssignTime: now,
ScaleSetAssignTime: time.Time{},
},
},
wantCounterValue: 1,
wantSampleCount: 0,
},
{
name: "RunnerAssignTime before ScaleSetAssignTime still counts the started job but skips the duration",
msg: scaleset.JobStarted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
RunnerAssignTime: now,
ScaleSetAssignTime: now.Add(10 * time.Second),
},
},
wantCounterValue: 1,
wantSampleCount: 0,
},
{
name: "valid timestamps",
msg: scaleset.JobStarted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
ScaleSetAssignTime: now,
RunnerAssignTime: now.Add(10 * time.Second),
},
},
wantCounterValue: 1,
wantSampleCount: 1,
wantSampleSum: 10,
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
e, reg := newTestExporter(t, startedMetrics)
e.RecordJobStarted(&tt.msg)
metrics := gatherMetrics(t, reg)
assert.Equal(t, tt.wantCounterValue, counterValue(t, metrics, MetricStartedJobsTotal))
assert.Equal(t, tt.wantSampleCount, histogramSampleCount(t, metrics, MetricJobStartupDurationSeconds))
assert.Equal(t, tt.wantSampleSum, histogramSampleSum(t, metrics, MetricJobStartupDurationSeconds))
})
}
}
func TestRecordJobCompleted(t *testing.T) {
completedMetrics := v1alpha1.MetricsConfig{
Counters: map[string]*v1alpha1.CounterMetric{
MetricCompletedJobsTotal: {
Labels: []string{
labelKeyEnterprise, labelKeyOrganization, labelKeyRepository,
labelKeyJobName, labelKeyJobWorkflowRef, labelKeyJobWorkflowName,
labelKeyJobWorkflowTarget, labelKeyEventName, labelKeyJobResult,
},
},
},
Histograms: map[string]*v1alpha1.HistogramMetric{
MetricJobExecutionDurationSeconds: {
Labels: []string{
labelKeyEnterprise, labelKeyOrganization, labelKeyRepository,
labelKeyJobName, labelKeyJobWorkflowRef, labelKeyJobWorkflowName,
labelKeyJobWorkflowTarget, labelKeyEventName, labelKeyJobResult,
},
},
},
}
now := time.Now()
tests := []struct {
name string
msg scaleset.JobCompleted
wantCounterValue float64
wantSampleCount uint64
wantSampleSum float64
}{
{
name: "zero RunnerAssignTime",
msg: scaleset.JobCompleted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
RunnerAssignTime: time.Time{},
FinishTime: now,
},
Result: "success",
},
wantCounterValue: 0,
wantSampleCount: 0,
},
{
name: "zero FinishTime still counts the completed job but skips the duration",
msg: scaleset.JobCompleted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
RunnerAssignTime: now,
FinishTime: time.Time{},
},
Result: "success",
},
wantCounterValue: 1,
wantSampleCount: 0,
},
{
name: "FinishTime before RunnerAssignTime still counts the completed job but skips the duration",
msg: scaleset.JobCompleted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
RunnerAssignTime: now.Add(20 * time.Second),
FinishTime: now,
},
Result: "success",
},
wantCounterValue: 1,
wantSampleCount: 0,
},
{
name: "valid timestamps",
msg: scaleset.JobCompleted{
JobMessageBase: scaleset.JobMessageBase{
OwnerName: "myorg",
RepositoryName: "myrepo",
JobDisplayName: "build",
JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main",
EventName: "push",
// ScaleSetAssignTime represents queue-wait time and must not
// leak into the execution duration, which should only measure
// FinishTime - RunnerAssignTime.
ScaleSetAssignTime: now.Add(-1 * time.Minute),
RunnerAssignTime: now,
FinishTime: now.Add(10 * time.Second),
},
Result: "success",
},
wantCounterValue: 1,
wantSampleCount: 1,
wantSampleSum: 10,
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
e, reg := newTestExporter(t, completedMetrics)
e.RecordJobCompleted(&tt.msg)
metrics := gatherMetrics(t, reg)
assert.Equal(t, tt.wantCounterValue, counterValue(t, metrics, MetricCompletedJobsTotal))
assert.Equal(t, tt.wantSampleCount, histogramSampleCount(t, metrics, MetricJobExecutionDurationSeconds))
assert.Equal(t, tt.wantSampleSum, histogramSampleSum(t, metrics, MetricJobExecutionDurationSeconds))
})
}
}