From 37daef770355dc4b20337e243257d6da8ec8ce64 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?J=C3=B6rg=20Thalheim?= <joerg@thalheim.io>
Date: Wed, 26 Aug 2026 12:59:55 +0200
Subject: [PATCH] JSONLogger: rate-limit resProgress per activity

copyPaths() reports progress for every NAR chunk and JSONLogger wrote a
line for each. In build-remote the log fd is a pipe that nix-daemon only
drains between goal iterations, so the hook blocked in
JSONLogger::write mid-NAR while holding the upload lock, stalling all
remote builds to that machine.

This is fixed by emitting resProgress at most every 100ms per activity,
except for the final update (done >= expected).

This commit just removes the trigger but we might want to fix the underlying
issue later in a more prinicipaled way that removes the hook's log output
completely from the tryBuildHook logic, since the pipe theoretically
still can get full.

However overall it seems reasonable to rate limit this event anyhow to
reduce load on nix clients and this fix might be an easy backport.
---
 src/libutil-tests/json-logger.cc | 47 ++++++++++++++++++++++++++++++++
 src/libutil-tests/meson.build    |  1 +
 src/libutil/logging.cc           | 31 +++++++++++++++++++++
 3 files changed, 79 insertions(+)
 create mode 100644 src/libutil-tests/json-logger.cc

diff --git a/src/libutil-tests/json-logger.cc b/src/libutil-tests/json-logger.cc
new file mode 100644
index 000000000000..2adad277ad23
--- /dev/null
+++ b/src/libutil-tests/json-logger.cc
@@ -0,0 +1,47 @@
+#include "nix/util/logging.hh"
+#include "nix/util/file-system.hh"
+#include "nix/util/strings.hh"
+
+#include <gtest/gtest.h>
+
+namespace nix {
+
+static size_t countLines(const std::filesystem::path & path, std::string_view needle)
+{
+    size_t n = 0;
+    for (auto & line : tokenizeString<Strings>(readFile(path), "\n"))
+        if (line.find(needle) != line.npos)
+            n++;
+    return n;
+}
+
+TEST(JSONLogger, progressIsRateLimited)
+{
+    auto tmpDir = createTempDir();
+    AutoDelete delTmpDir(tmpDir, true);
+    auto path = tmpDir / "log";
+    {
+        auto jsonLogger = makeJSONLogger(path, false);
+        Activity act(*jsonLogger, lvlInfo, actCopyPath, "copy", {}, 0);
+        for (uint64_t i = 1; i <= 100000; ++i)
+            act.progress(i, 100000);
+    }
+    EXPECT_LT(countLines(path, "\"type\":105"), 100u);
+    EXPECT_EQ(countLines(path, "\"fields\":[100000,100000,0,0]"), 1u);
+}
+
+TEST(JSONLogger, otherResultsAreNotRateLimited)
+{
+    auto tmpDir = createTempDir();
+    AutoDelete delTmpDir(tmpDir, true);
+    auto path = tmpDir / "log";
+    {
+        auto jsonLogger = makeJSONLogger(path, false);
+        Activity act(*jsonLogger, lvlInfo, actBuild, "build", {}, 0);
+        for (int i = 0; i < 1000; ++i)
+            act.result(resBuildLogLine, "x");
+    }
+    EXPECT_EQ(countLines(path, "\"type\":101"), 1000u);
+}
+
+} // namespace nix
diff --git a/src/libutil-tests/meson.build b/src/libutil-tests/meson.build
index 807bcbaa0ff5..aabcf8a20b90 100644
--- a/src/libutil-tests/meson.build
+++ b/src/libutil-tests/meson.build
@@ -59,6 +59,7 @@ sources = files(
   'git.cc',
   'hash.cc',
   'hilite.cc',
+  'json-logger.cc',
   'json-utils.cc',
   'local-keys.cc',
   'logging.cc',
diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc
index 3f766e82ff54..b413a5dee64b 100644
--- a/src/libutil/logging.cc
+++ b/src/libutil/logging.cc
@@ -9,6 +9,8 @@
 #include "nix/util/unix-domain-socket.hh"
 
 #include <atomic>
+#include <chrono>
+#include <map>
 #include <sstream>
 #include <nlohmann/json.hpp>
 
@@ -253,10 +255,28 @@ struct JSONLogger : Logger
     struct State
     {
         bool enabled = true;
+
+        /* resProgress is sampled per activity so that per-chunk updates
+           (e.g. from copyPaths) cannot back-pressure the log fd. */
+        std::map<ActivityId, std::chrono::steady_clock::time_point> lastProgress;
     };
 
     Sync<State> _state;
 
+    static constexpr std::chrono::milliseconds progressInterval{100};
+
+    /* resProgress fields are [done, expected, running, failed]. The update
+       that reaches `expected` is never dropped by the rate limit, otherwise
+       consumers could be left showing e.g. 97% for a finished copy. */
+    static bool isFinalProgress(std::span<const Field> fields)
+    {
+        if (fields.size() < 2)
+            return false;
+        auto done = std::get_if<uint64_t>(&fields[0]);
+        auto expected = std::get_if<uint64_t>(&fields[1]);
+        return done && expected && *expected && *done >= *expected;
+    }
+
     void write(const nlohmann::json & json)
     {
         auto line = (includeNixPrefix ? "@nix " : "")
@@ -335,6 +355,8 @@ struct JSONLogger : Logger
 
     void stopActivity(ActivityId act) noexcept override
     {
+        _state.lock()->lastProgress.erase(act);
+
         nlohmann::json json;
         json["action"] = "stop";
         json["id"] = act;
@@ -348,6 +370,15 @@ struct JSONLogger : Logger
         json["id"] = act;
         json["type"] = type;
         addFields(json, fields);
+
+        if (type == resProgress && !isFinalProgress(fields)) {
+            auto now = std::chrono::steady_clock::now();
+            auto & last = _state.lock()->lastProgress[act];
+            if (now - last < progressInterval)
+                return;
+            last = now;
+        }
+
         write(json);
     }
 };