`caUtils` floods piped logs with per-item progress output

[TheBearBoB]

Summary

Long-running caUtils update-from-1-7 progress displays emit every refresh as a separate output line when output is piped through tee. During identifier sorting, this produced tens of thousands of nearly identical lines instead of a single updating status line or rate-limited non-interactive output.

Environment

• Source installation: Providence 1.7.11
• Target: official Providence 2.0.11 release ZIP
• PHP CLI: 8.4
• OS: Rocky Linux 8
• Test context: isolated staging clone; production was unchanged

Steps to reproduce

php support/bin/caUtils update-from-1-7 2>&1 | tee /path/to/update-from-1-7.log

A representative phase produces output equivalent to:

[Sort: objects identifiers] ... 33295/67048 ...
[Sort: objects identifiers] ... 33296/67048 ...
[Sort: objects identifiers] ... 33297/67048 ...

Expected behavior

When standard output is not a TTY, the progress renderer should disable in-place animation and emit periodic milestones or other rate-limited status records suitable for logging.

Actual behavior

Every progress refresh is emitted as another line. The migration continues, but terminal scrollback is overwhelmed and the log is greatly inflated. Normalizing carriage returns to line breaks produced more than 1.2 million output records for this migration.

Impact

• Earlier migration messages disappear from practical terminal scrollback.
• Log files become unnecessarily large and difficult to inspect.
• Genuine warnings and errors can be buried in repetitive progress output.
• Healthy processing can appear to be malfunctioning.

Relevant source path

During sort-value rebuilding, Maintenance.php prints a progress frame for every label and every identifier:

CLIProgressBar::setMessage(_t("[Sort: %1 identifiers][Mem: %2]", $table_name_display, caGetMemoryUsage()));
print CLIProgressBar::next();

Source: Maintenance.php lines 75-102

CLIProgressBar::next() unconditionally renders and returns the next frame:

self::$done += $inc;
// ...
return self::display();

Source: CLIProgressBar.php lines 164-182

The default format always begins with a carriage return. The class does not distinguish an interactive terminal from redirected or piped output:

'format' => _t("\r:message::padding:%.01f%% %2\$d/%3\$d ETC: %4\$s. Elapsed: %5\$s [%6\$s]")

Source: CLIProgressBar.php lines 212-240

Source analysis

The source matches the observed output: high-volume callers render one complete progress frame per record, while CLIProgressBar always uses the interactive carriage-return format. In a pipe, every frame is preserved in the stream rather than replacing the preceding terminal line. I have not tested a patch to the renderer.

Possible implementation direction

The narrowest general fix appears to be inside CLIProgressBar, so individual commands would not need separate workarounds:

• Detect whether standard output is an interactive terminal when the progress bar starts.
• Preserve the current per-frame carriage-return display for an interactive terminal.
• For redirected or piped output, return newline-terminated progress only at bounded milestones, such as percentage changes or a time interval, plus the final state.

The exact TTY-detection fallback may need to account for the PHP versions and operating systems Providence supports. A regression test could capture non-interactive output for thousands of next() calls and assert that output remains bounded while still including initial, periodic, and final status.

AI assistance disclosure

This report was developed with ChatGPT Work using GPT-5.6 Sol with Extra High reasoning for source review, troubleshooting support, and drafting. Runtime claims, where included, were reproduced on an isolated staging clone; source-level claims were checked against the official Providence 2.0.11 release code.

[mellison-seagov]

It's difficult to test and support TTY detection in cross-platform software like this. When it fails for a user, it's hard to debug in their environment, and it takes some relatively rare expertise to troubleshoot. So, I'd advocate against taking that approach.

Some simpler alternate solutions might be:

• Using stderr for progress bars and stdout for everything else. This use case is, after all, very similar to the reason why stderr was invented half a century ago.
• Add an environment variable or argument that communicates the output is being piped, so progress bars and prompts should be excluded. This would be a nice "two-for-one" solution since it would also act as a contract between caUtils and whatever script calls it. See git's GIT_TERMINAL_PROMPT env var for a nice example of this approach.

Even so, the workaround to the core problem is to use the same basic log searching tools you'd use for inspecting any large log. When I ran into this issue at a similar scale, I found that grep handled my needs just fine (tip: grep "Step" to quickly see where it failed if you run into a failure).