Progress and logging

How cartridges emit progress updates and log messages, and how these flow through the execution chain.

LOG frames

LOG frames are how cartridges communicate status to the engine and UI during request handling. They are non-terminal: a handler can emit LOG frames at any point between the first STREAM_START and the final END. LOG frames travel alongside data frames on the same request channel and interleave freely with CHUNK frames.

Every LOG frame carries non-empty level and message text in metadata key 5. Non-progress LOG frames also carry a mandatory attribution_class (input, resource, environment, or internal) and may carry one non-empty source-declared arg_urn. Progress LOG frames instead carry a progress float and never carry diagnostic attribution.

LOG frames do not affect the data stream. Progress drives live progress state. Non-progress diagnostics are forwarded live with the stable execution step token and optional body ordinal; clients retain a bounded in-memory window. They are not persisted as structured run history. Receivers never infer a missing class or argument attribution, and malformed attribution is a protocol error.

Source: capdag-rs/src/bifaci/frame.rs (Frame::log, Frame::progress).

Log levels

Standard levels:

Custom levels are allowed. The engine passes them through without interpretation.

Progress frames

Progress frames are LOG frames with level = "progress" and an additional progress float (0.0–1.0) in the meta map. The engine uses this value to update task progress in the database and UI.

// Constructing a progress frame
Frame::progress(request_id, 0.5, "Processing page 3 of 6");
// Produces meta: {"level": "progress", "message": "Processing page 3 of 6", "progress": 0.5}

The log_progress() method on Frame returns Some(f32) only when the level is "progress". A LOG frame with a different level and a progress field in meta returns None, because the level check is strict.

Progress values do not ratchet. A handler can emit 0.8 followed by 0.3. There is no monotonicity enforcement in the protocol or the database, because some operations genuinely revisit earlier states (e.g., multi-pass encoding).

Source: frame.rs (Frame::progress, log_progress).

Emitting progress

From a handler, use the OutputStream methods:

// Progress update with value and message
req.output().progress(0.5, "Halfway through inference");

// Step-level diagnostic
req.output().log(
    "info",
    AttributionClass::Internal,
    "Found 12 images in document",
);

// Diagnostic attributed by its source to one cap argument
req.output().log_for_argument(
    "warn",
    AttributionClass::Resource,
    "Model cache is under memory pressure",
    MEDIA_MODEL_SPEC,
);

Both methods construct a LOG frame with the correct request_id and routing_id and send it through the output channel. They do not block.

Source: capdag-rs/src/bifaci/cartridge_runtime.rs (OutputStream::progress, OutputStream::log).

Handler progress conventions

ML cartridges follow a standard progress layout:

These are conventions, not protocol requirements. Content cartridges (PDF, text) use simpler layouts since their operations are faster.

Final progress rides in END

The request’s final progress is terminal metadata on the END frame (L3/L5), not a LOG frame. When a handler completes successfully, the runtime stamps progress (default 1.0) and an optional message into the END’s meta; a handler can override both via OutputStream::finish(progress, message) before returning. The receiving side delivers this value as the final progress event. Because it travels in the terminal frame, it cannot race it.

Consequences:

• Do not emit a trailing 100% progress LOG. END is the single authoritative terminal progress event, so completion cannot race a separate LOG frame.
• END/ERR is the LAST flow frame of a request (L4). The cartridge writer thread enforces this: a flow frame reaching it after the flow’s terminal has been written (a detached ProgressSender, a keepalive ticker that outlived the handler) is dropped and counted (post_terminal), never written. The same reason covers the RECEIVER side of the law: a frame that crossed its request’s terminal on the wire (a credit grant, a straggling LOG) is classified post_terminal by every routing runtime (see Flow control §”The teardown race”), keeping no_route a genuine routing-anomaly alarm. Drops are observable in the runtime’s protocol stats, so nothing is silent.
• A successful END without explicit terminal progress reads as 1.0. A failed END never synthesizes a completion value.

Keepalive frames

Keepalive frames solve a specific problem: blocking FFI calls (model loads) can starve the frame writer, causing the engine to think the cartridge is dead.

The problem

