improve observability and readiness timeout for buildkitd startup (#112)

Author: ajwerner

dist/index.js

@@ -24,6 +24,7 @@ import {
   getNumCPUs,
   pruneBuildkitCache,
   logBuildCacheContents,
+  logBuildkitdLogTail,
   logDatabaseHashes,
   writeDockerContainerBuildkitdTomlFile,
 } from "./setup_builder";
@@ -494,16 +495,20 @@ async function startBlacksmithBuilder(
 
     // Start buildkitd
     const buildkitdStartTime = Date.now();
-    const buildkitdAddr = await startAndConfigureBuildkitd(
-      parallelism,
-      buildkitdPath,
-      inputs["driver-opts"],
-    );
-    const buildkitdDurationMs = Date.now() - buildkitdStartTime;
-    await reporter.reportMetric(
-      Metric_MetricType.BPA_BUILDKITD_READY_DURATION_MS,
-      buildkitdDurationMs,
-    );
+    let buildkitdAddr: string;
+    try {
+      buildkitdAddr = await startAndConfigureBuildkitd(
+        parallelism,
+        buildkitdPath,
+        inputs["driver-opts"],
+      );
+    } finally {
+      const buildkitdDurationMs = Date.now() - buildkitdStartTime;
+      await reporter.reportMetric(
+        Metric_MetricType.BPA_BUILDKITD_READY_DURATION_MS,
+        buildkitdDurationMs,
+      );
+    }
 
     // Save state for post action
     stateHelper.setExposeId(stickyDiskSetup.exposeId);
@@ -555,7 +560,7 @@ async function maybeShutdownBuildkitd(): Promise<void> {
     core.warning(
       "buildkitd process has crashed - expected to be running but not found",
     );
-    await logBuildkitdCrashLogs();
+    await logBuildkitdLogTail();
     return;
   }
 
@@ -600,18 +605,6 @@ async function maybeShutdownBuildkitd(): Promise<void> {
   }
 }
 
-async function logBuildkitdCrashLogs(): Promise<void> {
-  try {
-    const { stdout } = await execAsync(
-      "tail -n 100 /tmp/buildkitd.log 2>/dev/null || echo 'No buildkitd.log found'",
-    );
-    core.info("Last 100 lines of buildkitd.log:");
-    core.info(stdout);
-  } catch (error) {
-    core.warning(`Could not read buildkitd logs: ${(error as Error).message}`);
-  }
-}
-
 void actionsToolkit.run(
   // main action
   async () => {

dist/index.js.map

@@ -408,8 +408,25 @@ export async function getStickyDisk(options?: {
 
 // buildkitdTimeoutMs states the max amount of time this action will wait for the buildkitd
 // daemon to start have its socket ready. It also additionally governs how long we will wait for
-// the buildkitd workers to be ready.
-const buildkitdTimeoutMs = 30000;
+// the buildkitd workers to be ready. Worker init can be slow when loading a large cache from
+// the sticky disk; falling back to a cold local builder costs far more than waiting here.
+const buildkitdTimeoutMs = 120000;
+
+/**
+ * Logs the tail of the buildkitd daemon log so failures during startup are
+ * visible in the job logs (and shipped to the observability pipeline).
+ */
+export async function logBuildkitdLogTail(): Promise<void> {
+  try {
+    const { stdout } = await execAsync(
+      "tail -n 100 /tmp/buildkitd.log 2>/dev/null || echo 'No buildkitd.log found'",
+    );
+    core.info("Last 100 lines of buildkitd.log:");
+    core.info(stdout);
+  } catch (error) {
+    core.warning(`Could not read buildkitd logs: ${(error as Error).message}`);
+  }
+}
 
 export async function startAndConfigureBuildkitd(
   parallelism: number,
@@ -470,6 +487,12 @@ export async function startAndConfigureBuildkitd(
     core.warning(
       `Error checking buildkit workers: ${(error as Error).message}`,
     );
+    await logBuildkitdLogTail();
+    await reporter.reportBuildPushActionFailure(
+      "BUILDER_STARTUP",
+      error as Error,
+      "buildkitd worker readiness",
+    );
     throw error;
   }