Skip to content

Commit e30b70f

Browse files
committed
detect canceled/timed-out jobs in build analysis, improve use of "jq"
1 parent 557aaab commit e30b70f

4 files changed

Lines changed: 163 additions & 8 deletions

File tree

.claude/skills/troubleshoot-ci-build/SKILL.md

Lines changed: 45 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -144,6 +144,18 @@ The script automatically:
144144
- integration_tests_windows
145145
...
146146

147+
**Timed Out Jobs** (<count>, canceled after ~60 min):
148+
- `DockerTest alpine_netcoreapp3.0_group1 (60.3 min)`
149+
- `IntegrationTests Windows x64 net8.0 (58.7 min)`
150+
...
151+
_(Note: These are jobs with result="canceled" and duration >= 55 minutes)_
152+
153+
**Collateral Cancellations** (<count>, < 5 min):
154+
- `Dependent Job 1`
155+
- `Dependent Job 2`
156+
...
157+
_(Note: Jobs canceled quickly, likely due to parent stage failure)_
158+
147159
**Failed Tests** (<count>, if applicable):
148160
- `TestNamespace.TestClass.TestMethod1`
149161
- `TestNamespace.TestClass.TestMethod2`
@@ -249,6 +261,7 @@ Timeout waiting for spans
249261
- Docker rate limiting: `toomanyrequests`, `pull rate limit exceeded`
250262
- Network timeouts: `TLS handshake timeout`, `Connection reset by peer`, `ECONNRESET`
251263
- Execution timeouts: `maximum execution time exceeded`, `Test timeout`
264+
- Timeout via cancellation: Job canceled with duration >= 55 minutes
252265
- Disk space: `No space left on device`, `ENOSPC`
253266
- Container failures: `docker: Error response from daemon`
254267

@@ -411,6 +424,23 @@ jq '[.records[] | select(.result == "failed")] | .[0:10]'
411424
--query-parameters branchName=refs/heads/master '$top=10'
412425
```
413426

427+
### 5. jq Pitfalls with Nullable Fields
428+
429+
**Problem**: Using `startswith()`, `contains()`, or `test()` on nullable fields causes errors when the field is null
430+
431+
**Solution**: Guard with `!= null` or use `// ""` default value
432+
433+
```bash
434+
# ❌ BAD - Fails if .name is null
435+
jq '.records[] | select(.name | startswith("Test"))'
436+
437+
# ✅ GOOD - Guard with null check
438+
jq '.records[] | select(.name != null and (.name | startswith("Test")))'
439+
440+
# ✅ GOOD - Use default value
441+
jq '.records[] | select((.name // "") | startswith("Test"))'
442+
```
443+
414444
## Error Handling
415445

416446
### Build Not Found
@@ -522,6 +552,21 @@ The Azure DevOps timeline contains a hierarchy:
522552
- Failed stages/jobs cascade down - focus on Task-level failures for specifics
523553
- Job `identifier` field reveals platform/variant info (e.g., `integration_tests_linux.Test.Job23`)
524554

555+
### Canceled Jobs and Timeout Detection
556+
557+
**Result values**: `"succeeded"`, `"failed"`, `"canceled"`, `"abandoned"`
558+
559+
**Canceled vs Failed**: Jobs canceled due to timeout have `result == "canceled"`, NOT `"failed"`.
560+
561+
**Duration-based Classification**:
562+
- **Timeout** (>= 55 min): Job likely hit Azure DevOps 60-minute timeout
563+
- **Collateral** (< 5 min): Job canceled quickly due to parent stage failure
564+
- **Unknown** (5-55 min): Could be manual cancellation or other cause
565+
566+
**Key Rule**: If a stage shows `result == "failed"` but no jobs have `result == "failed"`, check for canceled jobs with duration >= 55 minutes. These are likely timeouts that caused the stage failure.
567+
568+
**Example**: Build 195486 - `integration_tests_linux` stage failed with no failed jobs, but `DockerTest alpine_netcoreapp3.0_group1` was canceled after 60.3 minutes (timeout).
569+
525570
### Understanding Test Results
526571

