Add ability to tee IPM output to both terminal and a log file

[isc-dchui]

Description

Closes #1213.

Overview

Debugging a failing install or a long test run usually means wanting a file copy of what IPM printed, so it can be searched, diffed, or attached to an issue. Terminal scrollback is lossy, and the ANSI color codes IPM emits make copied text awkward to grep.

This PR tees IPM session output: the terminal shows exactly what it showed before, and a parallel ANSI-stripped copy goes to a file. Two entry points, one for ad-hoc use and one for always-on:

• -log-file <path>, a modifier injected into every command.
• AutoLog, a setting that starts a tee for every IPM shell.

Two supporting settings are added to %IPM.Repo.UniversalSettings: LogDirectory (default <IRIS data dir>/ipm/logs/) and AutoLog.

The CPF change belongs to the same theme. $zf(-100) runs the merge in a child process whose output bypasses IRIS device redirection, so it could never be teed and was previously discarded entirely (STDOUT="zf100stdout"). It now binds STDOUT and STDERR to a timestamped file under LogDirectory, echoes that file to the terminal under -verbose, and names the path in the error when the merge fails. STDIN is bound to the null device at the same time, since unbound it tries to open the parent's terminal as its principal device and logs a failure to do so.

Using it

Pass -log-file to any command. Absolute paths are used as given; a bare filename resolves under LogDirectory:

zpm "install mypackage -log-file /tmp/install.log"
zpm "test mypackage -log-file test-run.log"

For always-on logging:

zpm "config set AutoLog 1"
zpm "config set LogDirectory /var/log/ipm/"

Every shell then logs to LogDirectory under a name like ipm-2026-09-04-143201-12345.log (date, time, $job).

Both settings are read once when the shell starts, so changing either mid-session does not relocate the running log. UpdateOne() says so, and points at -log-file for logging a single command in the current session.

Behavior

What it covers

The -log-file modifier is injected into every command's structure at compile time, so every command accepts it. It covers that one command end to end, including any nested shell the command runs internally. AutoLog covers a whole process instead, and applies equally to an interactive zpm shell and to a one-shot zpm "install foo", since both go through ShellInternal.

Which one wins when both are on

Exactly one tee runs at a time. A -log-file command sets the AutoLog tee aside, writes to its own file, and puts AutoLog back afterwards, so the one-off file holds that command and the AutoLog transcript continues without it. If the two paths name the same file, nothing is switched and both write to it.

Appending or starting fresh

-log-file always appends, so re-running a command with the same path grows one file rather than overwriting the previous run. AutoLog always starts a new file: it derives ipm-<date>-<time>-<job>.log, and if that name is somehow taken it adds a -N suffix rather than appending to a file another run may own. Every write after the first in that process appends, so one process is one transcript.

What lands in the file

Everything IPM writes to the device, as UTF-8, with ANSI escapes and carriage returns stripped and write ?n rendered as spaces from a tracked column. Output is line-buffered and flushed at write !, so the file gets whole lines. Each command is preceded by a header that appears only in the file:

--- [2026-09-04 14:32:01] [USER] test mypackage ---

Three things do not land in it: text typed at a prompt, since reads go straight to the real device; output produced while redirection is suspended for a namespace excursion, discussed below; and child-process output, since $zf(-100) bypasses IRIS redirection entirely. The CPF merge is the only case of the last kind and gets its own cpf-merge-*.log under the same directory.

Relation to the history log

None, deliberately. %IPM.General.History records structured, per-namespace rows for installs, uninstalls, and loads, and answers "what is in this namespace and how did it get there". A log file is an unstructured transcript of one session's terminal output. Neither reads the other, and the log file is not pruned by HistoryRetain.

Relation to existing output redirection

The tee layers onto whatever redirection is already installed rather than replacing it, in both directions: starting a tee inside %IPM.Utils.Module.BeginCaptureOutput() leaves the capture intact, and a capture started while a tee is running is not stolen from. This is what makes the tee usable during zpm test, where the test harness captures output for its own report.

Implementation choices

State in a process-private global, not an object

Tee state (path, pending buffer, column, prior redirect) lives in the process-private global ^||%IPM.log rather than in an object. The redirect entry points are routine labels that IRIS calls from arbitrary write sites, with no $this and no object context, so instance properties are unreachable from them.

Reuse of the existing redirection idiom

The label set and $zutil protocol are the same ones %IPM.Utils.Module.BeginCaptureOutput() already uses, extended with buffering, ANSI stripping, and chaining.

Chaining a prior redirect instead of replacing it

