Adds workflow_job_duration_seconds and other small improvements (#38)

* adds .idea dir to .gitignore

Signed-off-by: Jan Akerman <[email protected]>

* handles body read error

Signed-off-by: Jan Akerman <[email protected]>

* adds guard for workflow job queued event handling...

where no steps are present

Signed-off-by: Jan Akerman <[email protected]>

* adds debug logging of event payload

Signed-off-by: Jan Akerman <[email protected]>

* updates binary name from make build

The Dockerfile expects the updated name.
Aligning the two makes building local images
easier.

Signed-off-by: Jan Akerman <[email protected]>

* calculates workflow_job duration from job timestamps

Instead of using the step timestamps which are not
always present. This is an improvement for two reasons
* We don't need logic as to which event type is needed,
  just that it has the required timestamp fields.
* GitHub sometimes sends strange events that are marked
  as completed but with partially completed steps.
* Also fixes issue whereby a lack of timestamp results
  in dropping the count metric for that job due to
  incorrect use of return instead of break.

Signed-off-by: Jan Akerman <[email protected]>

* adds status and conclusion labels to coun metrics

i.e workflow_job_status_count and workflow_status_count.

Previously, for completed status webhooks, conclusion was
being used as the status. However, having both of these
labels allows you to query for all completed jobs
(e.g status="completed") whilst also providing the
granularity on the reasons in conclusion.

Generally, it's making less assumptions about the
webhook contents and just displaying what GitHub
sends - so any future changes against current
assumptions will show in the metrics labels.

Signed-off-by: Jan Akerman <[email protected]>

* adds workflow_job_duration_seconds_total

* Metric is a counter for total job duration. Useful
  for more accurate usage as workflow_job_duration_seconds
  is a histogram that uses buckets, thus loosing this accuracy.
* Updates server_test with additional assertion
* Closes body correctly
* Removes workflow job skipped tests as they are no longer handled
  differently than any other event with completed status.

Signed-off-by: Jan Akerman <[email protected]>

Signed-off-by: Jan Akerman <[email protected]>
Co-authored-by: Carlos Tadeu Panato Junior <[email protected]>

Author: janakerman-form3

.gitignore

@@ -1,4 +1,4 @@
-github_actions_exporter
+github-actions-exporter
 *.env
 *.tar.gz
 
@@ -18,3 +18,4 @@ github_actions_exporter
 # VSCode
 .vscode/
 dist/
+.idea/

Makefile

@@ -12,4 +12,4 @@ test:
 
 .PHONY: build
 build:
-	go build .
+	go build -o github-actions-exporter .

doc/webhooks.md

@@ -0,0 +1,17 @@
+## GitHub Webhooks
+
+## [Workflow Run](https://docs.github.com/en/developers/webhooks-and-events/webhooks/webhook-events-and-payloads#workflow_run)
+
+* Webhook field `action` is `requested` or `completed`.
+  * `requested` has `status=queued` and `conclusion=null`.
+  * `completed` can be `failure`, `success`, `cancelled`.
+
+## [Workflow Job](https://docs.github.com/en/developers/webhooks-and-events/webhooks/webhook-events-and-payloads#workflow_job)
+
+* Webhook field `action` and `workflow_job[status]` are equal in webhook payloads and include `queued`, `in_progress`, `completed`
+* `workflow_job[conclusion]` includes but is not limited to `in_progress`, `queued`, `success`, `failure`, `cancelled`, `skipped`.
+* `workflow_job[started_at]` and `workflow_job[completed_at]` are present in all `conclusion`s that are associated with 
+  the `completed` `status` i.e `failure`, `success`, `cancelled`, `skipped`.
+
+
+

internal/server/metrics.go

@@ -11,11 +11,18 @@ var (
 		[]string{"org", "repo", "state", "runner_group"},
 	)
 
+	workflowJobDurationCounter = prometheus.NewCounterVec(prometheus.CounterOpts{
+		Name: "workflow_job_duration_seconds_total",
+		Help: "The total duration of jobs.",
+	},
+		[]string{"org", "repo", "status", "conclusion", "runner_group"},
+	)
+
 	workflowJobStatusCounter = prometheus.NewCounterVec(prometheus.CounterOpts{
 		Name: "workflow_job_status_count",
-		Help: "Count of the occurrences of different workflow job states.",
+		Help: "Count of workflow job events.",
 	},
-		[]string{"org", "repo", "status", "runner_group"},
+		[]string{"org", "repo", "status", "conclusion", "runner_group"},
 	)
 
 	workflowRunHistogramVec = prometheus.NewHistogramVec(prometheus.HistogramOpts{
@@ -30,7 +37,7 @@ var (
 		Name: "workflow_status_count",
 		Help: "Count of the occurrences of different workflow states.",
 	},
-		[]string{"org", "repo", "workflow_name", "status"},
+		[]string{"org", "repo", "status", "conclusion", "workflow_name"},
 	)
 
 	totalMinutesUsedActions = prometheus.NewGaugeVec(prometheus.GaugeOpts{
@@ -80,6 +87,7 @@ func init() {
 	// Register metrics with prometheus
 	prometheus.MustRegister(workflowJobHistogramVec)
 	prometheus.MustRegister(workflowJobStatusCounter)
+	prometheus.MustRegister(workflowJobDurationCounter)
 	prometheus.MustRegister(workflowRunHistogramVec)
 	prometheus.MustRegister(workflowRunStatusCounter)
 	prometheus.MustRegister(totalMinutesUsedActions)
@@ -92,9 +100,10 @@ func init() {
 
 type WorkflowObserver interface {
 	ObserveWorkflowJobDuration(org, repo, state, runnerGroup string, seconds float64)
-	CountWorkflowJobStatus(org, repo, status, runnerGroup string)
+	CountWorkflowJobStatus(org, repo, status, conclusion, runnerGroup string)
+	CountWorkflowJobDuration(org, repo, status, conclusion, runnerGroup string, seconds float64)
 	ObserveWorkflowRunDuration(org, repo, workflow string, seconds float64)
-	CountWorkflowRunStatus(org, repo, workflow, status string)
+	CountWorkflowRunStatus(org, repo, status, conclusion, workflow string)
 }
 
 var _ WorkflowObserver = (*PrometheusObserver)(nil)
@@ -106,15 +115,19 @@ func (o *PrometheusObserver) ObserveWorkflowJobDuration(org, repo, state, runner
 		Observe(seconds)
 }
 
-func (o *PrometheusObserver) CountWorkflowJobStatus(org, repo, status, runnerGroup string) {
-	workflowJobStatusCounter.WithLabelValues(org, repo, status, runnerGroup).Inc()
+func (o *PrometheusObserver) CountWorkflowJobStatus(org, repo, status, conclusion, runnerGroup string) {
+	workflowJobStatusCounter.WithLabelValues(org, repo, status, conclusion, runnerGroup).Inc()
+}
+
+func (o *PrometheusObserver) CountWorkflowJobDuration(org, repo, status, conclusion, runnerGroup string, seconds float64) {
+	workflowJobDurationCounter.WithLabelValues(org, repo, status, conclusion, runnerGroup).Add(seconds)
 }
 
 func (o *PrometheusObserver) ObserveWorkflowRunDuration(org, repo, workflowName string, seconds float64) {
 	workflowRunHistogramVec.WithLabelValues(org, repo, workflowName).
 		Observe(seconds)
 }
 
-func (o *PrometheusObserver) CountWorkflowRunStatus(org, repo, workflowName, status string) {
-	workflowRunStatusCounter.WithLabelValues(org, repo, workflowName, status).Inc()
+func (o *PrometheusObserver) CountWorkflowRunStatus(org, repo, status, conclusion, workflowName string) {
+	workflowRunStatusCounter.WithLabelValues(org, repo, status, conclusion, workflowName).Inc()
 }

internal/server/server_test.go

@@ -72,24 +72,22 @@ func Test_Server_MetricsRouteAfterWorkflowJob(t *testing.T) {
 	org := "someone"
 	expectedDuration := 10.0
 	jobStartedAt := time.Unix(1650308740, 0)
-	stepStartedAt := jobStartedAt.Add(time.Duration(expectedDuration) * time.Second)
+	completedAt := jobStartedAt.Add(time.Duration(expectedDuration) * time.Second)
 	runnerGroupName := "runner-group"
 
 	event := github.WorkflowJobEvent{
-		Action: github.String("in_progress"),
+		Action: github.String("completed"),
 		Repo: &github.Repository{
 			Name: &repo,
 			Owner: &github.User{
 				Login: &org,
 			},
 		},
 		WorkflowJob: &github.WorkflowJob{
-			StartedAt: &github.Timestamp{Time: jobStartedAt},
-			Steps: []*github.TaskStep{
-				{
-					StartedAt: &github.Timestamp{Time: stepStartedAt},
-				},
-			},
+			Status:          github.String("completed"),
+			Conclusion:      github.String("success"),
+			StartedAt:       &github.Timestamp{Time: jobStartedAt},
+			CompletedAt:     &github.Timestamp{Time: completedAt},
 			RunnerGroupName: &runnerGroupName,
 		},
 	}
@@ -109,5 +107,6 @@ func Test_Server_MetricsRouteAfterWorkflowJob(t *testing.T) {
 
 	payload, err := ioutil.ReadAll(metricsRes.Body)
 	require.NoError(t, err)
-	assert.Contains(t, string(payload), `workflow_job_duration_seconds_bucket{org="someone",repo="some-repo",runner_group="runner-group",state="queued",le="10.541350399999995"} 1`)
+	assert.Contains(t, string(payload), `workflow_job_duration_seconds_bucket{org="someone",repo="some-repo",runner_group="runner-group",state="in_progress",le="10.541350399999995"} 1`)
+	assert.Contains(t, string(payload), `workflow_job_duration_seconds_total{conclusion="success",org="someone",repo="some-repo",runner_group="runner-group",status="completed"} 10`)
 }

internal/server/workflow_metrics_exporter.go

@@ -36,7 +36,13 @@ func NewWorkflowMetricsExporter(logger log.Logger, opts Opts) *WorkflowMetricsEx
 
 // handleGHWebHook responds to POST /gh_event, when receive a event from GitHub.
 func (c *WorkflowMetricsExporter) HandleGHWebHook(w http.ResponseWriter, r *http.Request) {
-	buf, _ := ioutil.ReadAll(r.Body)
+	buf, err := ioutil.ReadAll(r.Body)
+	if err != nil {
+		_ = level.Error(c.Logger).Log("msg", "error reading body: %v", err)
+		w.WriteHeader(http.StatusInternalServerError)
+		return
+	}
+	defer r.Body.Close()
 
 	receivedHash := strings.SplitN(r.Header.Get("X-Hub-Signature"), "=", 2)
 	if receivedHash[0] != "sha1" {
@@ -45,13 +51,15 @@ func (c *WorkflowMetricsExporter) HandleGHWebHook(w http.ResponseWriter, r *http
 		return
 	}
 
-	err := validateSignature(c.Opts.GitHubToken, receivedHash, buf)
+	err = validateSignature(c.Opts.GitHubToken, receivedHash, buf)
 	if err != nil {
 		_ = level.Error(c.Logger).Log("msg", "invalid token", "err", err)
 		w.WriteHeader(http.StatusForbidden)
 		return
 	}
 
+	_ = level.Debug(c.Logger).Log("msg", "received webhook", "payload", string(buf))
+
 	eventType := r.Header.Get("X-GitHub-Event")
 	switch eventType {
 	case "ping":
@@ -86,45 +94,51 @@ func (c *WorkflowMetricsExporter) CollectWorkflowJobEvent(event *github.Workflow
 	repo := event.GetRepo().GetName()
 	org := event.GetRepo().GetOwner().GetLogin()
 	runnerGroup := event.WorkflowJob.GetRunnerGroupName()
+
 	action := event.GetAction()
+	conclusion := event.GetWorkflowJob().GetConclusion()
+	status := event.GetWorkflowJob().GetStatus()
 
-	var status string
 	switch action {
 	case "queued":
-		status = "queued"
+		// Do nothing.
 	case "in_progress":
-		status = "in_progress"
+
+		if len(event.WorkflowJob.Steps) == 0 {
+			_ = level.Debug(c.Logger).Log("msg", "unable to calculate job duration of in_progress event as event has no steps")
+			break
+		}
 
 		firstStep := event.WorkflowJob.Steps[0]
 		queuedSeconds := firstStep.StartedAt.Time.Sub(event.WorkflowJob.StartedAt.Time).Seconds()
 		c.PrometheusObserver.ObserveWorkflowJobDuration(org, repo, "queued", runnerGroup, math.Max(0, queuedSeconds))
 	case "completed":
-		status = event.GetWorkflowJob().GetConclusion()
-
-		if event.GetWorkflowJob().GetConclusion() != "skipped" {
-			firstStepStarted := event.WorkflowJob.Steps[0].StartedAt.Time
-			lastStepCompleted := event.WorkflowJob.Steps[len(event.WorkflowJob.Steps)-1].CompletedAt.Time
-			jobSeconds := lastStepCompleted.Sub(firstStepStarted).Seconds()
-			c.PrometheusObserver.ObserveWorkflowJobDuration(org, repo, "in_progress", runnerGroup, math.Max(0, jobSeconds))
+		if event.WorkflowJob.StartedAt == nil || event.WorkflowJob.CompletedAt == nil {
+			_ = level.Debug(c.Logger).Log("msg", "unable to calculate job duration of completed event steps are missing timestamps")
+			break
 		}
+
+		jobSeconds := math.Max(0, event.WorkflowJob.GetCompletedAt().Time.Sub(event.WorkflowJob.GetStartedAt().Time).Seconds())
+		c.PrometheusObserver.ObserveWorkflowJobDuration(org, repo, "in_progress", runnerGroup, jobSeconds)
+		c.PrometheusObserver.CountWorkflowJobDuration(org, repo, status, conclusion, runnerGroup, jobSeconds)
 	}
 
-	c.PrometheusObserver.CountWorkflowJobStatus(org, repo, status, runnerGroup)
+	c.PrometheusObserver.CountWorkflowJobStatus(org, repo, status, conclusion, runnerGroup)
 }
 
 func (c *WorkflowMetricsExporter) CollectWorkflowRunEvent(event *github.WorkflowRunEvent) {
-	if event.GetAction() != "completed" {
-		return
-	}
-
 	repo := event.GetRepo().GetName()
 	org := event.GetRepo().GetOwner().GetLogin()
 	workflowName := event.GetWorkflow().GetName()
-	seconds := event.GetWorkflowRun().UpdatedAt.Time.Sub(event.GetWorkflowRun().RunStartedAt.Time).Seconds()
-	c.PrometheusObserver.ObserveWorkflowRunDuration(org, repo, workflowName, seconds)
+
+	if event.GetAction() == "completed" {
+		seconds := event.GetWorkflowRun().UpdatedAt.Time.Sub(event.GetWorkflowRun().RunStartedAt.Time).Seconds()
+		c.PrometheusObserver.ObserveWorkflowRunDuration(org, repo, workflowName, seconds)
+	}
 
 	status := event.GetWorkflowRun().GetStatus()
-	c.PrometheusObserver.CountWorkflowRunStatus(org, repo, workflowName, status)
+	conclusion := event.GetWorkflowRun().GetConclusion()
+	c.PrometheusObserver.CountWorkflowRunStatus(org, repo, status, conclusion, workflowName)
 }
 
 // validateSignature validate the incoming github event.