fix: say what failed in a loop, and let a slow model load finish

Two things behind one report: "ERROR: reddit2image Loop iteration failed",
which says nothing, caused by a model load that was still in progress.

The message first. A loop that gave up set the error to the literal string
"Loop iteration failed" and threw away the node result that knew why - and
that string is what the error workflow forwards to whoever is watching. It
now names the body node, the item, and what the node actually said:

  Loop body node "SD.cpp Load Model" failed on item 0: ...

Then the cause. The node does poll /health while a model loads, but any single
poll that timed out threw and ended the node - and a server part-way through
reading eleven gigabytes answers /health slowly or not at all. That is what
loading looks like from outside, not a failure. Polls now tolerate no answer
and treat it as still working; only the deadline ends the wait, and if the
server has genuinely gone quiet the error says how many polls went unanswered
rather than reporting a bare timeout.

How long to wait is now its own setting rather than the request timeout. A
request giving up says nothing about whether the server is still working - it
usually is. So a load request that stops waiting falls through to following
the load through /health, instead of reporting a failure that is really just
impatience. Measured with the request timeout set to 8 seconds against a load
that takes 18: it reported real progress, 0 through 376 of 1095 steps, and
completed.

Health reads also retry now, which costs nothing and matters exactly when the
server is busiest.

New fixture pins the message, and the harness gained expectExecutionError to
assert it - every existing assertion looked at nodes, and the nodes were all
correct here. The message was the broken part. Checked that the assertion can
fail before trusting that it passes. 63 passed.

nodes/sdcpp/sdcpp-model-load.js

@@ -34,7 +34,7 @@ const configSchema = {
         { title: 'Advanced', fields: ['vaeFormat', 'prediction', 'rngType', 'samplerRngType',
                                       'loraApplyMode', 'vaeConvDirect', 'diffusionConvDirect',
                                       'taePreviewOnly', 'forceSdxlVaeConvScale', 'backend', 'paramsBackend', 'rpcServers',
-                                      'modelArgs', 'tensorTypeRules', 'options', 'timeout'] }
+                                      'modelArgs', 'tensorTypeRules', 'options', 'timeout', 'loadWaitMs'] }
     ],
     // Pressing this asks the server what it has loaded and writes it into the
     // settings below - the model and every component it reports - so a workflow
@@ -269,8 +269,13 @@ const configSchema = {
         },
         timeout: {
             type: 'number', title: 'Timeout (ms)',
-            description: 'Loading reads gigabytes from disk and can take minutes',
+            description: 'How long to wait on any one request to the server. Loading reads gigabytes from disk, so the request that starts it is given this long',
             default: 300000
+        },
+        loadWaitMs: {
+            type: 'number', title: 'Wait For Loading (ms)',
+            description: 'How long to keep watching after the load has started. This is separate from the timeout above because a request giving up says nothing about whether the server is still working - it usually is, and the node follows it through /health rather than reporting a failure that is really just impatience',
+            default: 900000
         }
     },
     required: []
@@ -374,10 +379,29 @@ function readHealth(server, timeout) {
         method: 'GET',
         url: server + '/health',
         timeout: timeout,
+        // Reading health is safe to repeat, and the moment it matters most is
+        // the moment the server is busiest.
+        retries: 2,
+        retryDelayMs: 1000,
         what: 'reading server health'
     });
 }
 