527572
1. **Build warnings vs test failures**:

.claude/skills/troubleshoot-ci-build/failure-patterns.md

Lines changed: 43 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,32 @@ Test run timed out after 600000 ms
5757
- Retry the build
5858
- If persistent, investigate test performance
5959

60+
#### Timeout via Cancellation
61+
62+
**Detection**: Jobs with `result == "canceled"` and duration >= 55 minutes
63+
64+
**Why not "failed"?**: Azure DevOps marks timed-out jobs as "canceled" rather than "failed".
65+
66+
**Differentiation**:
67+
| Duration | Classification | Likely Cause |
68+
|----------|---------------|--------------|
69+
| >= 55 min | Timeout | Azure DevOps 60-min limit exceeded |
70+
| < 5 min | Collateral | Parent stage failure triggered cascade cancellation |
71+
| 5-55 min | Unknown | Could be manual cancellation or other cause |
72+
73+
**Example**: Build 195486
74+
- Stage: `integration_tests_linux` - result: "failed"
75+
- Job: `DockerTest alpine_netcoreapp3.0_group1` - result: "canceled", duration: 60.3 min
76+
- Diagnosis: Job timed out, causing stage to fail
77+
- Action: Retry once; investigate if persistent (check test performance, resource contention)
78+
79+
**Solution**:
80+
- Retry the build (may be transient infrastructure slowness)
81+
- If persistent after 2 runs, investigate:
82+
- Check job logs for stuck tests or infinite loops
83+
- Look for resource contention (CPU, memory, I/O)
84+
- Compare with successful runs to identify anomalies
85+
6086
---
6187

6288
### Disk Space
@@ -359,15 +385,22 @@ Expected tracer log but found none
359385
## Categorization Decision Tree
360386

361387
```
362-
Is the failure in this PR only (not in master)?
363-
├─ Yes → **Real Failure** (investigate)
364-
└─ No → Is it an infrastructure issue?
365-
├─ Yes → **Infrastructure** (retry)
366-
└─ No → Does it have previousAttempts > 0?
367-
├─ Yes → **Flaky** (retry, monitor)
368-
└─ No → Is it a known flaky test?
388+
Are there canceled jobs?
389+
├─ Yes → Check duration:
390+
│ ├─ >= 55 min → **Timeout** (infrastructure, retry)
391+
│ ├─ < 5 min → **Collateral Cancellation** (check parent failure)
392+
│ └─ 5-55 min → **Unknown** (review manually, could be manual cancellation)
393+
394+
└─ No canceled jobs or after classifying them →
395+
Is the failure in this PR only (not in master)?
396+
├─ Yes → **Real Failure** (investigate)
397+
└─ No → Is it an infrastructure issue?
398+
├─ Yes → **Infrastructure** (retry)
399+
└─ No → Does it have previousAttempts > 0?
369400
├─ Yes → **Flaky** (retry, monitor)
370-
└─ No → **Pre-existing Real Failure** (investigate, may be blocking)
401+
└─ No → Is it a known flaky test?
402+
├─ Yes → **Flaky** (retry, monitor)
403+
└─ No → **Pre-existing Real Failure** (investigate, may be blocking)
371404
```
372405

373406
---
@@ -379,6 +412,8 @@ Is the failure in this PR only (not in master)?
379412
| `toomanyrequests`, `rate limit` | Infrastructure | Retry | Low |
380413
| `TLS handshake`, `Connection reset` | Infrastructure | Retry | Low |
381414
| `maximum execution time` | Infrastructure | Retry | Medium |
415+
| Canceled job, duration >= 55 min | Infrastructure (Timeout) | Retry, investigate if persistent | Medium |
416+
| Canceled job, duration < 5 min | Collateral | Check parent failure cause | None |
382417
| `Failed to walk N stacks` | Flaky | Retry, monitor | Low |
383418
| `previousAttempts > 0` | Flaky | Retry | Low |
384419
| `Expected X but got Y` (new) | Real | Investigate | **High** |

