opentofu task logs are buffered until completion — logs_full_size stays 0 for the whole run, and the task list omits log fields entirely

[jgruberf5]

Summary

An opentofu module produces no readable log until the task completes. logs_full_size stays at 0 for the entire run and jumps to its final value at completion. Separately, the task list endpoint omits log fields entirely, so anything enumerating a module's tasks sees every one as empty even after they finish.

Together these make a running opentofu module completely opaque: you cannot tell a module that is working from one that is wedged until it is over.

Measurement

opentofu module (Harbor VSI), plan task, detail endpoint sampled every 1s:

ELAPSED  STATUS        logs_full_size
1s       in_progress   0
2s       in_progress   0
4s       in_progress   0
5s       in_progress   0
6s       in_progress   0
8s       in_progress   0
9s       in_progress   0
11s      in_progress   0
12s      in_progress   0
13s      in_progress   0
15s      in_progress   0
16s      in_progress   0
18s      completed     4625

Twelve consecutive in-flight samples at exactly 0, then the whole 4625 bytes at once. Reproduced twice (tasks 127 and 128).

The log itself is per-line timestamped once it appears:

[04:42:26] === INIT REQUIRED: Module workspace not initialized ===
...
data.ibm_tg_gateways.all[0]: Read complete after 1s
ibm_is_instance.harbor: Refreshing state... [id=0757_ce100c4a-...]
No changes. Your infrastructure matches the configuration.

So the timestamps are captured progressively during the run — the data exists, it just is not persisted until the end.

Second, separate defect: the list endpoint drops log fields

For the same task, in the same moment:

GET /api/tasks?module_id=19&limit=10   ->  logs_full_size = null
GET /api/tasks/45                      ->  logs_full_size = 33601, logs_truncated = false

null on the list, real data on the detail. A client that enumerates a module's tasks — the obvious way to find "the log for this module" — sees every task as having no output, whether it is running or long finished.

Impact

A 40-minute cluster-create or a 7-minute Harbor VSI build is a black box for its entire duration. There is no progress signal, and no way to distinguish "still working" from "hung", which matters most precisely when something has gone wrong. Our harness worked around this by polling logs_full_size as a liveness signal for container modules, where it does climb — that workaround silently does nothing for the one opentofu module in our catalog.

Environment

BNK Forge v4.0.0-rc1. Module engine opentofu. Container modules in the same catalog do NOT show this: their logs_full_size climbs during an apply, which is why this went unnoticed.

Not a duplicate of #119 / #154

Both of those are closed and both concern container step output — the module log endpoint returning an empty 200, and no task id being exposed. This is a different engine and a different failure: the task id is exposed, the detail endpoint works, and the log is simply not written until the task ends.

Suggested

1. Flush opentofu task output incrementally, as the container engine already does.
2. Include logs_full_size (and logs_truncated) in the task list response, or document that logs are detail-only — the current null is indistinguishable from "this task produced no output".

[jgruberf5]

Better reproduction: both engines, one project, one moment

A destroy of a project containing one opentofu module and one container module, sampled while the opentofu one was still running:

module 19  harbor      opentofu    status=destroying   task=133 in_progress   logs_full_size = 0
module 20  far-mirror  container   status=destroyed    task=132 completed     logs_full_size = 176

Same project, same destroy, same instant. The container module's log is present; the opentofu module reports zero bytes while actively destroying, and its full log appears at completion.

This is cleaner than the plan/apply samples in the original report because it removes every variable except the engine — same Forge, same project, same operation, same second.

It also shows the behaviour is not specific to apply. Confirmed on all three so far:

plan     0 for 16s  -> 4625 at completion   (12 in-flight samples)
apply    0 for 25s  -> 7507 at completion   ( 8 in-flight samples)
destroy  0 while in_progress                (observed live)

The operator-visible symptom is what prompted this: a user watching the Forge UI saw the FLP (container) destroy stream its log, while the Harbor (opentofu) destroy showed nothing at all, and reasonably concluded the Harbor module was broken. It is not — it is the only opentofu module in that catalog, so it is the only one that ever looks that way.

[jgruberf5]

Root cause, in the source

Read against b5a37aa8. The opentofu runners cannot stream by construction:

backend/services/execution/opentofu_runtime.py:1519  run_init   -> subprocess.run(..., capture_output=True)
backend/services/execution/opentofu_runtime.py:1568  run_plan   -> subprocess.run(..., capture_output=True)
backend/services/execution/opentofu_runtime.py:1670  run_apply  -> subprocess.run(..., capture_output=True)

subprocess.run(capture_output=True) blocks until the process exits and returns the complete output as a string. There is no incremental read, so nothing can be persisted while tofu apply is running — the data does not exist in the parent process until the child has finished.

backend/tasks/opentofu_tasks.py then accumulates into an in-memory all_logs and assigns task.logs only between phases:

all_logs += f"[{_ts()}] --- PLAN ---\n"
exit_code, plan_logs = engine.run_plan(work_dir, env)   # blocks for the whole plan
all_logs += plan_logs
task.logs = all_logs                                    # first write
...
apply_code, apply_logs, outputs = engine.run_apply(...)  # blocks for the WHOLE apply

So the visible behaviour is: output appears at phase boundaries, and a module is dark for the entire duration of its longest phase.

Why the container engine does not have this

backend/services/execution/container_runner.py uses capture_output=True only for the short docker create/inspect calls, and runs the step's actual output through a dedicated follower:

streamer = threading.Thread(target=self._stream_logs, args=(container_name, run_env, _emit, ...))

_emit feeds sink in backend/tasks/container_tasks.py:376, which appends, publishes to the websocket, and throttle-flushes task.logs on an interval.

This corrects my earlier framing, and explains the "some opentofu modules do show output" report

I originally described this as opentofu logs appearing only at completion. More precisely: they appear at phase boundaries. A module whose init is cached and whose plan and apply are each quick will look like it streams, because the between-phase writes land within seconds of each other. A module with one long phase looks dark for exactly that long.

The Harbor VSI module is the latter: INIT SKIPPED (using cached providers), a fast plan, then a single ~7 minute apply that builds a VSI and waits on terraform_data.harbor_ready. Measured logs_full_size on that apply: 0 at 1s, 21s, 42s, 62s, 82s, 103s … then 33295 at completion.

So both observations are consistent, and neither is module-specific — it is the phase length that decides whether the buffering is visible.

Suggested fix

Give the three runners the same treatment the container runner already has: subprocess.Popen with an incremental read of stdout/stderr, an on_output callback per line, and a throttled task.logs flush in opentofu_tasks.py modelled on container_tasks.py:376. The engine layer in opentofu_engine.py already accepts and forwards on_output — it currently just has nothing to forward until the subprocess has ended.