If redirection is already active, Start() records the current handler ($zutil(96,12)) and forwards through it, and Stop() restores it rather than switching redirection off, so starting a tee inside BeginCaptureOutput() does not break the capture. One guard is required: if the recorded prior handler is this routine, forwarding would re-enter wstr() until <FRAMESTACK>, so that value is discarded.

Flush on newline, not per write

One logical IPM line arrives as many write calls (color escape, label, status text). The buffer accumulates and flushes at write !, so the file gets whole lines and each line costs one append.

Explicit ownership of the single tee

The single-tee rule needs explicit ownership, because commands run nested shells (test internally runs config set) and an inner ShellInternal seeing an active tee must not stop it. tOwnsLog marks the shell-lifetime AutoLog tee as belonging to the frame that started it, and inner frames skip StartAutoLog(). A -log-file tee is per-command instead, tracked by tCommandLogPath, with the tee it displaced in tDisplacedLogPath; RestoreLogAfterCommand() closes the former and reopens the latter on every path out of a command, including the error and early-return paths.

Redirect entry points must not be able to fault

An error inside a handler is reported by writing, and that write re-enters the handler, so any fault becomes an unbounded recursion ending in <FRAMESTACK> rather than a diagnosable error. Every state read therefore goes through $get, and detach() covers the case where redirection still points here but the state is gone. That case is reachable in practice: %UnitTest.Manager snapshots the device redirect flag when a suite starts and restores it afterwards, so running zpm verify from a shell with AutoLog on had the Manager switch redirection back on after the run had legitimately stopped the tee.

Never assume this tee is the installed handler

The prior handler recorded at Start() is only the top of the chain until someone else installs one, as BeginCaptureOutput() does. So Stop() releases the file and clears its state but leaves the chain alone when the installed handler is no longer ours. FlushBuffer() follows the same rule: it has to switch interception off to write the log, and it restores whichever handler was installed rather than reinstalling itself.

Stripping ANSI in the file only

ANSI stripping happens in buf(), after out() has already sent the original bytes onward, so the terminal keeps its color and only the file is plain text.

Namespace excursions

Installing a redirect names a handler routine, and the kernel re-resolves that name in the current namespace on every intercepted write. %IPM.General.OutputLog.1 resolves only where the %IPM.* routine mapping exists, so any write issued while parked in a namespace without it (%SYS, or a namespace IPM is not installed in) raises <NOROUTINE>. IPM makes such excursions routinely, and fifteen brackets across thirteen methods cover the ones that write from inside: web and CSP application configuration, database preparation, namespace deletion, backup, history cleanup, batch activation, default registry lookup, the two install loops in enable, the two in the namespace command, repo, the language extension fallback, and the Studio menu extension lookup. Not having the mapping in %SYS is the normal state of an instance, not a broken one, so the tee has to cope rather than require the mapping.

The bracket macros

Two macros in %IPM.Common bracket the excursion:

$$$SuspendRedirection(redirect)   // set:'$data(redirect) redirect = $zutil(82,12,0)
$$$RestoreRedirection(redirect)   // do:$data(redirect) $zutil(82,12,redirect) kill redirect

Macros and not utility methods, because the restore has to run while still inside the target namespace, where a ##class(%IPM...) call is exactly the thing that cannot be resolved. The macros expand inline at compile time in a mapped namespace, so the generated code carries no %IPM name to resolve. RestoreRedirection is a no-op on an undefined flag, so an exception thrown before the excursion was entered cannot switch interception off and kill a tee that was never suspended. It also clears the flag, and SuspendRedirection records state only when the flag is undefined. Together those make the pair safe both inside a loop that switches namespace per iteration, where a second $zutil(82,12,0) would otherwise overwrite the saved 1 with 0, and in a method that brackets several excursions in turn.

Restoring on the error path means the bracketed methods that did not already have one gained a try/catch that restores and rethrows.

Narrowing the bracket where the destination is known safe

Where a suspension is in force, the write that follows is either genuinely unsafe or the switch is known to land somewhere IPM is mapped. In the latter case the bracket closes immediately after the switch, so the output still reaches the log. %IPM.Main.Namespace() is the example: IsIPMEnabled() has already vouched for the destination, so only the switch itself sits inside the bracket. Where the excursion exists only to read something, the read result is hoisted into a variable and the namespace switched back before the write; two skip messages in enable are handled that way.

Why not relocate the writes instead

