Log agent output, and stop output capture from breaking logging

ClaudeR 0.14.1. Two problems from a user report.

Agent output was never logged. log_code_to_file() is called before the
code runs, so the entry could only ever hold the code. The executed
output is already captured for the response, so it is now appended to
the log entry as well.

The output capture added in 0.14.0 could stop console logging
altogether. start_console_logging() opened its sink before registering
the task callback, so a failure opening the sink aborted the function
and no commands were logged at all, which is worse than the gap it was
fixing. Opening the sink is now optional: on failure it degrades to
logging commands and their values, and says so.

Three further robustness fixes around the shared sink stack:
- execute_r unwound with a fallback that popped a sink when it had not
  opened one, which could remove the console sink. It no longer pops
  what it does not own.
- The console sink is restored if something else unwinds it, instead of
  silently recording nothing from that point on.
- execute_r opens its sink with split = TRUE on top of the console sink,
  so agent output cascaded into the console buffer and would have been
  attributed to the user. That buffer is now discarded after each run.

Logged output lines carry a #> marker, and replay, past-history and
notebook export skip them so output is never re-run as code. The same
filters now also skip the console entry header, which they did not.

R CMD check: Status OK.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

Author: IMNMV

DESCRIPTION

@@ -1,6 +1,6 @@
 Package: ClaudeR
 Title: R Integration for Claude AI
-Version: 0.14.0
+Version: 0.14.1
 Authors@R: person("Nykko", "Vitali", email = "nykvt@icloud.com", role = c("aut", "cre"))
 Description: Connects RStudio with Claude AI to enable interactive coding sessions.
 License: MIT + file LICENSE

R/console_log.R

@@ -46,7 +46,7 @@ console_note_condition <- function(kind, msg) {
   msg <- trimws(paste(msg, collapse = " "))
   if (!nzchar(msg)) return(invisible(NULL))
   .console_state$pending <- c(.console_state$pending,
-                              sprintf("# %s: %s", kind, msg))
+                              sprintf("#> %s: %s", kind, msg))
   invisible(NULL)
 }
 
@@ -59,6 +59,7 @@ console_sink_open <- function() {
   .console_state$sink_con <- con
   .console_state$consumed <- 0L
   sink(con, split = TRUE)
+  .console_state$sink_owned <- TRUE
   invisible(TRUE)
 }
 
