[receiver/github] fix span times when github sends incorrect values (#44495)

#### Description

Adds a corrective function to ensure timestamps that come from GitHub
won't produce negative values.

#### Link to tracking issue
Fixes

#43180

Author: adrielp

.chloggen/gh-span-times.yaml

@@ -0,0 +1,27 @@
+# Use this changelog template to create an entry for release notes.
+
+# One of 'breaking', 'deprecation', 'new_component', 'enhancement', 'bug_fix'
+change_type: bug_fix
+
+# The name of the component, or a single word describing the area of concern, (e.g. receiver/filelog)
+component: receiver/github
+
+# A brief description of the change.  Surround your text with quotes ("") if it needs to start with a backtick (`).
+note: Adds corrections to span times when GitHub sends incorrect start and end times.
+
+# Mandatory: One or more tracking issues related to the change. You can use the PR number here if no issue exists.
+issues: [43180]
+
+# (Optional) One or more lines of additional information to render under the primary note.
+# These lines will be padded with 2 spaces and then inserted directly into the document.
+# Use pipe (|) for multiline entries.
+subtext:
+
+# If your change doesn't affect end users or the exported elements of any package,
+# you should instead start your pull request title with [chore] or use the "Skip Changelog" label.
+# Optional: The change log or logs in which this entry should be included.
+# e.g. '[user]' or '[user, api]'
+# Include 'user' if the change is relevant to end users.
+# Include 'api' if there is a change to a library API.
+# Default: '[user]'
+change_logs: []

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

@@ -52,7 +52,7 @@ resourceSpans:
     scopeSpans:
       - scope: {}
         spans:
-          - endTimeUnixNano: "1746195354000000000"
+          - endTimeUnixNano: "1746195355000000000"
             kind: 2
             name: build
             parentSpanId: 3b54c768f3ef27e1
@@ -67,11 +67,11 @@ resourceSpans:
               - key: cicd.pipeline.run.queue.duration
                 value:
                   doubleValue: 0
-            endTimeUnixNano: "1746195354000000000"
+            endTimeUnixNano: "1746195355000000000"
             kind: 2
             name: queue-build
             parentSpanId: 84e27971417e5249
             spanId: 750687c67fcd26a3
-            startTimeUnixNano: "1746195354000000000"
+            startTimeUnixNano: "1746195355000000000"
             status: {}
             traceId: 0b0cff7305ff68eb7d1bb72c7fdbe277

receiver/githubreceiver/trace_event_handling.go

@@ -121,6 +121,22 @@ func newParentSpanID(runID int64, runAttempt int) (pcommon.SpanID, error) {
 	return spanID, nil
 }
 
+// correctActionTimestamps ensures span timestamps are valid by checking that
+// the end time is not before the start time. When GitHub reports timestamps
+// in reverse order (which can occur with skipped jobs and steps), this function
+// returns corrected timestamps where both start and end are set to the later
+// timestamp, resulting in a zero-duration span.
+//
+// This prevents negative durations that would otherwise appear as excessively
+// long spans in telemetry systems.
+func correctActionTimestamps(start, end time.Time) (time.Time, time.Time) {
+	if end.Before(start) {
+		// Use the later timestamp (start) for both, creating zero-duration span
+		return start, start
+	}
+	return start, end
+}
+
 // createRootSpan creates a root span based on the provided event, associated
 // with the deterministic traceID.
 func (gtr *githubTracesReceiver) createRootSpan(
@@ -141,8 +157,9 @@ func (gtr *githubTracesReceiver) createRootSpan(
 	span.SetSpanID(rootSpanID)
 	span.SetName(event.GetWorkflowRun().GetName())
 	span.SetKind(ptrace.SpanKindServer)
-	span.SetStartTimestamp(pcommon.NewTimestampFromTime(event.GetWorkflowRun().GetRunStartedAt().Time))
-	span.SetEndTimestamp(pcommon.NewTimestampFromTime(event.GetWorkflowRun().GetUpdatedAt().Time))
+	startTime, endTime := correctActionTimestamps(event.GetWorkflowRun().GetRunStartedAt().Time, event.GetWorkflowRun().GetUpdatedAt().Time)
+	span.SetStartTimestamp(pcommon.NewTimestampFromTime(startTime))
+	span.SetEndTimestamp(pcommon.NewTimestampFromTime(endTime))
 
 	switch strings.ToLower(event.WorkflowRun.GetConclusion()) {
 	case "success":
@@ -207,8 +224,9 @@ func (gtr *githubTracesReceiver) createParentSpan(
 	span.SetName(event.GetWorkflowJob().GetName())
 	span.SetKind(ptrace.SpanKindServer)
 
-	span.SetStartTimestamp(pcommon.NewTimestampFromTime(event.GetWorkflowJob().GetCreatedAt().Time))
-	span.SetEndTimestamp(pcommon.NewTimestampFromTime(event.GetWorkflowJob().GetCompletedAt().Time))
+	startTime, endTime := correctActionTimestamps(event.GetWorkflowJob().GetCreatedAt().Time, event.GetWorkflowJob().GetCompletedAt().Time)
+	span.SetStartTimestamp(pcommon.NewTimestampFromTime(startTime))
+	span.SetEndTimestamp(pcommon.NewTimestampFromTime(endTime))
 
 	switch strings.ToLower(event.WorkflowJob.GetConclusion()) {
 	case "success":
@@ -336,8 +354,9 @@ func (*githubTracesReceiver) createStepSpan(
 	attrs := span.Attributes()
 	attrs.PutStr(string(semconv.CICDPipelineTaskNameKey), name)
 	attrs.PutStr(AttributeCICDPipelineTaskRunStatus, step.GetStatus())
-	span.SetStartTimestamp(pcommon.NewTimestampFromTime(step.GetStartedAt().Time))
-	span.SetEndTimestamp(pcommon.NewTimestampFromTime(step.GetCompletedAt().Time))
+	startTime, endTime := correctActionTimestamps(step.GetStartedAt().Time, step.GetCompletedAt().Time)
+	span.SetStartTimestamp(pcommon.NewTimestampFromTime(startTime))
+	span.SetEndTimestamp(pcommon.NewTimestampFromTime(endTime))
 
 	switch strings.ToLower(step.GetConclusion()) {
 	case "success":
@@ -404,22 +423,11 @@ func (*githubTracesReceiver) createJobQueueSpan(
 
 	span.SetSpanID(spanID)
 
-	created := pcommon.NewTimestampFromTime(event.GetWorkflowJob().GetCreatedAt().Time)
-	started := pcommon.NewTimestampFromTime(event.GetWorkflowJob().GetStartedAt().Time)
-	duration := event.WorkflowJob.GetStartedAt().Sub(event.GetWorkflowJob().GetCreatedAt().Time)
-
-	span.SetStartTimestamp(created)
-	span.SetEndTimestamp(started)
-
-	// GitHub sometimes reports the createdAt value as being a second after the
-	// startedAt value which results in unreal times in duration. To work around
-	// this we set the duration to 0 and the start/end spans to the started
-	// time in that event. Otherwise we calculate the time properly and set the
-	// span start time as the created time.
-	if created.AsTime().After(started.AsTime()) {
-		duration = time.Duration(0)
-		span.SetStartTimestamp(started)
-	}
+	createdTime, startedTime := correctActionTimestamps(event.GetWorkflowJob().GetCreatedAt().Time, event.GetWorkflowJob().GetStartedAt().Time)
+	duration := startedTime.Sub(createdTime)
+
+	span.SetStartTimestamp(pcommon.NewTimestampFromTime(createdTime))
+	span.SetEndTimestamp(pcommon.NewTimestampFromTime(startedTime))
 
 	attrs := span.Attributes()
 	attrs.PutDouble(AttributeCICDPipelineRunQueueDuration, float64(duration.Nanoseconds()))

receiver/githubreceiver/trace_event_handling_test.go

@@ -866,3 +866,75 @@ func TestStepSpansHaveNoEvents(t *testing.T) {
 		}
 	}
 }
+
+func TestCorrectActionTimestamps(t *testing.T) {
+	tests := []struct {
+		name          string
+		start         time.Time
+		end           time.Time
+		expectedStart time.Time
+		expectedEnd   time.Time
+	}{
+		{
+			name:          "normal order - no change needed",
+			start:         time.Date(2025, 5, 2, 14, 15, 54, 0, time.UTC),
+			end:           time.Date(2025, 5, 2, 14, 15, 55, 0, time.UTC),
+			expectedStart: time.Date(2025, 5, 2, 14, 15, 54, 0, time.UTC),
+			expectedEnd:   time.Date(2025, 5, 2, 14, 15, 55, 0, time.UTC),
+		},
+		{
+			name:          "same timestamp - no change needed",
+			start:         time.Date(2025, 5, 2, 14, 15, 54, 0, time.UTC),
+			end:           time.Date(2025, 5, 2, 14, 15, 54, 0, time.UTC),
+			expectedStart: time.Date(2025, 5, 2, 14, 15, 54, 0, time.UTC),
+			expectedEnd:   time.Date(2025, 5, 2, 14, 15, 54, 0, time.UTC),
+		},
+		{
+			name:          "inverted timestamps - end before start",
+			start:         time.Date(2025, 5, 2, 14, 15, 55, 0, time.UTC),
+			end:           time.Date(2025, 5, 2, 14, 15, 54, 0, time.UTC),
+			expectedStart: time.Date(2025, 5, 2, 14, 15, 55, 0, time.UTC),
+			expectedEnd:   time.Date(2025, 5, 2, 14, 15, 55, 0, time.UTC),
+		},
+		{
+			name:          "end one second before start",
+			start:         time.Date(2025, 5, 2, 14, 15, 55, 0, time.UTC),
+			end:           time.Date(2025, 5, 2, 14, 15, 54, 0, time.UTC),
+			expectedStart: time.Date(2025, 5, 2, 14, 15, 55, 0, time.UTC),
+			expectedEnd:   time.Date(2025, 5, 2, 14, 15, 55, 0, time.UTC),
+		},
+		{
+			name:          "large time difference - inverted",
+			start:         time.Date(2025, 5, 2, 15, 0, 0, 0, time.UTC),
+			end:           time.Date(2025, 5, 2, 14, 0, 0, 0, time.UTC),
+			expectedStart: time.Date(2025, 5, 2, 15, 0, 0, 0, time.UTC),
+			expectedEnd:   time.Date(2025, 5, 2, 15, 0, 0, 0, time.UTC),
+		},
+		{
+			name:          "nanosecond precision - inverted",
+			start:         time.Date(2025, 5, 2, 14, 15, 55, 100, time.UTC),
+			end:           time.Date(2025, 5, 2, 14, 15, 55, 99, time.UTC),
+			expectedStart: time.Date(2025, 5, 2, 14, 15, 55, 100, time.UTC),
+			expectedEnd:   time.Date(2025, 5, 2, 14, 15, 55, 100, time.UTC),
+		},
+		{
+			name:          "zero times",
+			start:         time.Time{},
+			end:           time.Time{},
+			expectedStart: time.Time{},
+			expectedEnd:   time.Time{},
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			gotStart, gotEnd := correctActionTimestamps(tt.start, tt.end)
+
+			require.Equal(t, tt.expectedStart, gotStart, "start timestamp mismatch")
+			require.Equal(t, tt.expectedEnd, gotEnd, "end timestamp mismatch")
+
+			// Verify the invariant: end is never before start
+			require.False(t, gotEnd.Before(gotStart), "end timestamp should not be before start timestamp")
+		})
+	}
+}