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 / assets / arch-freertos.svg
Author[]Andy Green <andy@warmcat.com> 2026-09-26 14:44 UTC
Committer[]Andy Green <andy@warmcat.com> 2026-09-26 14:44 UTC
Tree243b27d4737dcfecf5311fa2ad18c5798b3d09b0   Raw Patch
 
web: page task logs on the row uid, and reset the pane when they are replaced
web: page task logs on the row uid, and reset the pane when they are replaced

Two ways a task's log could stop dead in the browser while the build
carried on:

The paging cursor was the log timestamp, which comes from the builder's
lws_now_usecs(), ie its CLOCK_MONOTONIC, which is relative to that
machine's boot.  The query only ever asks for rows strictly newer than
the cursor, so as soon as a builder issues a timestamp at or below what
the browser already has, every row after it is silently never delivered.
That is guaranteed for a builder VM that reboots part way through a task
(these are sai-virt VMs that come up and down), and it was also the
reason a task's steps had to take care not to reissue a timestamp an
earlier step had used, since each step is its own nspawn.

Page on logs.uid instead.  It is the table's autoincrement primary key,
so it only ever increases whatever any builder's clock does, and the rows
were already coming back in uid order.  The browser reports the highest
uid it holds so it still resumes across a reconnect instead of being sent
the whole log again.

The other way is the pane keeping rows that no longer exist.  "Remove all
tries" deletes a task's logs and puts it back to run 0, so the run does
not necessarily change and nothing told the browser to drop what it was
showing; a rebuild or a builder dropping off starts a new run, and the
new lines were appended underneath the old ones.  sai-web now tells the
browser to wipe and start over whenever it is about to send from the
first row, when the rows it holds belong to a run it is no longer looking
at, or when its cursor is ahead of the newest row that exists (which can
only mean the rows it was counting were deleted).

