Merge pull request #10324 from gadfort/web-log

web: cleanup logger handling

Author: gadfort

src/web/BUILD

@@ -169,6 +169,7 @@ cc_library(
         "@boost.beast",
         "@boost.geometry",
         "@boost.json",
+        "@boost.system",
         "@spdlog",
         "@tcl_lang//:tcl",
     ],

src/web/include/web/web.h

@@ -15,6 +15,7 @@
 #include <vector>
 
 #include "boost/asio/ip/tcp.hpp"
+#include "boost/asio/steady_timer.hpp"
 #include "odb/db.h"
 #include "tcl.h"
 #include "utl/Logger.h"
@@ -133,6 +134,13 @@ class WebServer
   std::unique_ptr<boost::asio::io_context> ioc_;
   std::vector<std::thread> threads_;
 
+  // Periodic timer that drains WebLogSink so log output produced by
+  // long-running Tcl commands streams to clients without waiting for a
+  // debug pause/redraw or for the command to return.  Reschedules
+  // itself; cancelled in stop() before ioc_ is shut down.
+  std::unique_ptr<boost::asio::steady_timer> log_drain_timer_;
+  void scheduleLogDrain();
+
   // Closes the Listener's acceptor before the io_context is destroyed,
   // avoiding a crash where the acceptor references a half-destroyed
   // io_context.

src/web/src/main.js

