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
 
root / src / common / c-sqlite3.c
Author[]Andy Green <andy@warmcat.com> 2026-09-26 14:44 UTC
Committer[]Andy Green <andy@warmcat.com> 2026-09-26 14:44 UTC
Tree9fa53389a4f28a2310b514535fbed1d0b8cff537   Raw Patch
 
server: say in a task's log why the server failed or restarted it
server: say in a task's log why the server failed or restarted it

A builder cannot always explain itself.  It is often a VM that just went
away, and anything it had queued for us went with it, so its log simply
stops after the last thing that got out.  Meanwhile the only paths that
can make a task red are here, and they said nothing at all.

sais_task_logf() puts a line in the task's own log, as ">sais> ", which
is the one record that survives the builder.  The log column holds base64
for the browser to decode and the timestamps are the builder's monotonic
clock, so it encodes the text and borrows the newest timestamp we have for
the task rather than inventing one from our own unrelated clock.

Used where we decide a task's fate and nothing else would say why:

 - a builder disconnecting while one of its tasks was being built.  This
   was entirely silent: the task's log just ended wherever the builder got
   to, and it was quietly reset for another try.  Now the retry's log
   starts by naming the builder and the step it got to
 - deciding SAIES_FAIL from a rejection's ecode, decoded: exited N,
   killed by signal N, timed out, or "finished without saying how it
   ended" for an ecode of 0, which is what an nspawn destroyed without
   ever being reaped reports
 - deciding a task has no more steps and is a success