The three copies of the log pane reset in the JS are now one function.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
diff --git a/assets/sai.js b/assets/sai.js index 887ac9f..abed574 100644 --- a/assets/sai.js +++ b/assets/sai.js @@ -404,7 +404,7 @@ const SaiAuthState = { var logs = "", redpend = 0, gitohashi_integ = 0, authd = 0, auth_is_admin = 0, auth_grant_level = -1, auth_state = SaiAuthState.NOT_LOGGED_IN, exptimer, auth_user = "", active_terminals = {}; logAnsiState = {}, logs_pending = "", lines_pending = "", times_pending = "", - ongoing_task_activities = {}, last_log_timestamp = 0, spreadsheet_data_cache = {}, loadreport_data_cache = {}, + ongoing_task_activities = {}, last_log_timestamp = 0, last_log_uid = 0, spreadsheet_data_cache = {}, loadreport_data_cache = {}, watcher_services = [], fadingTasks = new Map(); @@ -2659,15 +2659,7 @@ function clear_task_view() if (stickyEl) stickyEl.innerHTML = ""; if (overviewEl) overviewEl.innerHTML = ""; - lines = times = logs = ""; - lines_pending = times_pending = logs_pending = ""; - segment_stack = []; - seg_counter = 0; - window.held_start_line = null; - logAnsiState = {}; - tfirst = 0; - lli = 1; - last_log_timestamp = 0; + sai_reset_log_pane(0); } function selectEvent(uuid) { @@ -2710,6 +2702,39 @@ function selectEvent(uuid) { } } +/* + * Throw away everything we are showing for a task's logs and start again from + * the first row. The task's rows can go away underneath us: "remove all tries" + * deletes them, and a rebuild or a builder that dropped off starts a new run, + * so sai-web tells us to do this rather than us appending new lines under stale + * ones. Pass 1 to rebuild the log DOM as well. + */ +function sai_reset_log_pane(rebuild_dom) { + lines = times = logs = ""; + lines_pending = times_pending = logs_pending = ""; + segment_stack = []; + seg_counter = 0; + window.held_start_line = null; + window.pending_log_line = ""; + logAnsiState = {}; + tfirst = 0; + lli = 1; + last_log_timestamp = 0; + last_log_uid = 0; + + if (rebuild_dom) { + init_task_logs_dom(); + return; + } + + var dlogsn = document.getElementById("dlogsn"); + var dlogst = document.getElementById("dlogst"); + var dlogs = document.getElementById("dlogs"); + if (dlogsn) dlogsn.innerHTML = ""; + if (dlogst) dlogst.innerHTML = ""; + if (dlogs) dlogs.innerHTML = "<span id=\"logs\" class=\"nowrap\"></span>"; +} + function init_task_logs_dom() { var s = "<table><td colspan=\"3\"><pre><table class=\"scrollogs\"><tr>" + "<td class=\"atop\">" + @@ -2747,24 +2772,14 @@ function selectTask(taskUuid, runVal) { stickyEl.innerHTML = "<div class=\"taskinfo\" id=\"taskinfo-" + san(taskUuid) + "\"></div>"; } - lines = times = logs = ""; - lines_pending = times_pending = logs_pending = ""; - segment_stack = []; - seg_counter = 0; - window.held_start_line = null; - logAnsiState = {}; - tfirst = 0; - lli = 1; - last_log_timestamp = 0; - - init_task_logs_dom(); + sai_reset_log_pane(1); // Request logs from websocket var req = "{\"schema\":" + "\"com.warmcat.sai.taskinfo\"," + "\"js_api_version\": " + SAI_JS_API_VERSION + "," + "\"logs\": 1," + - "\"last_log_ts\":" + last_log_timestamp + ","; + "\"last_log_ts\":" + last_log_timestamp + ",\"last_log_uid\":" + last_log_uid + ","; if (runVal && runVal !== "-1") req += "\"run\":" + runVal + ","; else @@ -3853,7 +3868,7 @@ function ws_open_sai() "\"com.warmcat.sai.taskinfo\"," + "\"js_api_version\": " + SAI_JS_API_VERSION + "," + "\"logs\": 1," + - "\"last_log_ts\":" + last_log_timestamp + ","; + "\"last_log_ts\":" + last_log_timestamp + ",\"last_log_uid\":" + last_log_uid + ","; if (run_idx) req += "\"run\":" + run_idx + ","; else @@ -4593,7 +4608,7 @@ function ws_open_sai() "\"js_api_version\": " + SAI_JS_API_VERSION + "," + "\"logs\": 1," + "\"run\": -1," + - "\"last_log_ts\":" + last_log_timestamp + "," + + "\"last_log_ts\":" + last_log_timestamp + ",\"last_log_uid\":" + last_log_uid + "," + "\"task_hash\":" + JSON.stringify(tid) + "}"; @@ -4777,6 +4792,17 @@ function ws_open_sai() window.location.href = window.location.origin + window.location.pathname; break; + /* + * sai-web is about to send this task's logs from the + * first row again: what we are showing is either gone + * (the task's tries were removed) or belongs to an + * earlier run, so drop it rather than appending under it + */ + case "com.warmcat.sai.logs_reset": + if (jso.task_hash === selected_task_uuid) + sai_reset_log_pane(0); + break; + case "com-warmcat-sai-logs": var s1; try { @@ -4821,6 +4847,8 @@ function ws_open_sai() if (!tfirst) tfirst = jso.timestamp; last_log_timestamp = jso.timestamp; + if (jso.uid > last_log_uid) + last_log_uid = jso.uid; /* normalize CRs to LFs so line number counts track them properly */ if (window._sai_cr_pending && s1.startsWith('\n')) { @@ -5104,23 +5132,9 @@ window.addEventListener("load", function() { sai.send(rs); // Clear logs and re-request taskinfo - var dlogsn = document.getElementById("dlogsn"); - var dlogst = document.getElementById("dlogst"); - var dlogs = document.getElementById("dlogs"); - if (dlogsn) dlogsn.innerHTML = ""; - if (dlogst) dlogst.innerHTML = ""; - if (dlogs) dlogs.innerHTML = "<span id=\"logs\" class=\"nowrap\"></span>"; - lines = times = logs = ""; - lines_pending = times_pending = logs_pending = ""; - segment_stack = []; - seg_counter = 0; - window.held_start_line = null; - logAnsiState = {}; - tfirst = 0; - lli = 1; - last_log_timestamp = 0; - - var rq = "{\"schema\":\"com.warmcat.sai.taskinfo\",\"js_api_version\":" + SAI_JS_API_VERSION + ",\"logs\":1,\"run\":-1,\"last_log_ts\":" + last_log_timestamp + ",\"task_hash\":" + JSON.stringify(tid) + "}"; + sai_reset_log_pane(0); + + var rq = "{\"schema\":\"com.warmcat.sai.taskinfo\",\"js_api_version\":" + SAI_JS_API_VERSION + ",\"logs\":1,\"run\":-1,\"last_log_ts\":" + last_log_timestamp + ",\"last_log_uid\":" + last_log_uid + ",\"task_hash\":" + JSON.stringify(tid) + "}"; console.log(rq); sai.send(rq); } diff --git a/src/common/include/private.h b/src/common/include/private.h index b655921..348edb2 100644 --- a/src/common/include/private.h +++ b/src/common/include/private.h @@ -747,6 +747,18 @@ typedef struct sai_browse_rx_evinfo { typedef struct sai_browse_rx_taskinfo { char task_hash[65]; uint64_t last_log_ts; + /* + * The highest logs.uid the browser already has for this task + run, so + * a reconnecting or refreshing browser resumes where it left off. + * + * This used to be done with last_log_ts, but the log timestamps come + * from the builder's lws_now_usecs(), ie, its CLOCK_MONOTONIC, which is + * relative to that machine's boot: a builder VM that reboots (or any + * other builder taking over) issues timestamps below the cursor and + * every row after that is silently never delivered. uid is the logs + * table's autoincrement primary key, so it only ever increases. + */ + uint64_t last_log_uid; unsigned int log_start; unsigned int js_api_version; unsigned int offset; diff --git a/src/web/w-private.h b/src/web/w-private.h index b0dccd7..e6cac00 100644 --- a/src/web/w-private.h +++ b/src/web/w-private.h @@ -98,6 +98,8 @@ struct pss { struct vhd *vhd; struct lws_dll2 subs_list; uint64_t sub_timestamp; + /* highest logs.uid shipped to this browser for sub_task_uuid + sub_run */ + uint64_t sub_uid; char sub_task_uuid[65]; int sub_run; char specific_ref[65]; @@ -164,6 +166,7 @@ struct pss { struct vhd *vhd; uint64_t first_log_timestamp; uint64_t initial_log_timestamp; + uint64_t initial_log_uid; uint64_t artifact_offset; uint64_t artifact_length; diff --git a/src/web/w-ws-browser.c b/src/web/w-ws-browser.c index 074aed0..aa98528 100644 --- a/src/web/w-ws-browser.c +++ b/src/web/w-ws-browser.c @@ -70,12 +70,18 @@ static lws_struct_map_t lsm_browser_builder_visibility[] = { LSM_UNSIGNED (sai_browse_rx_builder_visibility_t, visible, "visible"), }; +static void +saiw_browser_logs_reset(struct pss *pss); +static int +saiw_browser_logs_cursor_stale(struct vhd *vhd, struct pss *pss); + static lws_struct_map_t lsm_browser_taskinfo[] = { LSM_CARRAY (sai_browse_rx_taskinfo_t, task_hash, "task_hash"), LSM_UNSIGNED (sai_browse_rx_taskinfo_t, logs, "logs"), LSM_UNSIGNED (sai_browse_rx_taskinfo_t, js_api_version, "js_api_version"), LSM_UNSIGNED (sai_browse_rx_taskinfo_t, offset, "offset"), LSM_UNSIGNED (sai_browse_rx_taskinfo_t, last_log_ts, "last_log_ts"), + LSM_UNSIGNED (sai_browse_rx_taskinfo_t, last_log_uid, "last_log_uid"), LSM_SIGNED (sai_browse_rx_taskinfo_t, run, "run"), /* Sidebar selection scoping the overview to project + branch */ LSM_CARRAY (sai_browse_rx_taskinfo_t, project, "project"), @@ -683,6 +689,8 @@ saiw_pss_schedule_taskinfo(struct pss *pss, const char *task_uuid, int logsub, i /* does he want to subscribe to logs? */ if (logsub) { int new_run = run_idx >= 0 ? run_idx : one_task->run; + /* was this pss watching anything before now? */ + int had_sub = !!pss->sub_task_uuid[0]; int is_new_task = strcmp(pss->sub_task_uuid, one_task->uuid); int is_new_run = pss->sub_run != new_run; @@ -693,18 +701,51 @@ saiw_pss_schedule_taskinfo(struct pss *pss, const char *task_uuid, int logsub, i lws_dll2_add_head(&pss->subs_list, &pss->vhd->subs_owner); } - if (is_new_task || is_new_run || pss->initial_log_timestamp == 0) { - pss->sub_timestamp = pss->initial_log_timestamp; + /* + * The browser tells us the highest row it already has, so it can + * resume across a reconnect instead of us shipping the whole log + * again. It sends 0 when it wants the log from the start, which + * is what it does whenever it selects a task. + * + * We have to wipe what it is showing if we are about to send + * from the start, or if the rows it has belong to a run it is no + * longer looking at... otherwise the new lines just pile up + * underneath lines that are not part of this build any more. + */ + + if (!pss->initial_log_uid || + (had_sub && (is_new_task || is_new_run))) { + saiw_browser_logs_reset(pss); saiw_broadcast_logs_batch(pss->vhd, pss); + } else { + pss->sub_uid = pss->initial_log_uid; + pss->sub_timestamp = pss->initial_log_timestamp; + + if (saiw_browser_logs_cursor_stale(pss->vhd, pss)) { + /* the rows it is resuming from are gone */ + saiw_browser_logs_reset(pss); + saiw_broadcast_logs_batch(pss->vhd, pss); + } } } else if (!strcmp(pss->sub_task_uuid, one_task->uuid)) { /* If already subscribed to this task, track new runs automatically */ int new_run = run_idx >= 0 ? run_idx : one_task->run; + if (pss->sub_run != new_run) { pss->sub_run = new_run; - pss->sub_timestamp = 0; + saiw_browser_logs_reset(pss); saiw_broadcast_logs_batch(pss->vhd, pss); - } + } else + /* + * Same task, same run, but the rows may have been + * removed under us: "remove all tries" deletes a task's + * logs and puts it back to run 0, so the run alone does + * not always change + */ + if (saiw_browser_logs_cursor_stale(pss->vhd, pss)) { + saiw_browser_logs_reset(pss); + saiw_broadcast_logs_batch(pss->vhd, pss); + } } saiw_browser_broadcast_queue_builders(pss->vhd, pss); @@ -956,10 +997,13 @@ saiw_ws_json_rx_browser(struct vhd *vhd, struct pss *pss, uint8_t *buf, * as long as needed to send it out */ - if (ti->logs) + if (ti->logs) { pss->initial_log_timestamp = ti->last_log_ts; - else + pss->initial_log_uid = ti->last_log_uid; + } else { pss->initial_log_timestamp = 0; + pss->initial_log_uid = 0; + } if (saiw_pss_schedule_taskinfo(pss, ti->task_hash, !!ti->logs, ti->run)) goto soft_error; @@ -1393,6 +1437,73 @@ saiw_retry_logs(lws_sorted_usec_list_t *sul) saiw_broadcast_logs_batch(pss->vhd, pss); } +/* + * Tell a browser to throw away the log lines it is showing for the task it is + * subscribed to, and start again from the first row. + * + * The task's logs can go away underneath a browser that is looking at them: + * "remove all tries" deletes them outright, and a builder disconnecting or a + * rebuild starts a new run. Without this the pane keeps showing lines that no + * longer exist, and for a fresh run appends the new ones underneath the old. + */ + +static void +saiw_browser_logs_reset(struct pss *pss) +{ + uint8_t buf[LWS_PRE + 192], *start = buf + LWS_PRE; + char esc[132]; + int n; + + pss->sub_uid = 0; + pss->sub_timestamp = 0; + + n = lws_snprintf((char *)start, sizeof(buf) - LWS_PRE, + "{\"schema\":\"com.warmcat.sai.logs_reset\"," + "\"task_hash\":\"%s\",\"run\":%d}", + lws_json_purify(esc, pss->sub_task_uuid, + sizeof(esc) - 1, NULL), pss->sub_run); + + saiw_ws_browser_queue_REQUIRES_LWS_PRE(pss, start, (size_t)n, + LWS_WRITE_TEXT); +} + +/* + * The cursor can never legitimately be ahead of the newest row that exists, so + * if it is, the rows it was counting have been deleted (or we have moved to a + * run that has not produced any yet) and the browser has to start over. + */ + +static int +saiw_browser_logs_cursor_stale(struct vhd *vhd, struct pss *pss) +{ + char event_uuid[33], q[256], pesc[132]; + uint64_t max_uid = 0; + sqlite3 *pdb = NULL; + + if (!pss->sub_uid || !pss->sub_task_uuid[0]) + return 0; + + sai_task_uuid_to_event_uuid(event_uuid, pss->sub_task_uuid); + + if (sai_event_db_ensure_open(vhd->context, &vhd->sqlite3_cache, + vhd->sqlite3_path_lhs, event_uuid, 0, &pdb)) + /* the event is gone, which the log query itself will report */ + return 0; + + lws_sql_purify(pesc, pss->sub_task_uuid, sizeof(pesc)); + lws_snprintf(q, sizeof(q), + "select coalesce(max(uid), 0) from logs where " + "task_uuid='%s' and run=%d", pesc, pss->sub_run); + + if (sqlite3_exec(pdb, q, sai_sql3_get_uint64_cb, &max_uid, NULL) != + SQLITE_OK) + max_uid = pss->sub_uid; /* don't guess on a query failure */ + + sai_event_db_close(&vhd->sqlite3_cache, &pdb); + + return max_uid < pss->sub_uid; +} + static void saiw_retry_overview(lws_sorted_usec_list_t *sul) { @@ -1434,10 +1545,19 @@ saiw_broadcast_logs_batch(struct vhd *vhd, struct pss *pss) /* uuid is db-derived, purify keeps the literal safe anyway */ lws_sql_purify(pesc, pss->sub_task_uuid, sizeof(pesc)); + /* + * Page on uid, the logs table's autoincrement primary key, not + * on timestamp: the timestamps are the builder's + * CLOCK_MONOTONIC, so they restart from near zero whenever a + * builder VM reboots, and rows issued below the cursor are + * never delivered. uid only ever increases, and the rows come + * back in uid order anyway. + */ + lws_snprintf(esc, sizeof(esc), - "and task_uuid='%s' and run=%d and timestamp > %llu", + "and task_uuid='%s' and run=%d and uid > %llu", pesc, pss->sub_run, - (unsigned long long)pss->sub_timestamp); + (unsigned long long)pss->sub_uid); // lwsl_notice("%s: collecting logs %s\n", __func__, esc); @@ -1458,7 +1578,7 @@ saiw_broadcast_logs_batch(struct vhd *vhd, struct pss *pss) } sr = lws_struct_sq3_deserialize(pdb, esc, - "uid,timestamp ", + "uid ", lsm_schema_sq3_map_log, &pss->logs_owner, &pss->logs_ac, 0, 50); @@ -1514,6 +1634,7 @@ saiw_broadcast_logs_batch(struct vhd *vhd, struct pss *pss) fi = 0; pss->sub_timestamp = log->timestamp; + pss->sub_uid = (uint64_t)log->uid; } while (n != LSJS_RESULT_FINISH); }
Page fetched 0s ago, creation time: 7ms (vhost etag hits: 0%, cache hits: 0%)