@@ -505,12 +505,12 @@ function createTclConsole(container) {
             tclAppend(`>>> ${cmd}\n`, 'tcl-cmd');
             completer.addToHistory(cmd);
             input.value = '';
+            // Log output produced while the command runs streams in
+            // separately as {"type":"log",...} push messages (handled
+            // below in the onPush dispatch).  The eval response only
+            // carries the Tcl return value plus shutdown signaling.
             app.websocketManager.request({ type: 'tcl_eval', cmd })
                 .then(data => {
-                    if (data.output) {
-                        tclAppend(data.output,
-                                  data.is_error ? 'tcl-error' : '');
-                    }
                     if (data.result) {
                         tclAppend(data.result + '\n',
                                   data.is_error ? 'tcl-error' : '');

src/web/src/request_handler.cpp

@@ -1208,7 +1208,6 @@ WebSocketResponse TclHandler::handleTclEval(const WebSocketRequest& req)
     // teardown is already requested by tclExitHandler via requestStop().
     const bool is_exit = (result.result == kExitResultMsg);
     boost::json::object root;
-    root["output"] = result.output;
     if (is_exit) {
       tcl_eval_->logger->info(
           utl::WEB, 40, "Exit requested from web GUI; shutting down.");

src/web/src/request_handler.h

@@ -7,6 +7,7 @@
 #include <boost/json/value.hpp>
 #include <boost/json/value_to.hpp>
 #include <cstdint>
+#include <functional>
 #include <map>
 #include <memory>
 #include <mutex>
@@ -36,16 +37,23 @@ class ClockTreeReport;
 // shutdown signal for the browser.
 inline constexpr const char* kExitResultMsg = "_WEB_EXITING_";
 
-// Thread-safe Tcl command evaluation with output capture.
+// Thread-safe Tcl command evaluation.  Log output emitted while the
+// command runs is captured by WebLogSink (registered on the logger via
+// addSink) and pushed to clients as {"type":"log",...} messages — do
+// NOT redirect the logger to a string here.  redirectStringBegin clears
+// the entire sink list, which would unhook WebLogSink (and any other
+// sink) for the duration of the command and break log streaming.  After
+// each eval the optional drain_output hook is invoked so any buffered
+// log output reaches clients before the eval response is sent.
 struct TclEvaluator
 {
   Tcl_Interp* interp;
   utl::Logger* logger;
   std::mutex mutex;
+  std::function<void()> drain_output;
 
   struct Result
   {
-    std::string output;
     std::string result;
     bool is_error;
   };
@@ -58,12 +66,13 @@ struct TclEvaluator
   Result eval(const std::string& cmd)
   {
     std::lock_guard<std::mutex> lock(mutex);
-    logger->redirectStringBegin();
     const int rc = Tcl_Eval(interp, cmd.c_str());
     Result r;
-    r.output = logger->redirectStringEnd();
     r.result = Tcl_GetStringResult(interp);
     r.is_error = (rc != TCL_OK);
+    if (drain_output) {
+      drain_output();
+    }
     return r;
   }
 };

src/web/src/web_serve.cpp

@@ -18,8 +18,13 @@
 #include <utility>
 #include <vector>
 
+#include "boost/asio/error.hpp"
 #include "boost/asio/io_context.hpp"
 #include "boost/asio/ip/tcp.hpp"
+#include "boost/asio/post.hpp"
+#include "boost/asio/steady_timer.hpp"
+#include "boost/asio/strand.hpp"
+#include "boost/system/error_code.hpp"
 // NOLINTNEXTLINE(misc-include-cleaner)
 #include "boost/beast/core.hpp"
 // NOLINTNEXTLINE(misc-include-cleaner)
@@ -168,6 +173,13 @@ void WebServer::serve(int port)
     logger_->addSink(log_sink_);
     viewer_hook_->setDrainLogsFn(
         [log_sink = std::move(log_sink)]() { log_sink->drainToClients(); });
+    // Flush WebLogSink at the end of every Tcl eval so log output
+    // emitted during a command reaches clients before the response
+    // carrying the Tcl result.  viewer_hook_ outlives every io thread
+    // that can run a request handler (stop() joins io threads before
+    // resetting viewer_hook_), so the raw pointer capture is safe.
+    tcl_eval->drain_output
+        = [hook = viewer_hook_.get()]() { hook->drainLogs(); };
 
     TileGenerator::setDebugOverlayCallback(
         [weak_gen = std::weak_ptr<TileGenerator>(generator_),
@@ -210,6 +222,17 @@ void WebServer::serve(int port)
 
     const std::string url = "http://localhost:" + std::to_string(handle.port);
 
+    // Bind the timer to a strand so all timer operations (expires_after,
+    // async_wait, cancel) run serialized on a single io thread.  Without
+    // this, stop()'s cancel from the caller thread would race with the
+    // async_wait handler rescheduling on a worker thread — the same
+    // steady_timer cannot be safely mutated from multiple threads.  The
+    // initial scheduleLogDrain() below runs before io threads start, so
+    // it is single-threaded by construction.
+    log_drain_timer_ = std::make_unique<net::steady_timer>(
+        net::make_strand(ioc_->get_executor()));
+    scheduleLogDrain();
+
     threads_.reserve(num_threads);
     for (int i = 0; i < num_threads; ++i) {
       threads_.emplace_back([this] { ioc_->run(); });
@@ -275,6 +298,32 @@ int WebServer::tclExitHandler(ClientData clientData,
   return TCL_ERROR;
 }
 
+// Drain interval chosen to keep the browser console feeling live without
+// burning CPU when nothing is logged.  An idle tick costs one mutex
+// acquire + empty-buffer check inside WebLogSink::drainToClients.
+static constexpr auto kLogDrainInterval = std::chrono::milliseconds(250);
+
+void WebServer::scheduleLogDrain()
+{
+  if (!log_drain_timer_) {
+    return;
+  }
+  log_drain_timer_->expires_after(kLogDrainInterval);
+  log_drain_timer_->async_wait([this](const boost::system::error_code& ec) {
+    // operation_aborted means cancel() was called from stop().  Any
+    // other error (or none) means the timer fired normally — drain and
+    // reschedule.  ioc_->stop() in stop() will discard a re-armed timer
+    // before its next firing, so no UAF risk on shutdown.
+    if (ec == net::error::operation_aborted) {
+      return;
+    }
+    if (viewer_hook_) {
+      viewer_hook_->drainLogs();
+    }
+    scheduleLogDrain();
+  });
+}
+
 void WebServer::requestStop()
 {
   if (!isRunning()) {
@@ -316,7 +365,20 @@ void WebServer::stop()
     shutdown_listener_();
     shutdown_listener_ = {};
   }
+  // Cancel the periodic log drain so its handler stops re-arming.  The
+  // cancel is posted onto the timer's strand so it runs serialized with
+  // scheduleLogDrain — calling cancel() directly from the caller thread
+  // would race with the async_wait handler mutating the timer on an io
+  // thread.  Any in-flight handler completes normally; a re-armed timer
+  // is discarded by ioc_->stop() below.
+  if (log_drain_timer_) {
+    auto* timer = log_drain_timer_.get();
+    net::post(timer->get_executor(), [timer] { timer->cancel(); });
+  }
   stopAndJoinIoThreads();
+  // Reset only after threads are joined so no handler can dereference
+  // the timer mid-shutdown.
+  log_drain_timer_.reset();
   // Release without destroying — destroying io_context can crash on
   // residual async handlers. Leak is bounded (at most one io_context
   // per serve/stop cycle).