.claude/skills/troubleshoot-ci-build/scripts-reference.md

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -108,6 +108,9 @@ When using `-OutputFormat json` or capturing the returned object, the following
108108
| `FailedTasks` | string[] | Array of failed task names |
109109
| `FailedJobs` | string[] | Array of failed job names |
110110
| `FailedStages` | string[] | Array of failed stage names |
111+
| `CanceledJobs` | string[] | Canceled job names |
112+
| `TimedOutJobs` | string[] | Jobs canceled after ~60 min (format: "name (XX.X min)") |
113+
| `CollateralCanceled` | string[] | Jobs canceled in < 5 min |
111114
| `FailedTests` | string[] | Extracted test names (via regex patterns) |
112115
| `ErrorMessages` | string[] | Raw error messages from failed tasks |
113116
| `Comparison` | object | Comparison data (see below) or `null` |
@@ -165,6 +168,16 @@ Comparison uses PowerShell's `Where-Object` with `-notin` operator:
165168

166169
Replaces bash `comm -13` for Windows compatibility.
167170

171+
#### Canceled Job Detection
172+
173+
Jobs with `result == "canceled"` are classified by duration:
174+
175+
- **Timeout** (>= 55 min): Job likely hit Azure DevOps 60-minute timeout. Threshold is 55 minutes (not 60) to account for Azure DevOps timing variance and early cancellation.
176+
- **Collateral** (< 5 min): Job canceled quickly, likely due to parent stage failure triggering cascade cancellation.
177+
- **Unknown** (5-55 min): Could be manual cancellation or other causes.
178+
179+
Duration is calculated from `startTime` and `finishTime` fields in the timeline record.
180+
168181
### Exit Codes
169182

170183
- **0:** Success (build analyzed, data returned)
@@ -186,6 +199,7 @@ Use `-Verbose` to see:
186199
2. **Log URL Availability:** Some tasks may not have `.log.url` populated
187200
3. **Master Build Lookup:** Checks only last 10 builds; may fail if no successful build in range
188201
4. **Performance:** Downloads full timeline JSON (can be large for multi-stage pipelines)
202+
5. **Canceled Job Classification:** Duration-based heuristic may misclassify manual cancellations that occur between 5-55 minutes. In practice, most manual cancellations happen quickly (< 5 min) or timeouts occur at ~60 min, so this range is rare.
189203

190204
### Related Documentation
191205

tracer/tools/Get-AzureDevOpsBuildAnalysis.ps1

Lines changed: 61 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -189,6 +189,48 @@ function Get-FailedRecords {
189189
}
190190
}
191191

192+
function Get-CanceledRecords {
193+
param(
194+
[object]$Timeline,
195+
[string]$Type
196+
)
197+
198+
$canceledRecords = $Timeline.records | Where-Object {
199+
$_.result -eq 'canceled' -and $_.type -eq $Type
200+
}
201+
202+
$results = @()
203+
foreach ($record in $canceledRecords) {
204+
$durationMinutes = 0
205+
$classification = 'unknown'
206+
207+
if ($record.startTime -and $record.finishTime) {
208+
$startTime = [datetime]::Parse($record.startTime)
209+
$finishTime = [datetime]::Parse($record.finishTime)
210+
$durationMinutes = ($finishTime - $startTime).TotalMinutes
211+
}
212+
213+
# Classify based on duration
214+
# >= 55 min: likely timeout (Azure DevOps has 60 min default)
215+
# < 5 min: likely collateral damage from parent cancellation
216+
# 5-55 min: unknown (could be manual cancellation or other)
217+
if ($durationMinutes -ge 55) {
218+
$classification = 'timeout'
219+
}
220+
elseif ($durationMinutes -lt 5) {
221+
$classification = 'collateral'
222+
}
223+
224+
$results += [PSCustomObject]@{
225+
Name = $record.name
226+
DurationMinutes = [math]::Round($durationMinutes, 1)
227+
Classification = $classification
228+
}
229+
}
230+
231+
return $results
232+
}
233+
192234
#endregion
193235