The cartridge’s frame writer task runs on a tokio worker thread. It drains the output channel and writes frames to stdout. When a handler calls a blocking FFI function (e.g., llama_model_load() which can take minutes for large models), the call runs on the same tokio worker thread pool.

If all tokio workers are occupied by blocking calls, the writer task cannot run. Frames queued in the output channel sit there, even frames emitted before the blocking call started. The engine sees no frames arriving on stdout and, after 120 seconds of silence, triggers its activity timeout and kills the task.

The sequence:

sequenceDiagram
    participant H as Handler
    participant CH as mpsc Channel
    participant WT as Writer Task
    participant E as Engine

    H->>CH: progress(0.25, "Loading model...")
    Note over H: llama_model_load() blocks a tokio worker
    Note over WT: Needs tokio worker — none available
    Note over CH: Frames stuck in channel
    Note over E: 30s... 60s... 90s...
    E->>E: 120s: Activity Timeout

run_with_keepalive (Rust)

OutputStream::run_with_keepalive() fixes this by running the blocking work on a separate thread pool:

pub async fn run_with_keepalive<T: Send + 'static>(
    &self,
    progress: f32,
    message: &str,
    f: impl FnOnce() -> T + Send + 'static,
) -> T

What it does:

1. Spawns the closure on tokio::task::spawn_blocking, a dedicated thread pool for blocking work, separate from the tokio async workers. The closure runs without blocking any tokio worker.
2. Runs a keepalive loop using tokio::select! with a tokio::time::interval(30s). Every 30 seconds, it emits a progress frame with the given value and message.
3. Returns the closure’s result when spawn_blocking completes. The keepalive loop stops.

Because spawn_blocking frees the tokio workers, the writer task can run and flush keepalive frames to stdout. The engine sees frames every 30 seconds and resets its 120-second timeout.

// Usage in a handler
let model = req.output().run_with_keepalive(
    0.25,
    "Loading model...",
    move || LlamaModel::load_from_file(&model_path, &params),
).await;

What must go through it: every blocking call, not only the model load. A forward pass (a Whisper window, an embedding batch, a caption, or a CLIP encode) is the same blocking work as loading the model, and run inline on a tokio worker it has the same effect: the runtime’s own loop does not get scheduled, the host’s heartbeat probe goes unanswered, and the host kills the cartridge as unresponsive (CARTRIDGE_UNHEALTHY). Move the work and its inputs into the closure (a model that is reused across calls moves in and comes back out with the result), and emit progress from inside it through a ProgressSender. For a stream of per-chunk calls against one loaded model, a single spawn_blocking worker fed over a channel follows the same rule.

Source: cartridge_runtime.rs (run_with_keepalive).

runWithKeepalive (Swift)

The Swift equivalent in capdag-objc/Sources/Bifaci/CartridgeRuntime.swift uses structured concurrency:

1. Spawns a background Task that emits progress frames every 30 seconds.
2. Awaits the async operation.
3. Cancels the keepalive Task when the operation completes.

The mechanism differs (Swift uses Task cancellation instead of tokio::select!) but the effect is identical: keepalive frames flow to the engine while blocking work runs.

ProgressSender

ProgressSender is a detachable handle for emitting progress and log frames from inside a spawn_blocking closure. It is Clone + Send + Sync + 'static, so it can cross thread boundaries freely.

#[derive(Clone)]
pub struct ProgressSender {
    sender: Arc<dyn FrameSender>,
    request_id: MessageId,
    routing_id: Option<MessageId>,
}

impl ProgressSender {
    pub fn progress(&self, progress: f32, message: &str);
    pub fn log(
        &self,
        level: &str,
        attribution_class: AttributionClass,
        message: &str,
    );
    pub fn log_for_argument(
        &self,
        level: &str,
        attribution_class: AttributionClass,
        message: &str,
        arg_urn: &str,
    );
}

Create one via output.progress_sender():

let ps = req.output().progress_sender();
let result = tokio::task::spawn_blocking(move || {
    // Runs on blocking thread pool
    ps.progress(0.4, "Processing token 50 of 200");
    do_inference(&model, &input, |token_idx, total| {
        ps.progress(0.35 + 0.6 * (token_idx as f32 / total as f32), "Generating...");
    })
}).await.unwrap();

