fix(daemon): rotate log file at cap and recover from tcpPortUsed ETIMEDOUT

The daemon's file logger silently dropped every write once the log file
exceeded a hard 20MB cap, leaving long-running daemons with a frozen
log file and `bitsocial logs -f` stuck on stale content. Compounding
this, process.stderr.write was overridden to route only to the file
logger, so once the cap tripped all stderr output was lost. Separately,
the keepKuboUpInterval awaited tcpPortUsed.check outside its try/catch,
so a transient ETIMEDOUT on 127.0.0.1:9138 became an unhandledRejection.

- Extract the file logger into common-utils/daemon-file-logger.ts with
  front-truncate rotation: when bytesWritten exceeds maxBytes, end the
  stream, keep the last trimToBytes (line-aligned), rewrite the file,
  and reopen in append mode. Concurrent writes during a trim are queued
  and drained after, capped to bound memory.
- writeTimestampedLine now returns boolean; the daemon's stderr and
  debug-module overrides fall back to the original stderr when it
  returns false, so debug/error output is never silently lost.
- Extract the keepKuboUp interval body into runKeepKuboUpTick(deps),
  exported for testing, with tcpPortUsedCheck inside the try/catch.

Refs #37

Author: Rinse12

src/cli/commands/daemon.ts

@@ -20,6 +20,7 @@ import { loadChallengesIntoPKC } from "../../challenge-packages/challenge-utils.
 import { migrateDataDirectory } from "../../common-utils/data-migration.js";
 import { createBsoResolvers, DEFAULT_PROVIDERS } from "../../common-utils/resolvers.js";
 import { pruneStaleStates, writeDaemonState, deleteDaemonState } from "../../common-utils/daemon-state.js";
+import { createDaemonFileLogger, type DaemonFileLogger } from "../../common-utils/daemon-file-logger.js";
 import fs from "fs";
 import fsPromise from "fs/promises";
 
@@ -46,6 +47,44 @@ const defaultPkcOptions: InputPKCOptions = {
     httpRoutersOptions: defaults.HTTP_TRACKERS
 };
 