Relocating IPM's own write statements out of the excursions was the alternative and is not sufficient in general. The fault is namespace-based, not caller-based: PrepareDatabase() hands $io to CompactDatabase(), which writes its own progress from inside the excursion and faults identically. Suspending covers callee output too.

The accepted cost is that output produced while suspended reaches the terminal but not the log file. These are configuration excursions, not the output users are logging, and the alternative is a hard error.

Backstops

Two backstops, since a missed restore leaves interception off for the rest of the session rather than for one statement:

• OutputLog.Resume(), called from RestoreLogAfterCommand() at every command boundary, reinstalls the tee when it is active but interception has been switched off. Caps the damage at one command's output.
• Test.PM.Unit.NamespaceExcursions scans %Dictionary.MethodDefinition source for every %IPM.* method and fails on a write that follows a set $namespace without a preceding $$$SuspendRedirection, and on a suspend with no matching restore. It reads saved method source, so the macros are still visible as written rather than expanded. There is no allowlist: every site conforms, so there are no exemption entries to go stale. Comments are stripped before scanning, in //, ; and #; form and quote-aware, so a commented out macro does not read as a real one.

Known gap: the scan guards writes, not switches

The scan enforces "no write inside an unbracketed excursion". The invariant that actually matters is "no output inside an unbracketed excursion", and those differ whenever the output comes from a callee. A method that switches namespace, writes nothing itself, and calls something that writes passes the scan and faults at runtime.

PrepareDatabase() is the shape of the problem, and it only conforms because it happens to write directly as well; a version that just handed $io to CompactDatabase() would have gone unflagged. CreateDatabase() right below it is an unbracketed %SYS excursion of exactly that form.

No source scan can close this. The writing callee may be closed system code (SYS.Database), reached through dynamic dispatch, or several frames down. Two things bound the risk rather than remove it:

• The failure is loud. An unguarded excursion raises <NOROUTINE> at the write, so any path that gets exercised with a tee active reports itself immediately. That is how Test.PM.Integration.InstallApplication surfaced.
• Every excursion that writes at all today is bracketed, and the bracket covers callee output as well, so the known sites are covered.

The complete fix is to enforce the invariant on the switch instead of on the write: bind the suspend and the set $namespace into one macro and have the scan require that every switch uses it. That is callee-independent by construction, but it is a much larger change (118 set $namespace sites against the 15 brackets here), it needs an opt-out for the narrow brackets described above, and it costs log fidelity everywhere it widens a bracket. Left as a follow-up issue.

Running the suites with AutoLog on is the only check that covers callee output, and it stays a manual step rather than a CI leg: it means a second full zpm verify -only run at 15-25 minutes, and it still only covers the paths the suites happen to exercise.

Other scan limits

The scan reads what is compiled in the namespace, not the working tree, so zpm test (which loads the module first) sees current source, but a local edit-then-test cycle can pass against stale code.

The one site that cannot use the macros

%IPM.Main.LanguageExtensions() has its body emitted verbatim into %ZLANGC00.mac, which is compiled without IPM's include file, so it spells out $zutil(82,12,0) and do:$data(redirect) $zutil(82,12,redirect) instead. The scan accepts that raw form as a suspend for exactly this reason. The suspend/restore pairing check stays scoped to the macros, since the raw form is also how redirection gets switched off for good, as Stop() does.

A latent bug this turned up

In %IPM.Main.LanguageExtensions(), new $namespace restores at method exit rather than at the end of the while loop, so the "IPM is not installed" message and the newlines before Terminate/halt all ran in whichever namespace the loop last visited. It is only unreachable today because that fallback runs where IPM is absent, so no tee is active; the suspension now covers the whole tail of the method regardless.

%IPM.Utils.Module.BeginCaptureOutput() has the same latent flaw and is left for a follow-up issue; it predates this PR and is not reached by the tee paths.

Technical details: the redirect entry points

IRIS device redirection lets a process intercept every write to a device. use $io::("^"_$zname) names the handling routine and $zutil(82,12,1) switches interception on; $zutil(82,12,0) switches it off and returns the prior state. While it is on, the kernel calls a fixed set of labels in that routine instead of touching the device. This is why Start() is [ ProcedureBlock = 0 ]: the labels have to be routine-level entry points in the generated code for ^routine to reach them.

The labels IRIS calls, one per kind of write:

Label	Called for	Behavior
wstr(s)	write <string>	out(s) to the device, buf(s) to the log buffer
wnl()	write !	outctl("!"), then flush the buffer with a trailing LF
wff()	write #	outctl("#"), then flush with a form feed
wchr(s)	write *<code>	Always echoes; buffers only if the code is printable, so a partial escape sequence written a character at a time cannot land in the file
wtab(s)	write ?n	Pads from the tracked column, since $x is not maintained under redirection
rstr(sz,to)	read	Reads from the real device and returns the value
rchr(to)	read *1	Same, single character

