actions / actions/actions-runner-controller

bug(metrics): Large negative values are reported when time.IsZero() in code.

Open
#2,743 2 comments 2 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug community
Dominant language
Go
Stars
6.5k
Forks
1.5k
Avg merge
2d 2h
Merged PRs (30d)
27

Description

Checks
Controller Version

0.27.4

Helm Chart Version

No response

CertManager Version

No response

Deployment Method

Helm

cert-manager installation

Unneeded for this bug.

Checks
  • This isn't a question or user support case (For Q&A and community support, go to Discussions. It might also be a good idea to contract with any of contributors and maintainers if your business is so critical and therefore you need priority support
  • I've read releasenotes before submitting this issue and I'm sure it's not due to any recently-introduced backward-incompatible changes
  • My actions-runner-controller version (v0.x.y) does support the feature
  • I've already upgraded ARC (including the CRDs, see charts/actions-runner-controller/docs/UPGRADING.md for details) to the latest and it didn't fix the issue
  • I've migrated to the workflow job webhook event (if you using webhook driven scaling)
Resource Definitions
Unneeded for this bug.
To Reproduce
Gather a large number of metrics and inspect the /metrics endpoint for large negative values.
Describe the bug

We see large negative values in our bucket timings. Code bug in additional context

Describe the expected behavior

The "run duration" of a job should never be a large negative value

Whole Controller Logs
.
Whole Runner Pod Logs
.
Additional Context

I'm looking at the function here: https://github.com/actions/actions-runner-controller/blob/e0a7e142e0fcd446c58e7875d4d44a7eea6e72f2/pkg/actionsmetrics/event_reader.go#L226

The code ends in this

	return &ParseResult{
		ExitCode:  exitCode,
		QueueTime: startedTime.Sub(queuedTime),
		RunTime:   completedTime.Sub(startedTime),
	}, nil

I believe that sometimes, startedTime or completedTime, are never parsed and are still the zero value. When they are the zero value, the returned value is 0-<now> which is very large and reports as a large negative number in the /metrics endpoint.

Proposed fix

Rather than this

	return &ParseResult{
		ExitCode:  exitCode,
		QueueTime: startedTime.Sub(queuedTime),
		RunTime:   completedTime.Sub(startedTime),
	}, nil

Do this

var ret ParseResult
if !startedTime.IsZero() && !queuedTime.IsZero() {
  ret.QueueTime = startedTime.Sub(queuedTime)
}

And the same for RunTime.

Then on the caller side, if the metric QueueTime.IsZero() is true, don't report the zero value to /metrics historgram

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start in pkg/actionsmetrics/event_reader.go around the referenced parsing function and trace how QueueTime and RunTime reach the /metrics endpoint. Reproduce the zero-time case, ensure missing timestamps do not produce large negative durations or histogram observations, and verify the relevant metrics behavior with tests.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
observability-sre
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.