Skip to content

Commit 722e97d

Browse files
taha-autaha-au
authored
fix: prevent ~30s hangs in setup and post steps (#99)
Both the setup and post steps were each spending ~30s of dead air after the action's JS work had finished. Pre-fix, every job using setup-docker-builder paid ~60s of pure wall-clock latency for nothing. Cause: createBlacksmithAgentClient() built a fresh @connectrpc/connect-node gRPC transport on every call, opening an HTTP/2 session via http2.connect() that was never close()d or abort()ed. Open HTTP/2 sessions hold a ref'd handle on the Node event loop, so the action's process couldn't exit until the Blacksmith agent's server-side idle timeout (~30s) closed the connection for it. This happened twice per job: once in setup (reportMetric + getStickyDisk) and once in post (reportMetric + commitStickyDisk). Fix: - Cache one Http2SessionManager + gRPC client per process and reuse it across all reporter calls. - Add closeBlacksmithAgentClient() that aborts the cached session. - Call it at the end of both the main and post action bodies, followed by setImmediate(() => process.exit(process.exitCode ?? 0)) as a belt-and-suspenders against any other stray open handle (axios keep-alive, fs watcher, etc.). Also adds .github/workflows/step-duration-regression.yml: a regression test that exercises the action against a Blacksmith runner, queries the Actions API for the resulting step timings, and fails CI if either the setup or post step exceeds 5s. Triggers on PRs, push to main, manual dispatch, and once daily so we also catch upstream regressions when the action source itself hasn't changed. A/B vs main on the validation run: setup 32s -> 3s, post 30s -> 1s.
1 parent 86ab255 commit 722e97d

5 files changed

Lines changed: 207 additions & 7 deletions

File tree

‎.github/workflows/step-duration-regression.yml‎

Lines changed: 143 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,143 @@
1+
name: Step Duration Regression
2+
3+
# Fails CI if the action's setup or post step exceeds STEP_MAX_SECONDS.
4+
# Catches regressions of the dangling-Http2Session class of bug that
5+
# silently added ~30s per step.
6+
7+
on:
8+
workflow_dispatch:
9+
pull_request:
10+
push:
11+
branches: [main]
12+
schedule:
13+
- cron: "17 6 * * *"
14+
15+
env:
16+
STEP_MAX_SECONDS: "5"
17+
SETUP_STEP_NAME: "Setup Docker Builder under test"
18+
19+
jobs:
20+
exercise-action:
21+
name: Run build with setup-docker-builder
22+
runs-on: blacksmith
23+
steps:
24+
- name: Checkout
25+
uses: actions/checkout@v6
26+
27+
- name: ${{ env.SETUP_STEP_NAME }}
28+
uses: ./
29+
with:
30+
buildx-version: v0.23.0
31+
32+
- name: Trivial build
33+
run: |
34+
cat > Dockerfile.test <<'EOF'
35+
FROM alpine:3.20
36+
RUN echo "step-duration-regression"
37+
EOF
38+
docker buildx build -f Dockerfile.test --load -t setup-docker-builder-regression:local .
39+
40+
validate-step-durations:
41+
name: Validate step durations
42+
needs: exercise-action
43+
if: always()
44+
runs-on: blacksmith
45+
permissions:
46+
actions: read
47+
contents: read
48+
steps:
49+
- name: Assert setup and post steps stay under threshold
50+
env:
51+
GH_TOKEN: ${{ github.token }}
52+
RUN_ID: ${{ github.run_id }}
53+
REPO: ${{ github.repository }}
54+
MAX_SECONDS: ${{ env.STEP_MAX_SECONDS }}
55+
SETUP_STEP_NAME: ${{ env.SETUP_STEP_NAME }}
56+
TARGET_JOB_NAME: "Run build with setup-docker-builder"
57+
run: |
58+
set -euo pipefail
59+
60+
echo "Fetching steps for run ${RUN_ID} in ${REPO}..."
61+
jobs_json=$(gh api \
62+
-H "Accept: application/vnd.github+json" \
63+
"repos/${REPO}/actions/runs/${RUN_ID}/jobs?per_page=100")
64+
65+
setup_name="${SETUP_STEP_NAME}"
66+
post_name="Post ${SETUP_STEP_NAME}"
67+
68+
# Returns step duration in seconds, or "MISSING".
69+
step_duration_seconds() {
70+
local job="$1"
71+
local step="$2"
72+
73+
local line
74+
line=$(echo "$jobs_json" | jq -r \
75+
--arg job "$job" --arg step "$step" '
76+
.jobs[] | select(.name == $job) | .steps[] | select(.name == $step) |
77+
"\(.started_at) \(.completed_at)"
78+
')
79+
80+
local started completed
81+
started=$(echo "$line" | awk '{print $1}')
82+
completed=$(echo "$line" | awk '{print $2}')
83+
84+
if [[ -z "${started:-}" || -z "${completed:-}" \
85+
|| "${started}" == "null" || "${completed}" == "null" ]]; then
86+
echo "MISSING"
87+
return
88+
fi
89+
90+
local s c
91+
s=$(date -u -d "$started" +%s)
92+
c=$(date -u -d "$completed" +%s)
93+
echo $(( c - s ))
94+
}
95+
96+
echo ""
97+
echo "=== ${TARGET_JOB_NAME} steps ==="
98+
echo "$jobs_json" | jq -r --arg job "$TARGET_JOB_NAME" '
99+
.jobs[] | select(.name == $job) | .steps[] |
100+
" step=\"\(.name)\" started=\(.started_at) completed=\(.completed_at) conclusion=\(.conclusion)"
101+
'
102+
103+
setup_duration=$(step_duration_seconds "$TARGET_JOB_NAME" "$setup_name")
104+
post_duration=$(step_duration_seconds "$TARGET_JOB_NAME" "$post_name")
105+
106+
echo ""
107+
echo "Setup step (\"${setup_name}\"): ${setup_duration}s"
108+
echo "Post step (\"${post_name}\"): ${post_duration}s"
109+
echo "Threshold: ${MAX_SECONDS}s"
110+
111+
{
112+
echo "## Step Durations"
113+
echo ""
114+
echo "| Step | Duration | Threshold |"
115+
echo "|---|---:|---:|"
116+
echo "| Setup (\`${setup_name}\`) | **${setup_duration}s** | ${MAX_SECONDS}s |"
117+
echo "| Post (\`${post_name}\`) | **${post_duration}s** | ${MAX_SECONDS}s |"
118+
} >> "$GITHUB_STEP_SUMMARY"
119+
120+
fail=0
121+
122+
assert_under_threshold() {
123+
local label="$1" value="$2"
124+
if [[ "$value" == "MISSING" ]]; then
125+
echo "::error::Could not find ${label} step in job \"${TARGET_JOB_NAME}\". Did the previous job fail before the step ran?"
126+
fail=1
127+
return
128+
fi
129+
if (( value > MAX_SECONDS )); then
130+
echo "::error::${label} step took ${value}s (> ${MAX_SECONDS}s threshold). Check for dangling open handles (Http2Session, axios keep-alive, fs watcher) at the end of the action body."
131+
fail=1
132+
fi
133+
}
134+
135+
assert_under_threshold "setup" "$setup_duration"
136+
assert_under_threshold "post" "$post_duration"
137+
138+
if (( fail )); then
139+
exit 1
140+
fi
141+
142+
echo ""
143+
echo "Both steps are within threshold."

‎dist/index.js‎

Lines changed: 1 addition & 1 deletion
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎dist/index.js.map‎

Lines changed: 1 addition & 1 deletion
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎src/main.ts‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -760,6 +760,11 @@ void actionsToolkit.run(
760760
}
761761

762762
stateHelper.setTmpDir(Context.tmpDir());
763+
764+
// Close the gRPC client and force-exit so a leaked open handle (HTTP/2
765+
// session, axios keep-alive, etc.) cannot delay the step by ~30s.
766+
reporter.closeBlacksmithAgentClient();
767+
setImmediate(() => process.exit(process.exitCode ?? 0));
763768
},
764769
// post action - cleanup
765770
async () => {
@@ -973,6 +978,10 @@ void actionsToolkit.run(
973978
"Expose ID not found in state, skipping sticky disk commit",
974979
);
975980
}
981+
982+
// See main step: close gRPC client + force-exit to avoid ~30s hang.
983+
reporter.closeBlacksmithAgentClient();
976984
});
985+
setImmediate(() => process.exit(process.exitCode ?? 0));
977986
},
978987
);