flowchart TD
    Q{"Blocking work needs<br/>granular progress?"}
    Q -->|"No: just keep alive"| RWK["run_with_keepalive()<br/>Fixed value every 30s"]
    Q -->|"Yes: per-token, per-step"| PS["ProgressSender<br/>Emit from inside closure"]

    RWK --> SB1["spawn_blocking(closure)"]
    PS --> SB2["spawn_blocking(move || {<br/>  ps.progress(...)  <br/>})"]

The key difference from run_with_keepalive: ProgressSender gives the closure control over when and what progress to emit, rather than emitting a fixed keepalive value at a fixed interval. Use run_with_keepalive for simple blocking calls (model loads). Use ProgressSender when the blocking work itself can report granular progress (per-token inference, multi-file processing).

A pipeline whose engine borrows from the loaded model (a vision engine, for example) cannot be returned from spawn_blocking. The entire pipeline (load + inference) must then run in a single blocking closure, and per-token progress is emitted from inside it through a ProgressSender.

Source: cartridge_runtime.rs (ProgressSender, progress_sender).

Activity timeout

The engine enforces an activity timeout of 120 seconds (DEFAULT_ACTIVITY_TIMEOUT_SECS in capdag-rs/src/orchestrator/executor.rs). Any frame on the response channel, including LOG, progress, and heartbeat responses, resets the timer. If no frames arrive for 120 seconds, the engine terminates the task with ExecutionError::ActivityTimeout.

The 30-second keepalive interval provides a 4x safety margin: even if one keepalive frame is delayed, the next one arrives well before the timeout.

Individual caps can override the default timeout via the activity_timeout field in their definition. This is used for caps that are known to have long silent periods that cannot be interrupted with keepalive frames.

Progress mapping through the execution chain

Progress values pass through several layers between the cartridge and the UI:

graph TD
    PH["Cartridge handler<br/>output.progress(0.5, ...)"] --> LOG["LOG frame on stdout"]
    LOG --> PHR["CartridgeHostRuntime<br/>(pass-through)"]
    PHR --> RS["RelaySlave → RelayMaster<br/>(pass-through)"]
    RS --> EF["execute_fanin<br/>→ CapProgressFn callback"]
    EF --> CI["cap_interpreter<br/>→ map to step range"]
    CI --> DB["SQLite database"]
    DB --> UI["UI"]

1. Cartridge handler: Emits raw progress in [0.0, 1.0].
2. Peer call forwarding: If the handler is forwarding peer progress, it maps the peer’s [0.0, 1.0] to a sub-range (e.g., [0.0, 0.25]) using map_progress(value, base, weight).
3. execute_fanin: The orchestrator’s execution loop reads LOG frames from the response channel and calls the CapProgressFn callback with the cartridge’s progress value.
4. cap_interpreter: Maps the cap’s [0.0, 1.0] progress to the step’s allocated range within the overall task progress.
5. Database: The mapped value is written to SQLite. The UI reads it.

See Progress mapping for how ProgressMapper deterministically subdivides progress ranges across steps.

Logging restrictions

Cartridges do not have a tracing subscriber. The following do not work inside cartridge processes:

• tracing::info!(), tracing::debug!(), etc.: No subscriber is installed. Messages are silently dropped.
• eprintln!(), fputs(stderr): In a GUI app sandbox, stderr goes to /dev/null. On macOS, write() to a dead stderr can block forever. A native library log callback that calls fputs(text, stderr) (the CLIP model loader’s default log callback, for example) can therefore block indefinitely.

The only way to emit observable output from a cartridge is through LOG frames via output.log(), output.log_for_argument(), and output.progress(). These send frames through the stdout channel, which the host receives and processes.

For FFI libraries that have their own log callbacks (llama.cpp, CLIP/MTMD), the callback must be redirected to a no-op function. LlamaBackend::void_logs() suppresses llama logs; mtmd_log_set() suppresses CLIP/MTMD logs. Both must be called before loading models.