Project homepage Mailing List  Warmcat.com  API Docs  Github Mirror 
    npro  
 Modern all-safe Rust Network Protocol library supporting h1, h2, h3, ws, wt sans-IO and with socket IO + tls
git clone https://npro.rs/repo/npro
Fulltext search
 
root / assets / netbsd-OSX-bigsur.svg.svg
Author[]Andy Green <andy@warmcat.com> 2026-09-25 02:04 UTC
Committer[]Andy Green <andy@warmcat.com> 2026-09-25 02:04 UTC
Tree42ed939f900cc962c38d64ada5a4731369641149   Raw Patch
 
builder: report builder-side task failures in the task's own log 
builder: report builder-side task failures in the task's own log

Builders are commonly transient sai-virt VMs, so by the time anybody
looks at a task that went red, the builder's own log is gone with the
VM.  Several paths that decide a task's fate only said why locally,
which is how tasks ended up red with a log that just stops after the
last successful step:

 - the job dir mkdir, git_helper and step script write failures, and
   lws_spawn_piped() failing to fork / get a pty / exec, all of which
   reach the silent bail: in saib_consider_allocating_task() that fails
   the task with nothing logged
 - the grace-period kill, and giving up on a child that won't die
 - the log spew limit: the one line explaining the kill was produced by
   recursing into saib_log_chunk_create(), which found the limit already
   exceeded and dropped it.  Emit it directly instead
 - an unrecognised child disposition.  lws reports a clean exit as
   CLD_EXITED + si_status and anything else as si_code 0 with
   128 + signal in si_status, and never fills in si_signo, so the
   CLD_KILLED / CLD_DUMPED arms were dead and everything that was not a
   clean exit fell through the switch leaving retcode at 0.  The server
   reads ecode 0 as a failure, giving a red task with no explanation
   anywhere.  Every arm now sets retcode and says what happened

saib_task_logf() is the way to say these things: it goes to the task's
log stream as well as ours, and the stream is not truncated by the
spawned process dying.  It works with or without an nspawn, since the
acceptance path has to be able to explain itself before one exists.

Also move the strictly-increasing log chunk timestamp latch from the
nspawn to the builder.  A task's steps are each their own nspawn, so the
latch reset every step, and the browser pages a task's logs with a
strictly-greater-than timestamp cursor: a step reissuing a timestamp an
earlier step already used has those rows silently never delivered.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

diff --git a/src/builder/b-nspawn.c b/src/builder/b-nspawn.c
index 33a38dc..d0bd5c5 100644
--- a/src/builder/b-nspawn.c
+++ b/src/builder/b-nspawn.c
@@ -24,6 +24,9 @@
 #include <libwebsockets.h>
 
 #include <string.h>
+#include <stdarg.h>
+#include <stdio.h>
+#include <errno.h>
 
 #include <sys/stat.h>
 #include <sys/types.h>
@@ -39,55 +42,46 @@
 
 extern struct lws_vhost *builder_vhost;
 