The rest are internal helpers, not part of the IRIS contract:

• out(s) gets a string to the terminal. With a prior handler recorded it installs that handler and writes, letting the chain run; otherwise it disables interception, writes to the raw device, and restores the previous interception state.
• outctl(c) is out() for ! and #. It exists because a prior handler has to receive these as write ! / write # to reach its own wnl()/wff(), which it would not if they were passed as a string to wstr().
• detach(s) uninstalls redirection and writes s to the raw device. Used when the state is gone, where there is nothing left to forward through.
• reattach(rd) reinstalls this routine and restores the interception flag, or leaves redirection off when there is no handler name to reinstall, rather than installing "^".
• buf(s) strips ANSI and CR, appends to ^||%IPM.log("buf"), and advances the column counter. Because the buffer is stripped on the way in, flushes and column math never rescan it. It no-ops when no tee is active so it cannot resurrect a half-populated one.
• flush(tail) appends the physical LF or form feed and calls FlushBuffer(), which turns interception off around its own write so writing the log does not recurse into the tee, then restores the handler that was installed. If that write fails, it clears the stored path rather than throwing, since throwing here would surface as a failure of whatever unrelated code happened to be writing; the tee degrades to terminal-only.

StripAnsi() walks the string with $find on $char(27). For a CSI sequence (ESC [) it consumes parameter and intermediate bytes (0x20-0x3F) through the final byte (0x40-0x7E); other escapes are consumed as two bytes. A sequence truncated at the end of the string is dropped rather than leaving a bare ESC.

Testing

Test.PM.Unit.StripAnsi covers StripAnsi() directly: plain text, text containing [0m with no ESC, single- and multi-parameter CSI sequences, non-CSI two-byte escapes (ESC M, ESC 7), truncated sequences, and non-ASCII characters.

Test.PM.Integration.OutputLog drives real commands through %IPM.Main.Shell() and inspects the resulting file:

• TestExplicitLogFile, TestBareNameResolution, TestAppendMode, TestHeaderFormat for the -log-file surface.
• TestTeeEquivalence wraps a logged command in BeginCaptureOutput() and compares the captured device output against the file past the header, which also exercises the chaining path.
• TestANSIStripping, TestIndentationAndEncoding for file content fidelity.
• TestAutoLog, TestAutoLogSharedFile (three commands in one process produce one file with three headers), TestAutoLogValidation.
• TestLogFileRestoresAutoLog checks the per-command contract: the AutoLog tee is the active one again after a -log-file command, the one-off file holds that command, and the AutoLog transcript holds the following command and only it.
• TestZeroCostPath asserts no tee is installed when the modifier is absent and AutoLog is off.

OnAfterOneTest restores LogDirectory and AutoLog, stops any leaked tee, and drops any leaked BeginCaptureOutput() state, since a test that fails mid-redirect would otherwise corrupt the output of every test after it. It also puts back a tee the suite inherited, because %UnitTest.Manager fails the case if the device redirect flag does not match the value it snapshotted. ClearAutoLog() exists for the same reason: the AutoLog path is deliberately per-process, so tests have to reset it between cases.

Test.PM.Unit.NamespaceExcursions enforces the excursion rule described above. Test.PM.Integration.InstallApplication is the case that surfaced the problem; it passes with %SYS unmapped and AutoLog on.

The suites need to be run in all three configurations: AutoLog off, AutoLog on, and AutoLog on with a tee already active before the run. AutoLog on is the one that matters most, for two reasons. The whole run then happens with a tee installed underneath every capture the tests do, and it is the only check that covers output written from inside an excursion by a callee, which the source scan cannot see. CI runs with AutoLog off, so this is a manual pre-merge step.

Not covered by automated tests: the tOwnsLog nested-shell guard is exercised indirectly whenever a logged command runs a nested shell, but there is no test that asserts it directly.

Checklist

• This branch has the latest changes from the main branch rebased or merged.
• Changelog entry added.
• Unit (zpm test -only) and integration tests (zpm verify -only) pass.
• Style matches the style guide in the contributing guide.
• Documentation has been/will be updated
  • Source controlled docs, e.g. README.md, should be included in this PR and Wiki changes should be made after this PR is merged (add an extra issue for this if needed)
• Pull request correctly renders in the "Preview" tab.