hooks enabled ui: hooks client messages issues

[evakhoni]

• beforeHook too verbose, even without --exporter-logs the whole lot of debug messages being printed.
• the hooks output is dumped all at once as the hook finished - not live. for a long hook the client will appear frozen.
• [exporter:beforeLease] at the end of the line, should be at the begging?
• [exporter:beforeLease] printed for every line, even for a single command with multi-line output

 uv run jmp shell --selector hooks=both --duration 60s
[02/16/26 15:59:21] INFO     Acquiring lease 019c66bf-a42d-7744-8f68-0317b8e6ef07 for selector hooks=both for duration 0:01:00 [jumpstarter.client.lease]
                    INFO     Waiting for ready connection at /run/user/1000/jumpstarter-n3pc9ree/socket [jumpstarter.client.lease]
[02/16/26 15:59:32] INFO     Status changed: None -> LEASE_READY (version=3) [jumpstarter.client.status_monitor]
                    INFO     Starting hook subprocess... [exporter:beforeLease]
                    INFO     Creating PTY pair... [exporter:beforeLease]
                    INFO     PTY created: parent_fd=18, child_fd=19 [exporter:beforeLease]
                    INFO     Executing inline script (interpreter: /bin/sh) [exporter:beforeLease]
                    INFO     Spawning subprocess with command: ['/bin/sh', '-c', 'echo "Powering on..."\nj power on\nsleep 5\necho "ok"\nsleep 5\necho "done prelease"\n']
                             [exporter:beforeLease]
python ⚡hooks-test-both ➤                     INFO     Subprocess spawned with PID 2363346 [exporter:beforeLease]
                    INFO     Starting PTY output reader and process waiter (timeout=60) [exporter:beforeLease]
                    INFO     Task group created, starting tasks... [exporter:beforeLease]
                    INFO     Waiting for subprocess to complete... [exporter:beforeLease]
                    INFO     Powering on... [exporter:beforeLease]
                    INFO     ok [exporter:beforeLease]
                    INFO     done prelease [exporter:beforeLease]
                    INFO     Subprocess completed with code: 0 [exporter:beforeLease]
                    INFO     Hook executed successfully [exporter:beforeLease]

[ambient-code]

Investigation Findings

Sub-issue 1: beforeHook too verbose without --exporter-logs

Root Cause: In hooks.py:_execute_hook_process, debug messages like "Starting hook subprocess...", "Creating PTY pair...", "PTY created: parent_fd=18...", "Executing inline script...", "Spawning subprocess with command: ..." are logged at logger.debug() and logger.info() level (lines 229-412). These go through the Session's LogHandler (exporter/logging.py), which routes them into the LogStream via context_log_source().

On the client side, in core.py:460-510, log_stream_async receives these log records. Hook messages (LogSource.BEFORE_LEASE_HOOK / AFTER_LEASE_HOOK) are ALWAYS shown regardless of show_all_logs (line 486: if is_hook or show_all_logs). This means ALL hook log records -- including DEBUG-level internal messages -- are forwarded to the client.

The issue is that internal debug/info messages from the hook executor itself (not the hook script's output) are logged through the same logger name (__name__ = jumpstarter.exporter.hooks) with context_log_source active, so they get tagged as hook messages and sent to the client.

Fix:

• Change the internal hook executor messages (PTY creation, subprocess spawning, etc.) to use logger.debug() consistently
• On the client side, filter hook messages by severity -- only show INFO and above for hook log source, or better yet, distinguish between "hook script output" (line 354: logger.info("%s", line_decoded)) and "hook infrastructure messages" by using a separate logger name for hook script output vs. hook executor internals
• Alternatively, use a dedicated logger for hook script output (e.g., jumpstarter.exporter.hooks.output) and only route that through context_log_source

Sub-issue 2: Hook output dumped all at once, not streaming/live

Root Cause: The hook subprocess writes to a PTY (hooks.py:274-281), and the read_pty_output coroutine (hooks.py:301-367) reads from the PTY and logs each line via logger.info(). These log records go into the Session's _logging_queue (a deque(maxlen=256), session.py:83). The client polls this queue via LogStream RPC (session.py:331-337), which yields records with a 50ms poll interval.

The issue is that the read_pty_output reads are gated by anyio.wait_readable(parent_fd) with a 0.1s timeout (hooks.py:314-315). This SHOULD stream in real-time. However, the log records may be delayed because:

1. The PTY buffering in the subprocess might batch output
2. The read_pty_output task and the LogStream RPC are in different async contexts -- the LogStream is on the client's gRPC connection, while the hook runs on the exporter's event loop
3. The status monitor polls block the client from reading log stream messages promptly

The most likely cause is that the client's wait_for_any_of([LEASE_READY, ...]) (shell.py:302) blocks until the beforeLease hook completes. During this time, the log stream is running in a background task and should be streaming. But the Rich logging handler on the client side might buffer console output.

Fix: Verify that the RichHandler on the client side flushes after each log record. Also ensure the hook subprocess's PTY is truly line-buffered (the code sets it up correctly with PTY, which should force line buffering).

Sub-issue 3: [exporter:beforeLease] tag at end of line instead of beginning

Root Cause: This is a RichHandler formatting issue. In core.py:509, hook log records are routed through logging.getLogger(logger_name) where logger_name is e.g., "exporter:beforeLease". Rich's RichHandler places the logger name (or handler name) at the end of the line by default in its right-aligned column layout.

Fix: Configure the RichHandler used for exporter log display to place the source tag at the beginning, or use a custom formatter that prefixes the tag. The client-side logging setup (likely in the CLI's main entry point) should configure the log format to put [logger_name] as a prefix.

Sub-issue 4: Tag printed for every line of multi-line output

Root Cause: Each line of hook output is logged as a separate logger.info() call (hooks.py:354: logger.info("%s", line_decoded)). The LogHandler creates a separate LogStreamResponse for each call (logging.py:46-51). On the client side, each response is logged separately via source_logger.log(log_level, response.message) (core.py:510), so each line gets its own tag.

Fix: The hook executor could batch multi-line output that arrives in the same read chunk and log it as a single message. In read_pty_output (hooks.py:349-354), when multiple lines are processed from the same buffer, they could be joined and logged as one message. However, this would interfere with live streaming. A better approach is to suppress the tag on continuation lines on the client side, or only show the tag on the first line of a burst.

Relevant Files

• python/packages/jumpstarter/jumpstarter/exporter/hooks.py (lines 229-367) - Hook executor logging
• python/packages/jumpstarter/jumpstarter/exporter/logging.py - LogHandler that routes to LogStream
• python/packages/jumpstarter/jumpstarter/client/core.py (lines 460-547) - Client-side log_stream_async
• python/packages/jumpstarter/jumpstarter/exporter/session.py (lines 331-337) - LogStream RPC