-int
-saib_log_chunk_create(struct sai_nspawn *ns, void *buf, size_t len, int channel)
+/*
+ * Build and queue one log chunk.  \p task_uuid identifies the task it belongs
+ * to; \p ns may be NULL, in which case there is no retcode to attach and no
+ * spew accounting to do.
+ */
+
+static int
+saib_log_chunk(struct sai_plat_server *spm, struct sai_nspawn *ns,
+	       const char *task_uuid, const void *buf, size_t len, int channel)
 {
 	char lj[2600 + LWS_PRE];
 	lws_usec_t us;
 	int n = 0;
 
-	if (!ns || !ns->spm)
+	if (!spm || !task_uuid || !task_uuid[0])
 		return 1;
 
-	if (!ns->task)
-		return 0;
-
-	{
-		unsigned int limit = ns->task->task_log_limit ? ns->task->task_log_limit : 30000;
-		ns->log_count++;
-
-		if (ns->log_count > limit) {
-			if (!ns->killed_for_spew) {
-				ns->killed_for_spew = 1;
-				if (ns->op && ns->op->lsp) {
-					const char *msg = ">saib> <=== Killed by Sai due to log spew limit exceeded\n";
-					saib_log_chunk_create(ns, (void *)msg, strlen(msg), 3);
-					lws_spawn_piped_kill_child_process(ns->op->lsp);
-				}
-			}
-			return 0;
-		}
-	}
 	/*
 	 * The web pages a task's logs 50 rows at a time with a strictly
 	 * greater-than timestamp cursor, so chunks sharing the timestamp of
 	 * the last row on a page are never delivered.  On Windows the clock
 	 * ticks at a millisecond or coarser, so a burst of chunks readily
-	 * shares one: issue strictly increasing timestamps per nspawn.
+	 * shares one: issue strictly increasing timestamps.  The latch is
+	 * builder-wide rather than per-nspawn, since a task's steps are each
+	 * their own nspawn and must not reissue timestamps an earlier step
+	 * already used.
 	 */
 	us = lws_now_usecs();
-	if (us <= ns->last_log_us)
-		us = ns->last_log_us + 1;
-	ns->last_log_us = us;
+	if (us <= builder.last_log_us)
+		us = builder.last_log_us + 1;
+	builder.last_log_us = us;
 
 	n = lws_snprintf(lj + LWS_PRE, sizeof(lj) - LWS_PRE,
 		"{\"schema\":\"com-warmcat-sai-logs\","
 		 "\"task_uuid\":\"%s\", \"timestamp\": %llu,"
 		 "\"channel\": %d, \"len\": %d, ",
-		 ns->task->uuid, (unsigned long long)us,
+		 task_uuid, (unsigned long long)us,
 		 channel, (int)len);
 
-	if (ns->retcode_set) {
+	if (ns && ns->retcode_set) {
 		n += lws_snprintf(lj + LWS_PRE + n,
 				  sizeof(lj) - LWS_PRE - (unsigned int)n,
 				  "\"finished\":%d,", ns->retcode);
@@ -103,17 +97,95 @@ saib_log_chunk_create(struct sai_nspawn *ns, void *buf, size_t len, int channel)
 			  sizeof(lj) - LWS_PRE - (unsigned int)n,
 			  "\"log\":\"");
 
-	// puts((const char *)&chunk[1]);
-	// puts((const char *)start);
-
 	n += lws_b64_encode_string(buf, (int)len, (char *)&lj[LWS_PRE + n],
 				   (int)sizeof(lj) - LWS_PRE - n - 5);
 
-	lj[LWS_PRE + n++] = '\"';
+	lj[LWS_PRE + n++] = '"';
 	lj[LWS_PRE + n++] = '}';
 	lj[LWS_PRE + n] = '\0';
 
-	return saib_srv_queue_tx(ns->spm->ss, lj + LWS_PRE, (size_t)n, LWSSS_FLAG_SOM | LWSSS_FLAG_EOM);
+	return saib_srv_queue_tx(spm->ss, lj + LWS_PRE, (size_t)n,
+				 LWSSS_FLAG_SOM | LWSSS_FLAG_EOM);
+}
+
+int
+saib_log_chunk_create_uuid(struct sai_plat_server *spm, const char *task_uuid,
+			   const void *buf, size_t len, int channel)
+{
+	return saib_log_chunk(spm, NULL, task_uuid, buf, len, channel);
+}
+
+int
+saib_log_chunk_create(struct sai_nspawn *ns, void *buf, size_t len, int channel)
+{
+	if (!ns || !ns->spm)
+		return 1;
+
+	if (!ns->task)
+		return 0;
+
+	{
+		unsigned int limit = ns->task->task_log_limit ? ns->task->task_log_limit : 30000;
+
+		ns->log_count++;
+
+		if (ns->log_count > limit) {
+			if (!ns->killed_for_spew) {
+				const char *msg = ">saib> <=== Killed by Sai due to log spew limit exceeded\n";
+
+				ns->killed_for_spew = 1;
+
+				/*
+				 * Say so directly rather than recursively:
+				 * re-entering here would find the limit
+				 * already exceeded and silently drop the one
+				 * message that explains the kill.
+				 */
+				saib_log_chunk(ns->spm, ns, ns->task->uuid,
+					       msg, strlen(msg), 3);
+
+				if (ns->op && ns->op->lsp)
+					lws_spawn_piped_kill_child_process(ns->op->lsp);
+			}
+			return 0;
+		}
+	}
+
+	return saib_log_chunk(ns->spm, ns, ns->task->uuid, buf, len, channel);
+}
+
+/*
+ * Report a builder-side problem with a task in the task's own log, as well as
+ * in our local log.  The builders are often transient VMs whose local logs are
+ * gone by the time anybody looks, so anything that decides a task's fate has to
+ * say why in the stream that goes to the server.
+ */
+
+int
+saib_task_logf(struct sai_plat_server *spm, struct sai_nspawn *ns,
+	       const char *task_uuid, const char *fmt, ...)
+{
+	char s[512];
+	va_list ap;
+	int n;
+
+	n = lws_snprintf(s, sizeof(s), ">saib> ");
+
+	va_start(ap, fmt);
+	n += vsnprintf(s + n, sizeof(s) - (unsigned int)n - 2, fmt, ap);
+	va_end(ap);
+
+	if (n > (int)sizeof(s) - 2)
+		n = (int)sizeof(s) - 2;
+	s[n++] = '\n';
+	s[n] = '\0';
+
+	lwsl_warn("%s", s);
+
+	if (ns)
+		return saib_log_chunk_create(ns, s, (size_t)n, 3);
+
+	return saib_log_chunk_create_uuid(spm, task_uuid, s, (size_t)n, 3);
 }
 
 /*
@@ -308,8 +380,19 @@ sai_lsp_reap_cb(void *opaque, const lws_spawn_resource_us_t *res, siginfo_t *si,
 		goto fail;
 	}
 
-	switch (si->si_code) {
-	case CLD_EXITED:
+	/*
+	 * lws reports the disposition as CLD_EXITED + si_status for a clean
+	 * exit, and si_code 0 for anything else, with si_status carrying
+	 * 128 + signal the way a shell does (or -1 if the child was reaped
+	 * elsewhere and we never learned).  si_signo is not filled in, so the
+	 * signal has to come out of si_status.
+	 *
+	 * Every branch must set retcode / retcode_set: leaving them alone
+	 * reports ecode 0 to the server, which it reads as a failure with no
+	 * explanation anywhere.
+	 */
+
+	if (si->si_code == CLD_EXITED) {
 		lwsl_notice("%s: Process Exited with exit code %d\n",
 			    __func__, si->si_status);
 		exit_code = si->si_status;
@@ -317,17 +400,30 @@ sai_lsp_reap_cb(void *opaque, const lws_spawn_resource_us_t *res, siginfo_t *si,
 		ns->retcode = SAISPRF_EXIT | si->si_status;
 		if (ns->user_cancel)
 			ns->retcode = SAISPRF_TERMINATED;
-		break;
-	case CLD_KILLED:
-	case CLD_DUMPED:
-		lwsl_notice("%s: Process Terminated by signal %d / %d\n",
-			    __func__, si->si_status, si->si_signo);
-		ns->retcode = SAISPRF_SIGNALLED | si->si_signo;
+	} else {
+		int sig = si->si_status > 128 ? si->si_status - 128 : 0;
+
+		exit_code = -1;
+
+		if (sig) {
+			saib_task_logf(ns->spm, ns, NULL,
+				       "Build process terminated by signal %d",
+				       sig);
+			ns->retcode = SAISPRF_SIGNALLED | sig;
+		} else {
+			/*
+			 * We know he's gone but not how... don't let it look
+			 * like a clean exit
+			 */
+			saib_task_logf(ns->spm, ns, NULL,
+				       "Build process disappeared without a "
+				       "usable exit status (si_code %d, "
+				       "si_status %d)", si->si_code,
+				       si->si_status);
+			ns->retcode = SAISPRF_TERMINATED;
+		}
+
 		ns->retcode_set = 1;
-		break;
-	default:
-		lwsl_notice("%s: SI code %d\n", __func__, si->si_code);
-		break;
 	}
 #else
 	exit_code = si->retcode & 0xff;
@@ -637,7 +733,9 @@ saib_spawn_script(struct sai_nspawn *ns)
 	fd = open(ns->script_path, O_CREAT | O_TRUNC | O_WRONLY, 0755);
 #endif
 	if (fd < 0) {
-		lwsl_err("%s: unable to open %s for write\n", __func__, ns->script_path);
+		saib_task_logf(ns->spm, ns, NULL,
+			       "Unable to create the step script %s: errno %d (%s)",
+			       ns->script_path, errno, strerror(errno));
 		return 1;
 	}
 
@@ -686,8 +784,12 @@ saib_spawn_script(struct sai_nspawn *ns)
 	/* but from the script's pov, it's chrooted at /home/sai */
 
 	if (write(fd, st, (unsigned int)n) != n) {
+		int en = errno;
+
 		close(fd);
-		lwsl_err("%s: failed to write runscript to %s\n", __func__, ns->script_path);
+		saib_task_logf(ns->spm, ns, NULL,
+			       "Unable to write the step script %s: errno %d (%s)",
+			       ns->script_path, en, strerror(en));
 		return 1;
 	}
 
@@ -753,7 +855,10 @@ saib_spawn_script(struct sai_nspawn *ns)
 	lwsl_user("%s: calling lws_spawn_piped for task uuid %s\n", __func__, ns->task->uuid);
 	lws_spawn_piped(&info);
 	if (!op->lsp) {
-		lwsl_user("%s: lws_spawn_piped failed to provide lsp\n", __func__);
+		saib_task_logf(ns->spm, ns, NULL,
+			       "Unable to spawn the step process (errno %d (%s)): "
+			       "the builder could not fork, allocate a pty or "
+			       "exec %s", errno, strerror(errno), ns->script_path);
 		/*
 		 * op is attached to wsi and will be freed in reap cb,
 		 * we can't free it here
diff --git a/src/builder/b-private.h b/src/builder/b-private.h
index 993acb8..4a07c4b 100644
--- a/src/builder/b-private.h
+++ b/src/builder/b-private.h
@@ -226,6 +226,15 @@ struct sai_builder {
 	uint64_t		disk_total_kib;
 	uint64_t		disk_reserved_kib;
 
+	/*
+	 * Strictly-increasing log chunk timestamp latch.  It is builder-wide
+	 * and not per-nspawn: a task's steps are each a separate nspawn, and
+	 * the browser pages a task's logs with a strictly-greater-than
+	 * timestamp cursor, so a later step issuing a timestamp a previous
+	 * step already used means those rows are never delivered.
+	 */
+	lws_usec_t		last_log_us;
+
 	uint16_t		wrap14;
 	unsigned int		build_timeout_secs;
 
@@ -348,6 +357,26 @@ saib_create_listen_uds(struct lws_context *context, struct saib_logproxy *lp, st
 int
 saib_srv_queue_tx(struct lws_ss_handle *h, void *buf, size_t len, unsigned int ss_flags);
 
+/*
+ * Queue a log chunk for a task that has no nspawn (yet, or ever): the task-
+ * acceptance path needs to be able to explain a refusal or a failed setup in
+ * the task's own log, since that is the only log that survives the builder's
+ * VM going away.
+ */
+int
+saib_log_chunk_create_uuid(struct sai_plat_server *spm, const char *task_uuid,
+			   const void *buf, size_t len, int channel);
+
+/*
+ * Report a builder-side decision about a task into the task's own log (and our
+ * local log).  \p ns may be NULL, in which case \p spm and \p task_uuid say
+ * where it goes.
+ */
+int
+saib_task_logf(struct sai_plat_server *spm, struct sai_nspawn *ns,
+	       const char *task_uuid, const char *fmt, ...)
+	LWS_FORMAT(4);
+
 int
 saib_srv_queue_json_fragments_helper(struct lws_ss_handle *h,
 				     const lws_struct_map_t *map,
diff --git a/src/builder/b-task.c b/src/builder/b-task.c
index c553241..f423e06 100644
--- a/src/builder/b-task.c
+++ b/src/builder/b-task.c
@@ -518,8 +518,14 @@ saib_sub_cleaner_cb(lws_sorted_usec_list_t *sul)
 						 sul_cleaner);
 	lwsl_warn("%s: +++++ Task completion grace period ended with ns alive\n", __func__);
 
-
 	if (ns->op && ns->op->lsp) {
+		if (!ns->term_budget)
+			saib_task_logf(ns->spm, ns, NULL,
+				       "Step %d completed but its process is "
+				       "still alive after the grace period, "
+				       "terminating it",
+				       ns->task ? ns->task->build_step + 1 : 0);
+
 		lwsl_notice("%s: +++++++++++ killing child process (budget %d)\n", __func__, ns->term_budget);
 		lws_spawn_piped_kill_child_process(ns->op->lsp);
 
@@ -533,6 +539,11 @@ saib_sub_cleaner_cb(lws_sorted_usec_list_t *sul)
 			return;
 		}
 
+		saib_task_logf(ns->spm, ns, NULL,
+			       "Unable to terminate the step process, "
+			       "abandoning it: the builder may have a stray "
+			       "process left behind");
+
 		lwsl_err("%s: ============= unable to kill child process -> destroying ns forcibly\n", __func__);
 		/*
 		 * It refused to die after a few seconds... we are giving up on it.
@@ -874,7 +885,7 @@ saib_consider_allocating_task(struct sai_plat_server *spm, lws_struct_args_t *a,
 		script_path[512];
 	sai_plat_t *sp = NULL;
 	struct sai_nspawn *ns;
-	int n, en, ml, fd;
+	int n, en = 0, ml, fd;
 	sai_task_t *task;
 
 	task = (sai_task_t *)a->dest;
@@ -979,6 +990,14 @@ saib_consider_allocating_task(struct sai_plat_server *spm, lws_struct_args_t *a,
 	memset(ns, 0, sizeof(*ns));
 	ns->builder	= &builder;
 	ns->sp		= sp;
+	/*
+	 * Bind the task and the server connection immediately: every failure
+	 * path from here on wants to be able to say what went wrong in the
+	 * task's own log, and nothing should ever see an nspawn on the list
+	 * with no task.
+	 */
+	ns->task	= task;
+	ns->spm		= spm;
 
 	/*
 	 * Find the lowest free ordinal and use that.  It doesn't
@@ -1076,13 +1095,7 @@ saib_consider_allocating_task(struct sai_plat_server *spm, lws_struct_args_t *a,
 	ns->hash		= task->git_hash;
 	ns->git_repo_url	= task->git_repo_url;
 
-	if (ns->task && ns->task->ac_task_container) {
-		struct lwsac *ac = ns->task->ac_task_container;
-		lwsac_free(&ac);
-	}
-
-	ns->task		= task; /* we are owning this nspawn for the duration */
-	ns->spm			= spm; /* bind this task to the spm the req came in on */
+	/* ns->task / ns->spm were bound when the nspawn was created */
 
 	if (!ns->task->build_step) {
 		ns->spins	= 0;
@@ -1177,14 +1190,18 @@ saib_consider_allocating_task(struct sai_plat_server *spm, lws_struct_args_t *a,
 			ns->inp, csep);
 	fd = open(script_path, O_CREAT | O_TRUNC | O_WRONLY, 0755);
 	if (fd < 0) {
-		lwsl_warn("%s: failed to open git script for write %s\n",
-			  __func__, script_path);
+		saib_task_logf(spm, ns, NULL,
+			       "Unable to create %s: errno %d (%s)",
+			       script_path, errno, strerror(errno));
 		goto bail;
 	}
 
 	if ((size_t)write(fd, git_helper_sh, strlen(git_helper_sh)) != strlen(git_helper_sh)) {
-		lwsl_warn("%s: failed to write git script %s\n", __func__, script_path);
+		en = errno;
 		close(fd);
+		saib_task_logf(spm, ns, NULL,
+			       "Unable to write %s: errno %d (%s)",
+			       script_path, en, strerror(en));
 		goto bail;
 	}
 	close(fd);
@@ -1196,13 +1213,18 @@ saib_consider_allocating_task(struct sai_plat_server *spm, lws_struct_args_t *a,
 			_SH_DENYNO, _S_IWRITE))
 		fd = -1;
 	if (fd < 0) {
-		lwsl_warn("%s: failed to open git script for write %s\n", __func__, script_path);
+		saib_task_logf(spm, ns, NULL,
+			       "Unable to create %s: errno %d (%s)",
+			       script_path, errno, strerror(errno));
 		goto bail;
 	}
 
 	if ((size_t)write(fd, git_helper_bat, (unsigned int)strlen(git_helper_bat)) != strlen(git_helper_bat)) {
-		lwsl_warn("%s: failed to write git script %s\n", __func__, script_path);
+		en = errno;
 		close(fd);
+		saib_task_logf(spm, ns, NULL,
+			       "Unable to write %s: errno %d (%s)",
+			       script_path, en, strerror(en));
 		goto bail;
 	}
 	close(fd);
@@ -1237,10 +1259,21 @@ saib_consider_allocating_task(struct sai_plat_server *spm, lws_struct_args_t *a,
 	return 0;
 
 ebail:
-	lwsl_err("%s: unable to create %s\n", __func__, ns->inp);
+	saib_task_logf(spm, ns, NULL,
+		       "Unable to create the job dir %s: errno %d (%s)",
+		       ns->inp, en, strerror(en));
 
 bail:
-	lwsl_notice("%s: failing spawn cleanly\n", __func__);
+	/*
+	 * We are about to report this step as failed with nothing in the log to
+	 * say why, unless one of the paths that got us here already did.  These
+	 * builders are often transient VMs, so the local log is no help after
+	 * the fact.
+	 */
+	saib_task_logf(spm, ns, NULL,
+		       "Builder %s could not start step %d, failing the task",
+		       sp->name, ns->task ? ns->task->build_step + 1 : 0);
+
 	saib_set_ns_state(ns, NSSTATE_FAILED);
 	saib_task_grace(ns);
 
diff --git a/src/common/include/private.h b/src/common/include/private.h
index ff6ba46..0211a91 100644
--- a/src/common/include/private.h
+++ b/src/common/include/private.h
@@ -299,7 +299,6 @@ struct sai_nspawn {
 	sai_task_t			*task;
 
 	unsigned int			log_count;
-	lws_usec_t			last_log_us; /* last chunk timestamp issued */
 	unsigned int			killed_for_spew:1;
 
 	struct lws			*stdwsi[3];
Page fetched 0s ago, creation time: 5ms (vhost etag hits: 0%, cache hits: 0%)