Skip to content

Commit 3e5fcc4

Browse files
adrielpdragonlord93
adrielp
authored and
dragonlord93
committed
[receiver/github] fix queue span lengths caused by GitHub event timestamp bug (open-telemetry#39972)
#### Description GitHub events from skipped jobs sometimes have the createdAt timestamp to be AFTER the startedAt timestamp. This causes the created span to having a time of some crazy long time, while the duration attribute is negative. This change accounts for that inconsistent behavior from GitHub and adds the corresponding tests. #### Link to tracking issue Fixes open-telemetry#39824 #### Testing Added the tests in the source code. #### Documentation Minor comment around the codeblock for context of why.
1 parent e52bb22 commit 3e5fcc4

File tree

5 files changed

+262
-5
lines changed

5 files changed

+262
-5
lines changed

‎.chloggen/queue-patch.yaml

Lines changed: 32 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,32 @@
1+
# Use this changelog template to create an entry for release notes.
2+
3+
# One of 'breaking', 'deprecation', 'new_component', 'enhancement', 'bug_fix'
4+
change_type: bug_fix
5+
6+
# The name of the component, or a single word describing the area of concern, (e.g. filelogreceiver)
7+
component: githubreceiver
8+
9+
# A brief description of the change. Surround your text with quotes ("") if it needs to start with a backtick (`).
10+
note: fix queue span lengths caused by GitHub event timestamp bug
11+
12+
# Mandatory: One or more tracking issues related to the change. You can use the PR number here if no issue exists.
13+
issues: [39824]
14+
15+
# (Optional) One or more lines of additional information to render under the primary note.
16+
# These lines will be padded with 2 spaces and then inserted directly into the document.
17+
# Use pipe (|) for multiline entries.
18+
subtext: |
19+
GitHub events from skipped jobs sometimes have the createdAt timestamp to be
20+
AFTER the startedAt timestamp. This causes the created span to having a time
21+
of some crazy long time, while the duration attribute is negative. This change
22+
accounts for that inconsistent behavior from GitHub and adds the corresponding
23+
tests.
24+
25+
# If your change doesn't affect end users or the exported elements of any package,
26+
# you should instead start your pull request title with [chore] or use the "Skip Changelog" label.
27+
# Optional: The change log or logs in which this entry should be included.
28+
# e.g. '[user]' or '[user, api]'
29+
# Include 'user' if the change is relevant to end users.
30+
# Include 'api' if there is a change to a library API.
31+
# Default: '[user]'
32+
change_logs: []

‎receiver/githubreceiver/testdata/workflow-job-skipped-expected.yaml

Lines changed: 77 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,77 @@
1+
resourceSpans:
2+
- resource:
3+
attributes:
4+
- key: service.name
5+
value:
6+
stringValue: opentelemetry-collector-contrib
7+
- key: vcs.repository.name
8+
value:
9+
stringValue: opentelemetry-collector-contrib
10+
- key: vcs.vendor.name
11+
value:
12+
stringValue: github
13+
- key: vcs.ref.head
14+
value:
15+
stringValue: main
16+
- key: vcs.ref.head.type
17+
value:
18+
stringValue: branch
19+
- key: vcs.ref.head.revision
20+
value:
21+
stringValue: 51eb1fb55541bf4856a7a24afd15bb3e90eea0ff
22+
- key: cicd.pipeline.worker.id
23+
value:
24+
intValue: "0"
25+
- key: cicd.pipeline.worker.group.id
26+
value:
27+
intValue: "0"
28+
- key: cicd.pipeline.worker.name
29+
value:
30+
stringValue: ""
31+
- key: cicd.pipeline.worker.group.name
32+
value:
33+
stringValue: ""
34+
- key: cicd.pipeline.worker.node.id
35+
value:
36+
stringValue: CR_kwDOOjaRi88AAAAJrFr5Eg
37+
- key: cicd.pipeline.name
38+
value:
39+
stringValue: build
40+
- key: cicd.pipeline.task.run.sender.login
41+
value:
42+
stringValue: adrielp
43+
- key: cicd.pipeline.task.run.url.full
44+
value:
45+
stringValue: https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/14796710445/job/41546348818
46+
- key: cicd.pipeline.task.run.id
47+
value:
48+
intValue: "41546348818"
49+
- key: cicd.pipeline.run.task.status
50+
value:
51+
stringValue: skip
52+
scopeSpans:
53+
- scope: {}
54+
spans:
55+
- endTimeUnixNano: "1746195354000000000"
56+
kind: 2
57+
name: build
58+
parentSpanId: 3b54c768f3ef27e1
59+
spanId: 84e27971417e5249
60+
startTimeUnixNano: "1746195355000000000"
61+
status:
62+
message: skipped
63+
traceId: 0b0cff7305ff68eb7d1bb72c7fdbe277
64+
- scope: {}
65+
spans:
66+
- attributes:
67+
- key: cicd.pipeline.run.queue.duration
68+
value:
69+
doubleValue: 0
70+
endTimeUnixNano: "1746195354000000000"
71+
kind: 2
72+
name: queue-build
73+
parentSpanId: 84e27971417e5249
74+
spanId: 750687c67fcd26a3
75+
startTimeUnixNano: "1746195354000000000"
76+
status: {}
77+
traceId: 0b0cff7305ff68eb7d1bb72c7fdbe277

‎receiver/githubreceiver/testdata/workflow-job-skipped.json

Lines changed: 86 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,86 @@
1+
{
2+
"action": "completed",
3+
"workflow_job": {
4+
"id": 41546348818,
5+
"run_id": 14796710445,
6+
"workflow_name": "skip-me",
7+
"head_branch": "main",
8+
"run_url": "https://api.github.com/repos/open-telemetry/opentelemetry-collector-contrib/actions/runs/14796710445",
9+
"run_attempt": 13,
10+
"node_id": "CR_kwDOOjaRi88AAAAJrFr5Eg",
11+
"head_sha": "51eb1fb55541bf4856a7a24afd15bb3e90eea0ff",
12+
"url": "https://api.github.com/repos/open-telemetry/opentelemetry-collector-contrib/actions/jobs/41546348818",
13+
"html_url": "https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/14796710445/job/41546348818",
14+
"status": "completed",
15+
"conclusion": "skipped",
16+
"created_at": "2025-05-02T14:15:55Z",
17+
"started_at": "2025-05-02T14:15:54Z",
18+
"completed_at": "2025-05-02T14:15:54Z",
19+
"name": "build",
20+
"steps": [
21+
22+
],
23+
"check_run_url": "https://api.github.com/repos/open-telemetry/opentelemetry-collector-contrib/check-runs/41546348818",
24+
"labels": [
25+
26+
],
27+
"runner_id": null,
28+
"runner_name": null,
29+
"runner_group_id": null,
30+
"runner_group_name": null
31+
},
32+
"repository": {
33+
"id": 976654731,
34+
"node_id": "R_kgDOOjaRiw",
35+
"name": "opentelemetry-collector-contrib",
36+
"full_name": "open-telemetry/opentelemetry-collector-contrib",
37+
"private": false,
38+
"owner": {
39+
"login": "open-telemetry",
40+
"id": 31416286,
41+
"node_id": "MDEyOk9yZ2FuaXphdGlvbjMxNDE2Mjg2",
42+
"url": "https://api.github.com/users/open-telemetry",
43+
"html_url": "https://github.com/open-telemetry",
44+
"followers_url": "https://api.github.com/users/open-telemetry/followers",
45+
"following_url": "https://api.github.com/users/open-telemetry/following{/other_user}",
46+
"gists_url": "https://api.github.com/users/open-telemetry/gists{/gist_id}",
47+
"starred_url": "https://api.github.com/users/open-telemetry/starred{/owner}{/repo}",
48+
"subscriptions_url": "https://api.github.com/users/open-telemetry/subscriptions",
49+
"organizations_url": "https://api.github.com/users/open-telemetry/orgs",
50+
"repos_url": "https://api.github.com/users/open-telemetry/repos",
51+
"events_url": "https://api.github.com/users/open-telemetry/events{/privacy}",
52+
"received_events_url": "https://api.github.com/users/open-telemetry/received_events",
53+
"type": "Organization",
54+
"user_view_type": "public",
55+
"site_admin": false
56+
},
57+
"html_url": "https://github.com/open-telemetry/opentelemetry-collector-contrib",
58+
"fork": false,
59+
"url": "https://api.github.com/repos/open-telemetry/opentelemetry-collector-contrib",
60+
"forks_url": "https://api.github.com/repos/open-telemetry/opentelemetry-collector-contrib/forks",
61+
"keys_url": "https://api.github.com/repos/open-telemetry/opentelemetry-collector-contrib/keys{/key_id}",
62+
"deployments_url": "https://api.github.com/repos/open-telemetry/opentelemetry-collector-contrib/deployments",
63+
"created_at": "2025-05-02T13:57:56Z",
64+
"updated_at": "2025-05-02T14:01:14Z",
65+
"pushed_at": "2025-05-02T14:01:10Z",
66+
"visibility": "public",
67+
"default_branch": "main",
68+
"custom_properties": {
69+
70+
}
71+
},
72+
"organization": {
73+
"login": "open-telemetry",
74+
"id": 31416286,
75+
"node_id": "MDEyOk9yZ2FuaXphdGlvbjMxNDE2Mjg2",
76+
"url": "https://api.github.com/orgs/open-telemetry"
77+
},
78+
"sender": {
79+
"login": "adrielp",
80+
"url": "https://api.github.com/users/adrielp",
81+
"html_url": "https://github.com/adrielp",
82+
"type": "User",
83+
"user_view_type": "public",
84+
"site_admin": false
85+
}
86+
}

‎receiver/githubreceiver/trace_event_handling.go

Lines changed: 18 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import (
99
"errors"
1010
"fmt"
1111
"strings"
12+
"time"
1213

1314
"github.com/google/go-github/v71/github"
1415
"go.opentelemetry.io/collector/pdata/pcommon"
@@ -385,13 +386,25 @@ func (gtr *githubTracesReceiver) createJobQueueSpan(
385386

386387
span.SetSpanID(spanID)
387388

388-
time := event.GetWorkflowJob().GetStartedAt().Sub(event.GetWorkflowJob().GetCreatedAt().Time)
389+
created := pcommon.NewTimestampFromTime(event.GetWorkflowJob().GetCreatedAt().Time)
390+
started := pcommon.NewTimestampFromTime(event.GetWorkflowJob().GetStartedAt().Time)
391+
duration := event.WorkflowJob.GetStartedAt().Sub(event.GetWorkflowJob().GetCreatedAt().Time)
392+
393+
span.SetStartTimestamp(created)
394+
span.SetEndTimestamp(started)
395+
396+
// GitHub sometimes reports the createdAt value as being a second after the
397+
// startedAt value which results in unreal times in duration. To work around
398+
// this we set the duration to 0 and the start/end spans to the started
399+
// time in that event. Otherwise we calculate the time properly and set the
400+
// span start time as the created time.
401+
if created.AsTime().After(started.AsTime()) {
402+
duration = time.Duration(0)
403+
span.SetStartTimestamp(started)
404+
}
389405

390406
attrs := span.Attributes()
391-
attrs.PutDouble(AttributeCICDPipelineRunQueueDuration, float64(time.Nanoseconds()))
392-
393-
span.SetStartTimestamp(pcommon.NewTimestampFromTime(event.GetWorkflowJob().GetCreatedAt().Time))
394-
span.SetEndTimestamp(pcommon.NewTimestampFromTime(event.GetWorkflowJob().GetStartedAt().Time))
407+
attrs.PutDouble(AttributeCICDPipelineRunQueueDuration, float64(duration.Nanoseconds()))
395408

396409
return spanID, nil
397410
}

‎receiver/githubreceiver/trace_event_handling_test.go

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -83,6 +83,55 @@ func TestHandleWorkflowJobWithGoldenFile(t *testing.T) {
8383
require.NoError(t, ptracetest.CompareTraces(expectedTraces, traces))
8484
}
8585

86+
func TestHandleWorkflowJobWithGoldenFileSkipped(t *testing.T) {
87+
defaultConfig := createDefaultConfig().(*Config)
88+
defaultConfig.WebHook.Endpoint = "localhost:0"
89+
consumer := consumertest.NewNop()
90+
91+
receiver, err := newTracesReceiver(receivertest.NewNopSettings(metadata.Type), defaultConfig, consumer)
92+
require.NoError(t, err, "failed to create receiver")
93+
94+
testFilePath := filepath.Join("testdata", "workflow-job-skipped.json")
95+
data, err := os.ReadFile(testFilePath)
96+
require.NoError(t, err, "Failed to read test data file")
97+
98+
var event github.WorkflowJobEvent
99+
err = json.Unmarshal(data, &event)
100+
require.NoError(t, err, "Failed to unmarshal workflow job event")
101+
102+
traces, err := receiver.handleWorkflowJob(&event)
103+
require.NoError(t, err, "Failed to handle workflow job event")
104+
105+
expectedFile := filepath.Join("testdata", "workflow-job-skipped-expected.yaml")
106+
107+
// Uncomment the following line to update the golden file
108+
// golden.WriteTraces(t, expectedFile, traces)
109+
110+
expectedTraces, err := golden.ReadTraces(expectedFile)
111+
require.NoError(t, err, "Failed to read expected traces")
112+
113+
var queueSpan ptrace.Span
114+
resourceSpans := expectedTraces.ResourceSpans()
115+
for i := range resourceSpans.Len() {
116+
scopeSpans := resourceSpans.At(i).ScopeSpans()
117+
for j := range scopeSpans.Len() {
118+
spans := scopeSpans.At(j).Spans()
119+
for k := range spans.Len() {
120+
if spans.At(k).Name() == "queue-build" {
121+
queueSpan = spans.At(k)
122+
break
123+
}
124+
}
125+
}
126+
}
127+
require.Equal(t, queueSpan.StartTimestamp(), queueSpan.EndTimestamp(), "Start and end timestamps should be equal for queue-build span")
128+
queueAttr, exists := queueSpan.Attributes().Get("cicd.pipeline.run.queue.duration")
129+
require.True(t, exists)
130+
require.Equal(t, float64(0), queueAttr.Double())
131+
132+
require.NoError(t, ptracetest.CompareTraces(expectedTraces, traces))
133+
}
134+
86135
func TestNewParentSpanID(t *testing.T) {
87136
tests := []struct {
88137
name string

0 commit comments

Comments
 (0)