@@ -68,7 +69,10 @@ console_sink_close <- function() {
   con <- .console_state$sink_con
   if (is.null(con)) return(invisible(FALSE))
   tryCatch({
-    if (sink.number() > 0) sink()
+    # Only pop if ours is the sink on top. Popping blindly would remove one
+    # that an agent execution opened and leave that execution writing nowhere.
+    if (isTRUE(.console_state$sink_owned) && sink.number() > 0) sink()
+    .console_state$sink_owned <- FALSE
     flush(con); close(con)
   }, error = function(e) NULL)
   tryCatch(unlink(.console_state$sink_file), error = function(e) NULL)
@@ -95,8 +99,22 @@ console_drain <- function() {
 
 `%||%` <- function(a, b) if (is.null(a)) b else a
 
+# Our sink can be removed by something else unwinding the sink stack. At top
+# level, with every execution finished, ours should be the only one left. If it
+# is gone, put it back rather than silently recording nothing from here on.
+console_sink_heal <- function() {
+  if (!isTRUE(.console_state$active)) return(invisible(FALSE))
+  if (isTRUE(.console_state$sink_owned) && sink.number() >= 1) return(invisible(FALSE))
+  if (sink.number() != 0) return(invisible(FALSE))
+  con <- .console_state$sink_con
+  if (!is.null(con)) tryCatch(close(con), error = function(e) NULL)
+  tryCatch(console_sink_open(), error = function(e) NULL)
+  invisible(TRUE)
+}
+
 console_task_callback <- function(expr, value, ok, visible) {
-  # Never let logging break the user's session.
+  # A task callback that signals an error is removed by R, which would end
+  # console logging silently, so nothing here is allowed to escape.
   tryCatch({
     if (is.null(console_log_path())) return(TRUE)
     code <- paste(deparse(expr), collapse = "\n")
@@ -107,21 +125,22 @@ console_task_callback <- function(expr, value, ok, visible) {
     lines <- character(0)
     printed <- console_drain()
     if (length(printed)) {
-      lines <- paste("#", console_trim(printed))
+      lines <- paste0("#> ", console_trim(printed))
     } else if (isTRUE(visible) && isTRUE(ok)) {
       # Nothing was printed as a side effect, so fall back to the value itself.
       out <- tryCatch(utils::capture.output(print(value)),
                       error = function(e) character(0))
-      if (length(out)) lines <- paste("#", console_trim(out))
+      if (length(out)) lines <- paste0("#> ", console_trim(out))
     }
-    if (!isTRUE(ok)) lines <- c(lines, "# error: command did not complete")
+    if (!isTRUE(ok)) lines <- c(lines, "#> error: command did not complete")
     if (length(.console_state$pending)) {
       lines <- c(.console_state$pending, lines)
       .console_state$pending <- NULL
     }
     body <- if (length(lines)) paste0(code, "\n", paste(lines, collapse = "\n")) else code
     console_write(body, tag = "user")
   }, error = function(e) NULL)
+  tryCatch(console_sink_heal(), error = function(e) NULL)
   TRUE
 }
 
@@ -136,12 +155,11 @@ console_task_callback <- function(expr, value, ok, visible) {
 start_console_logging <- function() {
   if (isTRUE(.console_state$active)) return(invisible(TRUE))
   .console_state$pending <- NULL
-  console_sink_open()
-  .console_state$handle <- addTaskCallback(console_task_callback,
-                                           name = "clauder_console_log")
+  # Order matters. globalCallingHandlers() cannot be wrapped in tryCatch (it
+  # refuses to run with handlers on the stack), so it goes first: if it fails,
+  # it fails before a sink or a callback has been installed, leaving nothing
+  # half-configured behind.
   if (getRversion() >= "4.0.0") {
-    # globalCallingHandlers() refuses to run with handlers on the stack, so it
-    # must not be wrapped in tryCatch here.
     .console_state$old_handlers <- globalCallingHandlers()
     # Observe only. Do NOT invoke the muffle restarts: the user must still see
     # their own warnings and messages in the console.
@@ -150,18 +168,29 @@ start_console_logging <- function() {
       message = function(m) console_note_condition("message", conditionMessage(m))
     )
   }
+  # Capturing printed output is the optional half. If the sink cannot be opened
+  # the callback must still be registered, or a failure here would silently
+  # stop commands being logged at all, which is worse than losing the output.
+  ok_sink <- isTRUE(tryCatch({ console_sink_open(); TRUE },
+                             error = function(e) FALSE))
+  .console_state$handle <- addTaskCallback(console_task_callback,
+                                           name = "clauder_console_log")
   .console_state$old_error <- getOption("error")
   options(error = function() {
     tryCatch({
       msg <- geterrmessage()
-      console_write(sprintf("# error: %s", trimws(msg)), tag = "user")
+      console_write(sprintf("#> error: %s", trimws(msg)), tag = "user")
     }, error = function(e) NULL)
   })
   reg.finalizer(.console_state,
                 function(e) tryCatch(console_sink_close(), error = function(x) NULL),
                 onexit = TRUE)
   .console_state$active <- TRUE
   message("ClaudeR: console logging on. Your console commands now appear in the session log.")
+  if (!ok_sink) {
+    message("ClaudeR: could not capture printed output here; ",
+            "commands and their values will still be logged.")
+  }
   # Our own startup message must not show up as the user's first log entry.
   .console_state$pending <- NULL
   invisible(TRUE)

R/notebook.R

@@ -92,7 +92,7 @@ export_log_as_notebook <- function(log_path = NULL, output_path = NULL,
     is_error <- grepl("(ERROR)", agent_line, fixed = TRUE)
     err_msgs <- sub("^# Error: ", "", block[grepl("^# Error: ", block)])
 
-    code_lines <- block[!grepl("^# --- \\[|^# Code executed by |^# Error: ", block)]
+    code_lines <- block[!grepl("^# --- \\[|^# Code executed by |^# Run by |^# Error: |^#> ", block)]
     while (length(code_lines) > 0 && trimws(code_lines[length(code_lines)]) == "") {
       code_lines <- code_lines[-length(code_lines)]
     }

R/ui.R

@@ -1441,6 +1441,21 @@ execute_code_in_session <- function(code, settings = NULL, agent_id = NULL) {
       output <- c(output, collected_conditions)
     }
 
+    # This execution's sink was opened on top of the console-logging sink (if
+    # one is active), and split = TRUE cascades, so everything printed here has
+    # also landed in the console buffer. Drop it, or the next thing the user
+    # types would carry the agent's output as if the user had produced it.
+    tryCatch(console_drain(), error = function(e) NULL)
+
+    # Record what the code printed, not just the code. The log is the one file
+    # an agent reads back to see what happened, and until now it showed the
+    # call but never its result.
+    if (settings$log_to_file && !is.null(settings$log_file_path) &&
+        settings$log_file_path != "" && length(output) > 0) {
+      tryCatch(log_output_to_file(output, settings$log_file_path),
+               error = function(e) NULL)
+    }
+
     # --- AFTER eval: only capture if a NEW plot was actually created ---
     captured_plot <- FALSE
     plot_data <- NULL
@@ -1583,7 +1598,10 @@ execute_code_in_session <- function(code, settings = NULL, agent_id = NULL) {
     # Unwind any sinks opened during this execution
     if (exists("sink_depth")) {
       while (sink.number() > sink_depth) sink()
-    } else if (sink.number() > 0) sink()
+    }
+    # No sink_depth means we failed before opening one. Do NOT pop blindly:
+    # console logging keeps a sink of its own underneath, and popping it
+    # silently stops the user's console from being recorded.
 
     # Recover whatever was printed before the error: partial output plus
     # captured warnings/messages are often exactly the context the agent
@@ -1636,7 +1654,10 @@ execute_code_in_session <- function(code, settings = NULL, agent_id = NULL) {
     # Unwind any sinks this execution opened
     if (exists("sink_depth")) {
       while (sink.number() > sink_depth) sink()
-    } else if (sink.number() > 0) sink()
+    }
+    # No sink_depth means we failed before opening one. Do NOT pop blindly:
+    # console logging keeps a sink of its own underneath, and popping it
+    # silently stops the user's console from being recorded.
 
     # Clean up temporary files
     if (exists("output_file") && file.exists(output_file)) {
@@ -1681,7 +1702,7 @@ past_history_entries <- function(max_files = 5L) {
       agent_line <- if (length(block) >= 2) block[2] else ""
       agent <- sub("^# Code executed by ([^ ]+).*$", "\\1", agent_line)
       agent <- sub(":$", "", agent)
-      code_lines <- block[!grepl("^# --- \\[|^# Code executed by |^# Error: ", block)]
+      code_lines <- block[!grepl("^# --- \\[|^# Code executed by |^# Run by |^# Error: |^#> ", block)]
       code_lines <- code_lines[nzchar(trimws(code_lines))]
       entries[[length(entries) + 1L]] <- list(
         timestamp = suppressWarnings(as.POSIXct(ts)),
@@ -1799,6 +1820,20 @@ validate_code_security <- function(code) {
   return(list(blocked = FALSE))
 }
 
+# Append what a command printed, under the entry just written for it.
+# The "#> " prefix marks these lines as output rather than code, so replay,
+# history and notebook export skip them.
+log_output_to_file <- function(output, log_path, max_lines = 40L) {
+  if (length(output) == 0) return(invisible(NULL))
+  if (length(output) > max_lines) {
+    output <- c(output[seq_len(max_lines)],
+                sprintf("... %d more lines not logged", length(output) - max_lines))
+  }
+  entry <- paste0(paste0("#> ", output, collapse = "\n"), "\n\n")
+  tryCatch(cat(entry, file = log_path, append = TRUE), error = function(e) NULL)
+  invisible(NULL)
+}
+
 #' Log code to file
 #'
 #' @param code The R code to log
@@ -1971,7 +2006,7 @@ export_log_as_script <- function(log_path = NULL, output_path = NULL, include_er
 
     # Extract code lines (skip the header comments)
     # Header lines: "# --- [timestamp] ---", "# Code executed by ...", "# Error: ..."
-    code_lines <- block[!grepl("^# --- \\[|^# Code executed by |^# Error: |^#\\s*$", block)]
+    code_lines <- block[!grepl("^# --- \\[|^# Code executed by |^# Run by |^# Error: |^#> |^#\\s*$", block)]
 
     # Remove trailing blank lines
     while (length(code_lines) > 0 && code_lines[length(code_lines)] == "") {

README.md

@@ -50,6 +50,8 @@ claudeAddin()
 <details>
 <summary><b>Recent Updates</b> (click to expand)</summary>
 
+- **Logging fixes (R 0.14.1).** Two problems from a user report. Agent output was never written to the log, only the code, because the entry was written before the code ran; the log now records what each call printed. And the output capture added in 0.14.0 could stop console logging entirely: it opened its own output sink before registering the console callback, so if that sink could not be opened, nothing was logged at all. Opening it is now optional and failing back to logging commands and their values, the sink is restored if another execution unwinds it, and an agent run no longer pops a sink it did not open. Logged output lines are marked so that replay, history and notebook export skip them.
+
 - **Console logging now captures output, not just results (R 0.14.0).** From follow-up on the logging request. The log recorded the value a command returned, so anything printed as a side effect was missing: `cat()`, progress output, and `print()` called inside a function. Running `f()` showed the call but not what `f()` printed, which is exactly the context an agent needs when you hand it an error you hit yourself. Standard output is now teed to the log and grouped under the command that produced it, alongside the warnings, messages, and errors already captured. Your console still shows everything as normal.
 
 - **Windows session-liveness fix (R 0.13.2).** Checking whether a recorded R session was still alive used `tools::pskill(pid, signal = 0)`. That is the standard idiom on Unix, but on Windows `pskill` always calls `TerminateProcess` regardless of signal, so the check killed the session it was asking about, then reported it as alive and left the stale discovery file in place. Starting a server could therefore terminate another RStudio session and leave agents routed to a dead port. Liveness is now probed without signalling. Separately, registering a session whose name is already held by a different live session now warns instead of silently overwriting its discovery file, which had left agents holding the wrong port and token.