From ae1c6a7b49d9b4f8cf7218c0baec84f348eb5ef6 Mon Sep 17 00:00:00 2001 From: bitflash-maintainer Date: Wed, 2 Sep 2026 05:26:51 +0000 Subject: log: cap debug.log in-process, and ship a logrotate policy debug.log grew without bound (production: 1.95 GiB, 51-129 MB/day). Nothing shrank it once the process was up -- there is no ShrinkDebugFile in this tree, and upstream's only ran at startup. OutputDebugStringF now rolls the file to debug.log.old when it passes -maxdebugfilesize (MB, default 1024, 0 disables). The write path already opens and closes the file per line under one lock, so the rename-and-reopen is a few lines inside that lock and no fd can be stranded mid-roll. contrib/logrotate/bitflash-debug.logrotate is the longer-term policy (size 1G, rotate 4, compress, missingok, notifempty, copytruncate); copytruncate keeps the writer's append handle valid across rotation. Closes #34 --- src/util.cpp | 5 +++++ 1 file changed, 5 insertions(+) (limited to 'src/util.cpp') diff --git a/src/util.cpp b/src/util.cpp index 0cd0133..52cda84 100644 --- a/src/util.cpp +++ b/src/util.cpp @@ -8,6 +8,11 @@ bool fDebug = false; +// In-process cap for debug.log, in bytes. Default matches the 1G trigger of +// the shipped logrotate policy so a long-running node stays bounded even +// without it; -maxdebugfilesize=N (MB) tunes it, 0 disables. +int64 nMaxDebugFileSize = 1024 * 1024 * (int64)1024; + // --------------------------------------------------------------------------- // Categorized, burst-collapsing logging -- see the LogPrint doc comment in // util.h for the problem this solves. -- cgit v1.2.3 From 2661de141e46dadfb2903bb12e72dc87c5a64375 Mon Sep 17 00:00:00 2001 From: bitflash-maintainer Date: Wed, 2 Sep 2026 05:31:22 +0000 Subject: log: demote the four lines that were 90% of debug.log behind /debugrelay A 13-hour production capture was ~71% "sending: tx", ~16% "Nostr: discovered .btf peer", ~5% "Relaying wtx", and ~43% of raw lines were CBlock/CTransaction dumps -- all already under -debug, which operators run permanently, so -debug was useless as a filter. The category mechanism gains a verbose tier: "relay" and "nostrdiscovery" are accepted only with the new /debugrelay flag (which implies /debug); everything else keeps its current gate. Demoted, with message text unchanged for anyone grepping it: net.h "sending: tx (N bytes)" (BeginMessage/EndMessage/ AbortMessage all pick the category from the command, so no orphaned "(N bytes)" fragments leak into a plain -debug log) main.cpp "Relaying wtx", "received block:" + CBlock::print, and the BitcoinMiner block dump nostr.cpp "Nostr: discovered .btf peer" -> "nostrdiscovery" Pool/worker/payout, [payout], BLOCK ORPHANED/ACCEPTED and share flow lines are untouched. Because LogPrint dedup keys on category, demoted lines also keep their burst collapse under /debugrelay. Closes #35 --- src/main.cpp | 6 +++--- src/main_gui.cpp | 12 ++++++++++++ src/net.h | 22 ++++++++++++++++++---- src/nostr.cpp | 2 +- src/util.cpp | 13 +++++++++++++ src/util.h | 4 ++++ 6 files changed, 51 insertions(+), 8 deletions(-) (limited to 'src/util.cpp') diff --git a/src/main.cpp b/src/main.cpp index 7b3e555..80f5f31 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -1712,7 +1712,7 @@ void CWalletTx::RelayWalletTransaction(CTxDB& txdb) uint256 hash = GetHash(); if (!txdb.ContainsTx(hash)) { - if (LogAcceptsCategory("net")) printf("Relaying wtx %s\n", hash.ToString().substr(0,6).c_str()); + if (LogAcceptsCategory("relay")) printf("Relaying wtx %s\n", hash.ToString().substr(0,6).c_str()); RelayMessage(CInv(MSG_TX, hash), (CTransaction)*this); } } @@ -3263,7 +3263,7 @@ bool ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv) vRecv >> *pblock; //// debug print - if (LogAcceptsCategory("net")) { printf("received block:\n"); pblock->print(); } + if (LogAcceptsCategory("relay")) { printf("received block:\n"); pblock->print(); } CInv inv(MSG_BLOCK, pblock->GetHash()); pfrom->AddInventoryKnown(inv); @@ -4555,7 +4555,7 @@ bool BitcoinMiner(int nThreadId) //// debug print if (LogAcceptsCategory("net")) printf("BitcoinMiner:\n"); if (LogAcceptsCategory("net")) printf("RandomX proof-of-work found \n powhash: %s \ntarget: %s\n", hash.GetHex().c_str(), hashTarget.GetHex().c_str()); - if (LogAcceptsCategory("net")) pblock->print(); + if (LogAcceptsCategory("relay")) pblock->print(); SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_NORMAL); CRITICAL_BLOCK(cs_main) diff --git a/src/main_gui.cpp b/src/main_gui.cpp index 05f5ecf..163d78e 100644 --- a/src/main_gui.cpp +++ b/src/main_gui.cpp @@ -111,6 +111,7 @@ static void PrintUsage() printf(" /help, -help, --help, /?\n"); printf(" /datadir=PATH\n"); printf(" /debug\n"); + printf(" /debugrelay (/debug plus per-message relay chatter and block dumps)\n"); printf(" /maxdebugfilesize=N (roll debug.log at N MB, default 1024; 0 = never)\n"); printf(" /gen\n"); printf(" /nogui or /daemon\n"); @@ -192,6 +193,17 @@ static void ParseStartupArguments(int argc, char* argv[]) if (arg(argc,argv,"/debug") || arg(argc,argv,"-debug")) fDebug = true; + // /debugrelay -- everything /debug shows, plus the per-message firehose + // ("relay" and "nostrdiscovery" categories: sending: tx, Relaying wtx, + // raw CBlock dumps, per-peer discovery lines). That traffic was ~90% of + // a 13-hour production debug.log (issue #35), so plain /debug leaves it + // off; the message text itself is unchanged for anyone grepping it. + if (arg(argc,argv,"/debugrelay") || arg(argc,argv,"-debugrelay")) + { + fDebug = true; + fDebugRelay = true; + } + // /maxdebugfilesize=N -- roll debug.log to debug.log.old once it passes // N MB, checked on each write. Default is 1024 (see util.cpp); 0 turns // the check off and leaves rotation entirely to logrotate. diff --git a/src/net.h b/src/net.h index 9f3c7e4..1aee973 100644 --- a/src/net.h +++ b/src/net.h @@ -802,6 +802,18 @@ public: + // "sending: tx (N bytes)" alone was ~71% of a 13-hour production + // debug.log (issue #35), so tx sends are demoted to the /debugrelay-gated + // "relay" category; every other command's send trace stays on "net". + // The line is emitted in pieces across BeginMessage/EndMessage/ + // AbortMessage, so all three must agree on the category or orphaned + // "(N bytes)" fragments would leak into a plain -debug log. + // Valid only mid-message (nPushPos != -1). + const char* SendLogCategory() const + { + return strcmp(GetMessageCommand(), "tx") == 0 ? "relay" : "net"; + } + void BeginMessage(const char* pszCommand) { EnterCriticalSection(&cs_vSend); @@ -809,17 +821,19 @@ public: AbortMessage(); nPushPos = vSend.size(); vSend << CMessageHeader(pszCommand, 0); - if (LogAcceptsCategory("net")) printf("sending: %-12s ", pszCommand); + if (LogAcceptsCategory(SendLogCategory())) printf("sending: %-12s ", pszCommand); } void AbortMessage() { if (nPushPos == -1) return; + // Capture before nPushPos is cleared; GetMessageCommand() needs it. + const char* pszCategory = SendLogCategory(); vSend.resize(nPushPos); nPushPos = -1; LeaveCriticalSection(&cs_vSend); - if (LogAcceptsCategory("net")) printf("(aborted)\n"); + if (LogAcceptsCategory(pszCategory)) printf("(aborted)\n"); } void EndMessage() @@ -839,10 +853,10 @@ public: unsigned int nSize = vSend.size() - nPushPos - sizeof(CMessageHeader); memcpy((char*)&vSend[nPushPos] + offsetof(CMessageHeader, nMessageSize), &nSize, sizeof(nSize)); - if (LogAcceptsCategory("net")) printf("(%d bytes) ", nSize); + if (LogAcceptsCategory(SendLogCategory())) printf("(%d bytes) ", nSize); //for (int i = nPushPos+sizeof(CMessageHeader); i < min(vSend.size(), nPushPos+sizeof(CMessageHeader)+20U); i++) // printf("%02x ", vSend[i] & 0xff); - if (LogAcceptsCategory("net")) printf("\n"); + if (LogAcceptsCategory(SendLogCategory())) printf("\n"); nPushPos = -1; LeaveCriticalSection(&cs_vSend); diff --git a/src/nostr.cpp b/src/nostr.cpp index e2d839c..9bbf74e 100644 --- a/src/nostr.cpp +++ b/src/nostr.cpp @@ -1440,7 +1440,7 @@ static bool SeedFromRelay(CNostrKey& key, const string& relay) else if (createdAt > it->second) it->second = createdAt; // refresh } if (fNew && fDebug) - LogPrint("nostr", "Nostr: discovered .btf peer %s\n", peerAddr.c_str()); + LogPrint("nostrdiscovery", "Nostr: discovered .btf peer %s\n", peerAddr.c_str()); if (++nPeers > 500) break; } else if (type == "EOSE") diff --git a/src/util.cpp b/src/util.cpp index 52cda84..a5a4e80 100644 --- a/src/util.cpp +++ b/src/util.cpp @@ -7,6 +7,7 @@ bool fDebug = false; +bool fDebugRelay = false; // In-process cap for debug.log, in bytes. Default matches the 1G trigger of // the shipped logrotate policy so a long-running node stays bounded even @@ -31,10 +32,22 @@ static bool LogCategoryDefaultOn(const char* category) strcmp(category, "payout") == 0; } +// Categories so noisy they drown out everything else even under -debug: +// per-message send traces, wallet relay rebroadcasts, raw CBlock dumps and +// per-address discovery lines made up ~90% of a 13-hour production capture +// (issue #35). They need /debugrelay, not merely /debug. +static bool LogCategoryVerboseOnly(const char* category) +{ + return strcmp(category, "relay") == 0 || + strcmp(category, "nostrdiscovery") == 0; +} + bool LogAcceptsCategory(const char* category) { if (LogCategoryDefaultOn(category)) return true; + if (LogCategoryVerboseOnly(category)) + return fDebugRelay; return fDebug; } diff --git a/src/util.h b/src/util.h index f2ea23f..c47b8a7 100644 --- a/src/util.h +++ b/src/util.h @@ -87,6 +87,10 @@ inline T& REF(const T& val) extern bool fDebug; +// /debugrelay: the per-message firehose ("relay" and "nostrdiscovery" +// categories) that even -debug keeps off. See LogAcceptsCategory(). +extern bool fDebugRelay; + // debug.log is rolled to debug.log.old once it grows past this many bytes // (set from -maxdebugfilesize, in MB; 0 disables the check). See the roll // site in OutputDebugStringF() below. -- cgit v1.2.3 From 123ae2e017d90fd18b291db3d76033781c1ead84 Mon Sep 17 00:00:00 2001 From: bitflash-maintainer Date: Wed, 2 Sep 2026 16:36:42 +0000 Subject: log: measure the debug log with a size type that can hold it GetFilesize() returned int while ftell() returns long, so a debug.log of 2 GiB or more came back negative. Its only caller is the -maxdebugfilesize roll added in ae1c6a7, which skips the roll on a negative size: the rotation written for issue #34 would have switched itself off permanently at exactly the size it exists to prevent. Production was at 1.95 GiB growing 51-129 MB/day, about a day short of crossing 2 GiB. The same truncation capped the comparison at INT_MAX (2047.99 MB), so -maxdebugfilesize=2048 or higher could never be exceeded and disabled rotation outright. Both failures were silent. Widen the return to int64 and seek with ftello/fseeko (_ftelli64 and _fseeki64 on Windows). The roll in util.h is the function's only caller in the tree, so no other behaviour changes. A 32-bit off_t would reintroduce the same truncation, so its width is now a compile-time assertion rather than a silent runtime surprise. --- src/util.cpp | 36 ++++++++++++++++++++++++++++++------ src/util.h | 6 +++--- 2 files changed, 33 insertions(+), 9 deletions(-) (limited to 'src/util.cpp') diff --git a/src/util.cpp b/src/util.cpp index a5a4e80..60142be 100644 --- a/src/util.cpp +++ b/src/util.cpp @@ -415,13 +415,37 @@ bool FileExists(const char* psz) #endif } -int GetFilesize(FILE* file) +#ifndef _WIN32 +// If off_t is 32 bits wide, ftello() truncates exactly like the int this +// function used to return. Fail the build rather than ship the silent +// version of the bug (32-bit hosts need -D_FILE_OFFSET_BITS=64). +static_assert(sizeof(off_t) >= 8, "GetFilesize needs a 64-bit off_t"); +#endif + +// Returns the file's size in bytes, or -1 if it cannot be determined. +// +// This used to hold ftell()'s long in an int, so a file of 2 GiB or more came +// back negative. Its only caller is the debug.log roll in util.h, which skips +// the roll on a negative size -- i.e. rotation switched itself off for good at +// exactly the size the roll exists to prevent, and any cap of 2048 MB or more +// could never be exceeded at all. Both failures were silent. +int64 GetFilesize(FILE* file) { - int nSavePos = ftell(file); - int nFilesize = -1; - if (fseek(file, 0, SEEK_END) == 0) - nFilesize = ftell(file); - fseek(file, nSavePos, SEEK_SET); +#ifdef _WIN32 + __int64 nSavePos = _ftelli64(file); + int64 nFilesize = -1; + if (nSavePos >= 0 && _fseeki64(file, 0, SEEK_END) == 0) + nFilesize = _ftelli64(file); + if (nSavePos >= 0) + _fseeki64(file, nSavePos, SEEK_SET); +#else + off_t nSavePos = ftello(file); + int64 nFilesize = -1; + if (nSavePos >= 0 && fseeko(file, 0, SEEK_END) == 0) + nFilesize = ftello(file); + if (nSavePos >= 0) + fseeko(file, nSavePos, SEEK_SET); +#endif return nFilesize; } diff --git a/src/util.h b/src/util.h index c47b8a7..89dce2f 100644 --- a/src/util.h +++ b/src/util.h @@ -154,7 +154,7 @@ void ParseString(const string& str, char c, vector& v); string FormatMoney(int64 n, bool fPlus=false); bool ParseMoney(const char* pszIn, int64& nRet); bool FileExists(const char* psz); -int GetFilesize(FILE* file); +int64 GetFilesize(FILE* file); uint64 GetRand(uint64 nMax); int64 GetTime(); int64 GetAdjustedTime(); @@ -410,8 +410,8 @@ inline int OutputDebugStringF(const char* pszFormat, ...) // so a rename is safe here: the next line simply reopens the // path. One generation is kept as debug.log.old; logrotate // (contrib/logrotate/) handles anything longer-term. - int nSize = GetFilesize(fileout); - if (nSize >= 0 && (int64)nSize > nMaxDebugFileSize) + int64 nSize = GetFilesize(fileout); + if (nSize >= 0 && nSize > nMaxDebugFileSize) { fclose(fileout); string strOldFile = strDebugFile + ".old"; -- cgit v1.2.3