Also use SAISPRF_TERMINATED rather than the bare 0x2000 for the cancelled
test right next to it.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
diff --git a/src/server/s-private.h b/src/server/s-private.h index 71c3f58..13c4003 100644 --- a/src/server/s-private.h +++ b/src/server/s-private.h @@ -298,6 +298,14 @@ sai_sq3_event_lookup(sqlite3 *pdb, uint64_t start, lws_struct_args_cb cb, void * int sai_sql3_get_uint64_cb(void *user, int cols, char **values, char **name); +/* + * Say something in a task's own log, as the server. Used where we decide a + * task's fate and the builder either cannot say why or is already gone. + */ +int +sais_task_logf(struct vhd *vhd, const char *task_uuid, const char *fmt, ...) + LWS_FORMAT(3); + int sais_validate_id(const char *id, int reqlen); diff --git a/src/server/s-task.c b/src/server/s-task.c index 9d1c9ca..830df05 100644 --- a/src/server/s-task.c +++ b/src/server/s-task.c @@ -1010,6 +1010,9 @@ sais_create_and_offer_task_step(struct vhd *vhd, const char *task_uuid) lwsl_err("%s: +++ determined no more steps after " "build_step %d for task %s, setting SAIES_SUCCESS\n", __func__, build_step, temp_task->uuid); + sais_task_logf(vhd, temp_task->uuid, + "all %d steps completed, task succeeded", + build_step); sais_set_task_state(vhd, temp_task->uuid, SAIES_SUCCESS, 0, 0); if (sais_is_task_inflight(vhd, sp, temp_task->uuid, &u)) diff --git a/src/server/s-ws-builder.c b/src/server/s-ws-builder.c index f72ce04..2d0a2db 100644 --- a/src/server/s-ws-builder.c +++ b/src/server/s-ws-builder.c @@ -28,6 +28,8 @@ #include <libwebsockets.h> #include <string.h> +#include <stdarg.h> +#include <stdio.h> #include <assert.h> #include <time.h> @@ -326,6 +328,78 @@ sais_log_to_db(struct vhd *vhd, sai_log_t *log) */ } +/* + * Say something in a task's own log, as the server. + * + * A builder cannot always explain itself: it may be a VM that just went away, + * and anything it had queued for us went with it. When we are the one deciding + * a task's fate, the reason has to go somewhere the user will find it, and the + * only place that survives is the task's log. + * + * The log column holds base64 the browser decodes, and the timestamps are the + * builder's monotonic clock, so borrow the newest one we have for this task + * rather than inventing a value from our own unrelated clock. + */ + +int +sais_task_logf(struct vhd *vhd, const char *task_uuid, const char *fmt, ...) +{ + char text[512], esc[132], q[224], event_uuid[33]; + uint64_t ts = 0; + sqlite3 *pdb = NULL; + sai_log_t log; + va_list ap; + int n; + + if (!task_uuid || !task_uuid[0]) + return -1; + + n = lws_snprintf(text, sizeof(text), ">sais> "); + + va_start(ap, fmt); + n += vsnprintf(text + n, sizeof(text) - (unsigned int)n - 2, fmt, ap); + va_end(ap); + + if (n > (int)sizeof(text) - 2) + n = (int)sizeof(text) - 2; + text[n++] = '\n'; + text[n] = '\0'; + + lwsl_notice("%s: %s: %s", __func__, task_uuid, text); + + sai_task_uuid_to_event_uuid(event_uuid, task_uuid); + lws_sql_purify(esc, task_uuid, sizeof(esc)); + + if (!sai_event_db_ensure_open(vhd->context, &vhd->sqlite3_cache, + vhd->sqlite3_path_lhs, event_uuid, 0, + &pdb)) { + lws_snprintf(q, sizeof(q), + "select coalesce(max(timestamp), 0) from logs " + "where task_uuid='%s'", esc); + sqlite3_exec(pdb, q, sai_sql3_get_uint64_cb, &ts, NULL); + sai_event_db_close(&vhd->sqlite3_cache, &pdb); + } + + memset(&log, 0, sizeof(log)); + lws_strncpy(log.task_uuid, task_uuid, sizeof(log.task_uuid)); + log.timestamp = ts + 1; + log.channel = 3; + log.len = (size_t)n; + + { + char b64[(sizeof(text) * 4) / 3 + 8]; + + if (lws_b64_encode_string(text, n, b64, (int)sizeof(b64)) < 0) + return -1; + + log.log = b64; + + sais_log_to_db(vhd, &log); + } + + return 0; +} + sai_plat_t * sais_builder_from_uuid(struct vhd *vhd, const char *hostname) { @@ -478,7 +552,7 @@ sais_builder_disconnected(struct vhd *vhd, struct lws *wsi) sqlite3_stmt *sm; lws_snprintf(q, sizeof(q), - "SELECT uuid FROM tasks WHERE " + "SELECT uuid, build_step FROM tasks WHERE " "builder_name=? AND (state = 0 OR state = %d OR state = %d) " "AND run=(SELECT max(run) FROM tasks t2 WHERE t2.uuid = tasks.uuid)", SAIES_PASSED_TO_BUILDER, @@ -488,10 +562,25 @@ sais_builder_disconnected(struct vhd *vhd, struct lws *wsi) sqlite3_bind_text(sm, 1, sp->name, -1, SQLITE_TRANSIENT); while (sqlite3_step(sm) == SQLITE_ROW) { const unsigned char *task_uuid = sqlite3_column_text(sm, 0); + int bs = sqlite3_column_int(sm, 1); + if (task_uuid) { lwsl_notice("%s: resetting task %s from disconnected builder %s\n", __func__, (const char *)task_uuid, sp->name); sais_task_clear_build_and_logs(vhd, (const char *)task_uuid, 0); + + /* + * The builder went away mid-task, so whatever it + * was about to tell us went with it and its log just + * stops. Say so at the top of the retry's log: the + * reset above has already moved us to a new run, so + * this lands there. + */ + sais_task_logf(vhd, (const char *)task_uuid, + "builder %s disconnected while this task was " + "at step %d, so its log stops there; retrying " + "the task from the beginning", + sp->name, bs); } } sqlite3_finalize(sm); @@ -655,9 +744,13 @@ sais_process_rej(struct vhd *vhd, struct pss *pss, n = SAIES_FAIL; lwsl_notice("%s: |||| SAIES_FAIL: %s\n", __func__, rej->task_uuid); + sais_task_logf(vhd, rej->task_uuid, + "builder %s reported the step exited %d, " + "failing the task", sp->name, + rej->ecode & 0xff); } } else - if (rej->ecode & 0x2000) { + if (rej->ecode & SAISPRF_TERMINATED) { n = SAIES_CANCELLED; lwsl_notice("%s: |||| SAIES_CANCELLED: %s\n", __func__, rej->task_uuid); @@ -666,6 +759,30 @@ sais_process_rej(struct vhd *vhd, struct pss *pss, n = SAIES_FAIL; lwsl_notice("%s: |||| SAIES_STEP_FAIL: %s\n", __func__, rej->task_uuid); + + /* + * We are about to make this red, and unlike a + * nonzero exit the builder has no log line that + * matches: an ecode of 0 in particular means it + * never worked out how the step ended + */ + if (rej->ecode & SAISPRF_TIMEDOUT) + sais_task_logf(vhd, rej->task_uuid, + "builder %s timed the step out, " + "failing the task", sp->name); + else + if (rej->ecode & SAISPRF_SIGNALLED) + sais_task_logf(vhd, rej->task_uuid, + "builder %s reported the step " + "was killed by signal %d, " + "failing the task", sp->name, + rej->ecode & 0xff); + else + sais_task_logf(vhd, rej->task_uuid, + "builder %s finished this step " + "without saying how it ended " + "(ecode 0x%x), failing the task", + sp->name, rej->ecode); } if (sais_set_task_state(vhd, rej->task_uuid, n, 0,
Page fetched 0s ago, creation time: 4ms (vhost etag hits: 0%, cache hits: 0%)