+export interface KeepKuboUpTickDeps {
+    pkcRpcUrl: URL;
+    tcpPortUsedCheck: (port: number, host: string) => Promise<boolean>;
+    pkcOptionsFromFlag: { kuboRpcClientsOptions?: unknown } | undefined;
+    usingDifferentProcessRpc: boolean;
+    hasKuboProcess: boolean;
+    hasPendingKuboStart: boolean;
+    keepKuboUp: () => Promise<void>;
+    createOrConnectRpc: () => Promise<void>;
+    onError: (message: string) => void;
+}
+
+/**
+ * Runs one tick of the keepKuboUp interval. Exported so it can be unit-tested.
+ *
+ * Both `tcpPortUsedCheck` and the downstream `keepKuboUp`/`createOrConnectRpc` calls
+ * are wrapped in try/catch — a transient ETIMEDOUT from the port check (or any other
+ * error from this tick) must not propagate to the setInterval callback, which would
+ * become an unhandledRejection (issue #37 bug 3).
+ */
+export async function runKeepKuboUpTick(deps: KeepKuboUpTickDeps): Promise<void> {
+    let isRpcPortTaken = false;
+    try {
+        isRpcPortTaken = await deps.tcpPortUsedCheck(Number(deps.pkcRpcUrl.port), deps.pkcRpcUrl.hostname);
+        if (!deps.pkcOptionsFromFlag?.kuboRpcClientsOptions && !isRpcPortTaken && !deps.usingDifferentProcessRpc) await deps.keepKuboUp();
+        else if (deps.pkcOptionsFromFlag?.kuboRpcClientsOptions && !deps.usingDifferentProcessRpc) await deps.keepKuboUp();
+        // Retry if kubo died and onKuboExit's restart attempt failed (e.g. transient port conflict)
+        else if (!deps.hasKuboProcess && !deps.hasPendingKuboStart && !deps.usingDifferentProcessRpc) await deps.keepKuboUp();
+    } catch (error) {
+        deps.onError(`keepKuboUp tick error (will retry): ${error instanceof Error ? error.message : String(error)}`);
+    }
+    try {
+        await deps.createOrConnectRpc();
+    } catch (error) {
+        deps.onError(`createOrConnectRpc tick error (will retry): ${error instanceof Error ? error.message : String(error)}`);
+    }
+}
+
 export default class Daemon extends Command {
     static override description = `Run a network-connected Bitsocial node. Once the daemon is running you can create and start your communities and receive publications from users. The daemon will also serve web ui on http that can be accessed through a browser on any machine. Within the web ui users are able to browse, create and manage their communities fully P2P.
     Options can be passed to the RPC's instance through flag --pkcOptions.optionName. For a list of pkc options (https://github.com/pkcprotocol/pkc-js?tab=readme-ov-file#pkcoptions)
@@ -115,24 +154,13 @@ export default class Daemon extends Command {
     private async _pipeDebugLogsToLogFile(
         logPath: string,
         Logger: PKCLoggerType
-    ): Promise<{ logFilePath: string; stdoutWrite: typeof process.stdout.write }> {
+    ): Promise<{ logFilePath: string; stdoutWrite: typeof process.stdout.write; fileLogger: DaemonFileLogger }> {
         const { logFilePath, deletedLogFile, logfilesCapacity } = await this._getNewLogfileByEvacuatingOldLogsIfNeeded(logPath);
 
-        const logFile = fs.createWriteStream(logFilePath, { flags: "a" });
+        const fileLogger = createDaemonFileLogger({ logFilePath });
         const stdoutWrite = process.stdout.write.bind(process.stdout);
         const stderrWrite = process.stderr.write.bind(process.stderr);
 
-        const isLogFileOverLimit = () => logFile.bytesWritten > 20000000; // 20mb
-
-        const writeTimestampedLine = (text: string, stream: "stdout" | "stderr") => {
-            if (isLogFileOverLimit()) return;
-            if (!text || text.trim().length === 0) return;
-            const timestamp = `[${new Date().toISOString()}] [${stream}] `;
-            const lines = text.split("\n");
-            const timestamped = lines.map((line, i) => (i === 0 ? timestamp + line : line)).join("\n");
-            logFile.write(timestamped);
-        };
-
         // Redirect debug library output directly to the log file
         // instead of stderr, so only real errors appear in the terminal
         const require = createRequire(import.meta.url);
@@ -142,24 +170,32 @@ export default class Daemon extends Command {
         debugModule.inspectOpts.colors = true;
         debugModule.inspectOpts.hideDate = true;
         debugModule.log = (...args: any[]) => {
-            writeTimestampedLine(formatWithOptions({ depth: Logger.inspectOpts?.depth || 10, colors: true }, ...args).trimStart() + EOL, "stderr");
+            const text = formatWithOptions({ depth: Logger.inspectOpts?.depth || 10, colors: true }, ...args).trimStart() + EOL;
+            const wrote = fileLogger.writeTimestampedLine(text, "stderr");
+            // If the file logger could not accept the write (closed / pending buffer full),
+            // fall back to original stderr so debug output is never silently lost
+            if (!wrote) stderrWrite(text);
         };
 
         const asString = (data: string | Uint8Array) => (typeof data === "string" ? data : Buffer.from(data).toString());
 
         process.stdout.write = (...args) => {
             //@ts-expect-error
             const res = stdoutWrite(...args);
-            writeTimestampedLine(asString(args[0]), "stdout");
+            fileLogger.writeTimestampedLine(asString(args[0]), "stdout");
             return res;
         };
 
         process.stderr.write = (...args) => {
-            // Only write stderr to the log file, not to the terminal.
-            // Debug output goes to stderr; we want it in logs only.
-            // Real errors are caught by uncaughtException/unhandledRejection handlers
-            // which use console.error -> stderr.write -> this override -> log file.
-            writeTimestampedLine(asString(args[0]).trimStart(), "stderr");
+            // Debug output goes to stderr; route it to the log file.
+            // If the file logger is unavailable (closed, errored), fall back to original stderr
+            // so output is never silently swallowed.
+            const text = asString(args[0]);
+            const wrote = fileLogger.writeTimestampedLine(text.trimStart(), "stderr");
+            if (!wrote) {
+                //@ts-expect-error
+                return stderrWrite(...args);
+            }
             return true;
         };
 
@@ -184,9 +220,13 @@ export default class Daemon extends Command {
             console.error(err);
         });
 
-        process.on("exit", () => logFile.close());
+        process.on("exit", () => {
+            // close() returns a promise but exit handlers must be synchronous.
+            // Best-effort: trigger the close; the underlying writeStream flushes on process exit.
+            fileLogger.close().catch(() => {});
+        });
 
-        return { logFilePath, stdoutWrite };
+        return { logFilePath, stdoutWrite, fileLogger };
     }
 
     async run() {
@@ -532,16 +572,17 @@ export default class Daemon extends Command {
 
             keepKuboUpInterval = setInterval(async () => {
                 if (mainProcessExited) return;
-                const isRpcPortTaken = await tcpPortUsed.check(Number(pkcRpcUrl.port), pkcRpcUrl.hostname);
-                try {
-                    if (!pkcOptionsFromFlag?.kuboRpcClientsOptions && !isRpcPortTaken && !usingDifferentProcessRpc) await keepKuboUp();
-                    else if (pkcOptionsFromFlag?.kuboRpcClientsOptions && !usingDifferentProcessRpc) await keepKuboUp();
-                    // Retry if kubo died and onKuboExit's restart attempt failed (e.g. transient port conflict)
-                    else if (!kuboProcess && !pendingKuboStart && !usingDifferentProcessRpc) await keepKuboUp();
-                } catch (error) {
-                    log.trace(`keepKuboUp error (will retry): ${error instanceof Error ? error.message : String(error)}`);
-                }
-                await createOrConnectRpc();
+                await runKeepKuboUpTick({
+                    pkcRpcUrl,
+                    tcpPortUsedCheck: (port, host) => tcpPortUsed.check(port, host),
+                    pkcOptionsFromFlag,
+                    usingDifferentProcessRpc,
+                    hasKuboProcess: !!kuboProcess,
+                    hasPendingKuboStart: !!pendingKuboStart,
+                    keepKuboUp,
+                    createOrConnectRpc,
+                    onError: (msg) => log.trace(msg)
+                });
             }, 5000);
         } catch (err) {
             const errorMsg = err instanceof Error ? err.message : String(err);

src/common-utils/daemon-file-logger.ts

@@ -0,0 +1,140 @@
+import fs from "fs";
+import fsPromise from "fs/promises";
+
+export interface DaemonFileLoggerOptions {
+    logFilePath: string;
+    /** Trigger a trim once the current writer's bytesWritten exceeds this. Defaults to 20 MB. */
+    maxBytes?: number;
+    /** Target file size after trim. Must be < maxBytes. Defaults to 15 MB. */
+    trimToBytes?: number;
+    /** Bound on how many bytes of writes are buffered while a trim cycle is running. */
+    pendingByteCap?: number;
+}
+
+export interface DaemonFileLogger {
+    /**
+     * Append a timestamped line to the log file. Returns false when the write was
+     * dropped (e.g. the logger is closed or the in-flight pending buffer is full),
+     * letting the caller decide whether to fall back to terminal output.
+     */
+    writeTimestampedLine(text: string, stream: "stdout" | "stderr"): boolean;
+    close(): Promise<void>;
+    /** Force-run a trim cycle — for tests. */
+    _trimNow(): Promise<void>;
+    readonly currentPath: string;
+    readonly bytesWritten: number;
+}
+
+const DEFAULT_MAX = 20_000_000;
+const DEFAULT_TRIM_TO = 15_000_000;
+const DEFAULT_PENDING_CAP = 5_000_000;
+
+export function createDaemonFileLogger(options: DaemonFileLoggerOptions): DaemonFileLogger {
+    const maxBytes = options.maxBytes ?? DEFAULT_MAX;
+    const trimToBytes = options.trimToBytes ?? DEFAULT_TRIM_TO;
+    const pendingByteCap = options.pendingByteCap ?? DEFAULT_PENDING_CAP;
+    if (trimToBytes >= maxBytes) {
+        throw new Error(`trimToBytes (${trimToBytes}) must be less than maxBytes (${maxBytes})`);
+    }
+    const logFilePath = options.logFilePath;
+
+    let stream = fs.createWriteStream(logFilePath, { flags: "a" });
+    stream.on("error", () => {});
+    let trimming: Promise<void> | undefined;
+    let pending: string[] = [];
+    let pendingBytes = 0;
+    let closed = false;
+
+    const reopenStream = () => {
+        stream.removeAllListeners("error");
+        stream = fs.createWriteStream(logFilePath, { flags: "a" });
+        stream.on("error", () => {});
+    };
+
+    const trim = async () => {
+        // End the current stream first so its buffered writes flush to disk before we read the file
+        await new Promise<void>((res) => stream.end(() => res()));
+
+        const stat = await fsPromise.stat(logFilePath).catch(() => null);
+        if (stat && stat.size > trimToBytes) {
+            const fd = await fsPromise.open(logFilePath, "r");
+            try {
+                const buf = Buffer.alloc(trimToBytes);
+                await fd.read(buf, 0, trimToBytes, stat.size - trimToBytes);
+                // Skip a partial line at the start so the file always starts on a line boundary
+                const firstNewline = buf.indexOf(0x0a);
+                const tail = firstNewline >= 0 ? buf.subarray(firstNewline + 1) : buf;
+                await fsPromise.writeFile(logFilePath, tail);
+            } finally {
+                await fd.close();
+            }
+        }
+        reopenStream();
+    };
+
+    const drainPending = () => {
+        if (pending.length === 0) return;
+        const drained = pending;
+        pending = [];
+        pendingBytes = 0;
+        for (const chunk of drained) {
+            stream.write(chunk);
+        }
+    };
+
+    const scheduleTrim = () => {
+        if (trimming) return;
+        trimming = trim()
+            .catch(() => {
+                // If trim fails (FS error, etc.) we drop the pending buffer rather than
+                // hold memory forever. The next write will hit the same condition and retry.
+                pending = [];
+                pendingBytes = 0;
+            })
+            .finally(() => {
+                trimming = undefined;
+                drainPending();
+            });
+    };
+
+    const writeTimestampedLine = (text: string, streamLabel: "stdout" | "stderr"): boolean => {
+        if (closed) return false;
+        if (!text || text.trim().length === 0) return false;
+        const timestamp = `[${new Date().toISOString()}] [${streamLabel}] `;
+        const lines = text.split("\n");
+        const timestamped = lines.map((line, i) => (i === 0 ? timestamp + line : line)).join("\n");
+
+        if (trimming) {
+            // A trim cycle is in flight — buffer up to pendingByteCap, then drop with false
+            // so the caller can fall back to writing to the terminal.
+            if (pendingBytes + timestamped.length > pendingByteCap) return false;
+            pending.push(timestamped);
+            pendingBytes += timestamped.length;
+            return true;
+        }
+
+        stream.write(timestamped);
+
+        if (stream.bytesWritten > maxBytes) scheduleTrim();
+        return true;
+    };
+
+    return {
+        writeTimestampedLine,
+        async close() {
+            closed = true;
+            if (trimming) await trimming.catch(() => {});
+            await new Promise<void>((res) => stream.end(() => res()));
+        },
+        async _trimNow() {
+            scheduleTrim();
+            if (trimming) await trimming;
+        },
+        get currentPath() {
+            return logFilePath;
+        },
+        get bytesWritten() {
+            return stream.bytesWritten;
+        }
+    };
+}