‎src/reporter.ts‎

Lines changed: 53 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -2,8 +2,11 @@ import * as core from "@actions/core";
22
import axios from "axios";
33
import axiosRetry from "axios-retry";
44
import { create } from "@bufbuild/protobuf";
5-
import { createClient } from "@connectrpc/connect";
6-
import { createGrpcTransport } from "@connectrpc/connect-node";
5+
import { Client, createClient } from "@connectrpc/connect";
6+
import {
7+
createGrpcTransport,
8+
Http2SessionManager,
9+
} from "@connectrpc/connect-node";
710
import {
811
MetricSchema,
912
Metric_MetricType,
@@ -44,15 +47,60 @@ const createBlacksmithAPIClient = () => {
4447
return client;
4548
};
4649

47-
export function createBlacksmithAgentClient() {
50+
// Cached so we open a single HTTP/2 session per process. The session must
51+
// be torn down via closeBlacksmithAgentClient() before the action exits,
52+
// otherwise it keeps the Node event loop alive for ~30s.
53+
let cachedAgentSessionManager: Http2SessionManager | undefined;
54+
let cachedAgentClient: Client<typeof StickyDiskService> | undefined;
55+
let cachedAgentBaseUrl: string | undefined;
56+
57+
export function createBlacksmithAgentClient(): Client<
58+
typeof StickyDiskService
59+
> {
60+
const baseUrl = `http://192.168.127.1:${process.env.BLACKSMITH_STICKY_DISK_GRPC_PORT || "5557"}`;
61+
62+
if (cachedAgentClient && cachedAgentBaseUrl === baseUrl) {
63+
return cachedAgentClient;
64+
}
65+
66+
if (cachedAgentSessionManager) {
67+
try {
68+
cachedAgentSessionManager.abort();
69+
} catch {
70+
// best-effort
71+
}
72+
}
73+
4874
core.info(
4975
`Creating Blacksmith agent client with port: ${process.env.BLACKSMITH_STICKY_DISK_GRPC_PORT || "5557"}`,
5076
);
77+
78+
cachedAgentSessionManager = new Http2SessionManager(baseUrl);
5179
const transport = createGrpcTransport({
52-
baseUrl: `http://192.168.127.1:${process.env.BLACKSMITH_STICKY_DISK_GRPC_PORT || "5557"}`,
80+
baseUrl,
81+
sessionManager: cachedAgentSessionManager,
5382
});
83+
cachedAgentClient = createClient(StickyDiskService, transport);
84+
cachedAgentBaseUrl = baseUrl;
85+
86+
return cachedAgentClient;
87+
}
5488

55-
return createClient(StickyDiskService, transport);
89+
// Must be called before the action exits. See cache comment above.
90+
// Safe to call multiple times.
91+
export function closeBlacksmithAgentClient(): void {
92+
if (cachedAgentSessionManager) {
93+
try {
94+
cachedAgentSessionManager.abort();
95+
} catch (error) {
96+
core.debug(
97+
`Failed to abort Blacksmith agent session: ${(error as Error).message}`,
98+
);
99+
}
100+
cachedAgentSessionManager = undefined;
101+
}
102+
cachedAgentClient = undefined;
103+
cachedAgentBaseUrl = undefined;
56104
}
57105

58106
export async function reportBuildPushActionFailure(

0 commit comments

Comments
 (0)