+// The same, but a server that does not answer is treated as one that is busy
+// rather than one that has failed. A machine part-way through loading eleven
+// gigabytes answers /health slowly or not at all - that is what loading looks
+// like from outside, and throwing there ended the whole run for the one thing
+// the node was waiting for.
+function pollHealth(server, timeout) {
+    try {
+        return readHealth(server, timeout);
+    } catch (e) {
+        smartbotic.log.info('SD.cpp: no answer from /health while loading (' +
+            ((e && e.message) || e) + '), still waiting');
+        return null;
+    }
+}
+
 function putIfSet(target, key, value) {
     if (value === undefined || value === null || value === '') {
         return;
@@ -464,6 +488,8 @@ function optionsThatDiffer(wanted, current) {
 async function execute(config, input, context) {
     const server = normalizeServer(config.serverUrl);
     const timeout = config.timeout > 0 ? config.timeout : 300000;
+    // Watching costs nothing, so it is allowed to outlast any single request.
+    const loadWait = config.loadWaitMs > 0 ? config.loadWaitMs : 900000;
     const modelName = String(config.modelName || '').trim();
 
     if (!modelName) {
@@ -555,14 +581,32 @@ async function execute(config, input, context) {
 
     // Loading unloads whatever was in the slot first, and the server holds a
     // mutex for the duration, so this blocks until the weights are resident.
-    const loaded = call({
-        method: 'POST',
-        url: server + '/models/load',
-        headers: { 'Content-Type': 'application/json', 'Authorization': 'Bearer ' + token },
-        body: JSON.stringify(body),
-        timeout: timeout,
-        what: 'loading model ' + modelName
-    });
+    let loaded;
+    try {
+        loaded = call({
+            method: 'POST',
+            url: server + '/models/load',
+            headers: { 'Content-Type': 'application/json', 'Authorization': 'Bearer ' + token },
+            body: JSON.stringify(body),
+            timeout: timeout,
+            // Deliberately not retried: the server holds a mutex for the whole
+            // load, so a second request would queue behind the first and load
+            // the same weights twice.
+            what: 'loading model ' + modelName
+        });
+    } catch (loadError) {
+        // This call giving up does not mean the server did. If it is still
+        // loading, that is the answer to what happened - so the wait below
+        // finds out how it goes rather than reporting a failure that is really
+        // just impatience.
+        const probe = pollHealth(server, 15000);
+        if (!probe || probe.model_loading !== true) {
+            throw loadError;
+        }
+        smartbotic.log.info('SD.cpp: the load request stopped waiting, but the server is still ' +
+            'loading ' + (probe.loading_model_name || modelName) + ' - following it through /health');
+        loaded = {};
+    }
 
     // The load call comes back before the model is in memory. The API
     // documentation describes it as blocking, and it is not: /health reports
@@ -570,26 +614,45 @@ async function execute(config, input, context) {
     // would tell the workflow the model is ready and let the next node ask it
     // to generate, which fails with "no model loaded" - a confusing way to
     // learn that this node lied.
-    const deadline = startedAt + timeout;
-    let after = readHealth(server, 15000);
+    const deadline = Date.now() + loadWait;
+    let after = pollHealth(server, 15000);
     let lastStep = -1;
-
-    while (after.model_loading === true && Date.now() < deadline) {
-        const step = after.loading_step;
-        const total = after.loading_total_steps;
-        if (typeof step === 'number' && step !== lastStep) {
-            lastStep = step;
-            smartbotic.log.info('SD.cpp: loading ' + (after.loading_model_name || modelName) +
-                ' - ' + step + (total ? '/' + total : ''));
+    let silentPolls = 0;
+
+    while ((after === null || after.model_loading === true) && Date.now() < deadline) {
+        if (after === null) {
+            silentPolls++;
+        } else {
+            silentPolls = 0;
+            const step = after.loading_step;
+            const total = after.loading_total_steps;
+            if (typeof step === 'number' && step !== lastStep) {
+                lastStep = step;
+                smartbotic.log.info('SD.cpp: loading ' + (after.loading_model_name || modelName) +
+                    ' - ' + step + (total ? '/' + total : ''));
+            }
         }
         smartbotic.utils.sleep(2000);
-        after = readHealth(server, 15000);
+        after = pollHealth(server, 15000);
+    }
+
+    const waitedSeconds = Math.round((Date.now() - startedAt) / 1000);
+
+    if (after === null) {
+        throw new Error('SD.cpp: ' + modelName + ' was asked for ' + waitedSeconds +
+            's ago and the server has stopped answering /health (' + silentPolls +
+            ' polls in a row went unanswered). It may still be loading - check the ' +
+            'server, and raise the timeout on this node if this model is simply slow');
     }
 
     if (after.model_loading === true) {
-        throw new Error('SD.cpp: ' + modelName + ' was still loading after ' +
-            Math.round((Date.now() - startedAt) / 1000) + 's. It may still finish on the server; ' +
-            'raise the timeout on this node if this model is simply slow to load');
+        throw new Error('SD.cpp: ' + modelName + ' was still loading after ' + waitedSeconds +
+            's' + (typeof after.loading_step === 'number'
+                ? ' (at step ' + after.loading_step +
+                  (after.loading_total_steps ? ' of ' + after.loading_total_steps : '') + ')'
+                : '') +
+            '. It may still finish on the server; raise the timeout on this node if this ' +
+            'model is simply slow to load');
     }
 
     if (after.model_loaded !== true) {

scripts/verify-node.py

@@ -243,6 +243,16 @@ def main():
             if "output" in want:
                 failures += subset_matches(want["output"], got.get("output"), node_id)
 
+        # What a watcher is told when the run fails. "Loop iteration failed" on
+        # its own passed every assertion that looked at nodes, because the nodes
+        # were all correct - the message was the broken part.
+        wanted_error = case.get("expectExecutionError")
+        if wanted_error and wanted_error not in (execution.get("error") or ""):
+            failures.append(
+                f"execution error does not contain {wanted_error!r}, "
+                f"got {execution.get('error')!r}"
+            )
+
         for node_id in case.get("expectMissing", []):
             got = by_id.get(node_id)
             if got is not None and got.get("status") != "skipped":

src/runner/workflow_engine.cpp

@@ -812,7 +812,36 @@ Result<ExecutionResult> WorkflowEngine::execute(const Workflow& workflow,
 
                 if (!loop_success && !loop_ctx.continue_on_error) {
                     result.status = ExecutionStatus::Failed;
-                    result.error = "Loop iteration failed";
+
+                    // "Loop iteration failed" on its own says nothing, and it is
+                    // what an error workflow forwards to whoever is watching -
+                    // so the node that actually failed and what it said are
+                    // carried out with it. The results are keyed
+                    // "<node>_iter_<n>", and the first failure is the one that
+                    // matters; the rest are usually the same thing repeated.
+                    std::string detail;
+                    for (const auto& [key, body_result] : result.node_results) {
+                        if (body_result.status != NodeStatus::Failed) {
+                            continue;
+                        }
+                        const auto suffix = key.find("_iter_");
+                        if (suffix == std::string::npos) {
+                            continue;
+                        }
+                        const std::string body_node_id = key.substr(0, suffix);
+                        std::string body_name = body_node_id;
+                        for (const auto& n : workflow.nodes) {
+                            if (n.id == body_node_id && !n.name.empty()) {
+                                body_name = n.name;
+                                break;
+                            }
+                        }
+                        detail = "Loop body node \"" + body_name + "\" failed on item " +
+                                 key.substr(suffix + 6) + ": " + body_result.error;
+                        break;
+                    }
+
+                    result.error = detail.empty() ? "Loop iteration failed" : detail;
                     break;
                 }
 

tests/nodes/loop-failure-message.json

@@ -0,0 +1,23 @@
+{
+  "name": "verify-loop-failure-says-what-failed",
+  "nodes": [
+    {"id": "n1", "name": "Trigger", "type": "click-trigger", "position": {"x": 0, "y": 0}, "config": {}},
+    {"id": "items", "name": "Items", "type": "code", "position": {"x": 0, "y": 100},
+     "config": {"code": "return { items: ['alpha'] };"}},
+    {"id": "loop", "name": "Loop", "type": "loop", "position": {"x": 0, "y": 200},
+     "config": {"inputField": "data.result.items", "continueOnError": false}},
+    {"id": "boom", "name": "The Node That Broke", "type": "code", "position": {"x": 0, "y": 300},
+     "config": {"code": "throw new Error('the model refused to load');"}},
+    {"id": "report", "name": "Report", "type": "code", "position": {"x": 200, "y": 300},
+     "config": {"code": "return { marker: 'should not run' };"}}
+  ],
+  "connections": [
+    {"sourceNodeId": "n1", "sourceOutput": "main", "targetNodeId": "items", "targetInput": "data"},
+    {"sourceNodeId": "items", "sourceOutput": "main", "targetNodeId": "loop", "targetInput": "data"},
+    {"sourceNodeId": "loop", "sourceOutput": "loop", "targetNodeId": "boom", "targetInput": "data"},
+    {"sourceNodeId": "loop", "sourceOutput": "done", "targetNodeId": "report", "targetInput": "data"}
+  ],
+  "expectStatus": "failed",
+  "expectExecutionError": "Loop body node \"The Node That Broke\" failed on item 0: Error: the model refused to load",
+  "expectMissing": ["report"]
+}