194236
try {
@@ -232,6 +274,10 @@ try {
232274
$failedJobs = @(Get-FailedRecords -Timeline $timeline -Type 'Job')
233275
$failedStages = @(Get-FailedRecords -Timeline $timeline -Type 'Stage')
234276

277+
$canceledJobs = @(Get-CanceledRecords -Timeline $timeline -Type 'Job')
278+
$timedOutJobs = @($canceledJobs | Where-Object { $_.Classification -eq 'timeout' })
279+
$collateralCanceledJobs = @($canceledJobs | Where-Object { $_.Classification -eq 'collateral' })
280+
235281
$errorMessages = @($failedTasks | ForEach-Object {
236282
$_.issues | Where-Object { $_.type -eq 'error' } | ForEach-Object { $_.message }
237283
})
@@ -251,6 +297,9 @@ try {
251297
FailedTasks = @($failedTasks | ForEach-Object { $_.name })
252298
FailedJobs = @($failedJobs | ForEach-Object { $_.name })
253299
FailedStages = @($failedStages | ForEach-Object { $_.name })
300+
CanceledJobs = @($canceledJobs | ForEach-Object { $_.Name })
301+
TimedOutJobs = @($timedOutJobs | ForEach-Object { "$($_.Name) ($($_.DurationMinutes) min)" })
302+
CollateralCanceled = @($collateralCanceledJobs | ForEach-Object { $_.Name })
254303
FailedTests = $failedTests
255304
ErrorMessages = $errorMessages
256305
Comparison = $null
@@ -364,6 +413,8 @@ try {
364413
Write-Host " Failed Jobs: " -NoNewline; Write-Host $result.FailedJobs.Count -ForegroundColor Green
365414
Write-Host " Failed Tasks: " -NoNewline; Write-Host $result.FailedTasks.Count -ForegroundColor Green
366415
Write-Host " Failed Tests: " -NoNewline; Write-Host $result.FailedTests.Count -ForegroundColor Green
416+
Write-Host " Timed Out: " -NoNewline; Write-Host $result.TimedOutJobs.Count -ForegroundColor Yellow
417+
Write-Host " Canceled: " -NoNewline; Write-Host $result.CanceledJobs.Count -ForegroundColor DarkGray
367418

368419
if ($result.FailedStages.Count -gt 0) {
369420
Write-Host "`nFailed Stages:" -ForegroundColor Red
@@ -380,6 +431,16 @@ try {
380431
$result.FailedTasks | ForEach-Object { Write-Host " - $_" -ForegroundColor DarkGray }
381432
}
382433

434+
if ($result.TimedOutJobs.Count -gt 0) {
435+
Write-Host "`nTimed Out Jobs (canceled after ~60 min):" -ForegroundColor Yellow
436+
$result.TimedOutJobs | ForEach-Object { Write-Host " - $_" -ForegroundColor DarkGray }
437+
}
438+
439+
if ($result.CollateralCanceled.Count -gt 0) {
440+
Write-Host "`nCollateral Cancellations (< 5 min, likely parent failure):" -ForegroundColor DarkGray
441+
$result.CollateralCanceled | ForEach-Object { Write-Host " - $_" -ForegroundColor DarkGray }
442+
}
443+
383444
if ($result.FailedTests.Count -gt 0) {
384445
Write-Host "`nFailed Tests:" -ForegroundColor Red
385446
$result.FailedTests | ForEach-Object { Write-Host " - $_" -ForegroundColor DarkGray }

0 commit comments

Comments
 (0)