diff options
| author | bitflash-maintainer <noreply@bitflash.invalid> | 2026-09-04 05:59:40 +0000 |
|---|---|---|
| committer | bitflash-maintainer <noreply@bitflash.invalid> | 2026-09-04 05:59:40 +0000 |
| commit | 152c859b18b222a7c11a82b5485110e902267d40 (patch) | |
| tree | 1ceadf421609a2e58da81103165a2fb7085387de /src/util.cpp | |
| parent | e4f898c4a6b9900553c64b9804889b5fdae3e55f (diff) | |
| parent | b810d86752ddb2674118f737582c924bb9eb74c1 (diff) | |
Merge branch 'deploy/all-2026-08-24' into 'deploy/soak-2026-08-21'
deploy: land MRs 1-12 and upstream 1.2.20, as shipped in relay component
See merge request !13
Diffstat (limited to 'src/util.cpp')
| -rw-r--r-- | src/util.cpp | 153 |
1 files changed, 138 insertions, 15 deletions
diff --git a/src/util.cpp b/src/util.cpp index 0cd0133..ab29178 100644 --- a/src/util.cpp +++ b/src/util.cpp | |||
| @@ -7,6 +7,12 @@ | |||
| 7 | 7 | ||
| 8 | 8 | ||
| 9 | bool fDebug = false; | 9 | bool fDebug = false; |
| 10 | bool fDebugRelay = false; | ||
| 11 | |||
| 12 | // In-process cap for debug.log, in bytes. Default matches the 1G trigger of | ||
| 13 | // the shipped logrotate policy so a long-running node stays bounded even | ||
| 14 | // without it; -maxdebugfilesize=N (MB) tunes it, 0 disables. | ||
| 15 | int64 nMaxDebugFileSize = 1024 * 1024 * (int64)1024; | ||
| 10 | 16 | ||
| 11 | // --------------------------------------------------------------------------- | 17 | // --------------------------------------------------------------------------- |
| 12 | // Categorized, burst-collapsing logging -- see the LogPrint doc comment in | 18 | // Categorized, burst-collapsing logging -- see the LogPrint doc comment in |
| @@ -26,10 +32,22 @@ static bool LogCategoryDefaultOn(const char* category) | |||
| 26 | strcmp(category, "payout") == 0; | 32 | strcmp(category, "payout") == 0; |
| 27 | } | 33 | } |
| 28 | 34 | ||
| 35 | // Categories so noisy they drown out everything else even under -debug: | ||
| 36 | // per-message send traces, wallet relay rebroadcasts, raw CBlock dumps and | ||
| 37 | // per-address discovery lines made up ~90% of a 13-hour production capture | ||
| 38 | // (issue #35). They need /debugrelay, not merely /debug. | ||
| 39 | static bool LogCategoryVerboseOnly(const char* category) | ||
| 40 | { | ||
| 41 | return strcmp(category, "relay") == 0 || | ||
| 42 | strcmp(category, "nostrdiscovery") == 0; | ||
| 43 | } | ||
| 44 | |||
| 29 | bool LogAcceptsCategory(const char* category) | 45 | bool LogAcceptsCategory(const char* category) |
| 30 | { | 46 | { |
| 31 | if (LogCategoryDefaultOn(category)) | 47 | if (LogCategoryDefaultOn(category)) |
| 32 | return true; | 48 | return true; |
| 49 | if (LogCategoryVerboseOnly(category)) | ||
| 50 | return fDebugRelay; | ||
| 33 | return fDebug; | 51 | return fDebug; |
| 34 | } | 52 | } |
| 35 | 53 | ||
| @@ -47,6 +65,61 @@ struct LogDedupState { | |||
| 47 | static std::map<std::string, LogDedupState> g_logDedup; | 65 | static std::map<std::string, LogDedupState> g_logDedup; |
| 48 | static CCriticalSection cs_logDedup; | 66 | static CCriticalSection cs_logDedup; |
| 49 | 67 | ||
| 68 | // A pending "(N similar)" summary, lifted out of the table while the lock is | ||
| 69 | // held and written after it is released. | ||
| 70 | struct LogDedupFlush { | ||
| 71 | std::string category; | ||
| 72 | int suppressed; | ||
| 73 | int64 elapsed; // how long the window that counted them ran | ||
| 74 | std::string lastMsg; | ||
| 75 | }; | ||
| 76 | |||
| 77 | static int64 g_logDedupLastSweep = 0; | ||
| 78 | |||
| 79 | static void EmitDedupSummary(const LogDedupFlush& f) | ||
| 80 | { | ||
| 81 | OutputDebugStringF("[%s] (%d similar in %llds, last: %s)\n", | ||
| 82 | f.category.c_str(), f.suppressed, | ||
| 83 | (long long)f.elapsed, f.lastMsg.c_str()); | ||
| 84 | } | ||
| 85 | |||
| 86 | // A window is otherwise only closed out when its own call site fires again, so | ||
| 87 | // a burst that simply stops -- 100 ledger entries voided in one pass and then | ||
| 88 | // silence -- leaves its count sitting in the table and the summary is never | ||
| 89 | // written at all. That is how 99 of 100 voids went unreported, with no "(N | ||
| 90 | // similar)" line to say anything was missing (issue #3). Sweep every expired | ||
| 91 | // window instead, so a finished burst is summarised as soon as anything at all | ||
| 92 | // is logged. | ||
| 93 | // | ||
| 94 | // Expired entries are erased rather than reopened: the window is over, so there | ||
| 95 | // is no state left worth keeping, and the next call from that site then takes | ||
| 96 | // the "first time" path and prints directly -- exactly what the rollover branch | ||
| 97 | // below would have done. It also stops the table growing without bound. | ||
| 98 | // | ||
| 99 | // Caller holds cs_logDedup; the summaries are written after it is released. | ||
| 100 | static void SweepExpiredWindowsLocked(int64 now, std::vector<LogDedupFlush>& out) | ||
| 101 | { | ||
| 102 | for (std::map<std::string, LogDedupState>::iterator it = g_logDedup.begin(); | ||
| 103 | it != g_logDedup.end(); ) | ||
| 104 | { | ||
| 105 | if (now - it->second.windowStart < DEDUP_WINDOW_SECS) | ||
| 106 | { | ||
| 107 | ++it; | ||
| 108 | continue; | ||
| 109 | } | ||
| 110 | if (it->second.suppressed > 0) | ||
| 111 | { | ||
| 112 | LogDedupFlush f; | ||
| 113 | f.category = it->first.substr(0, it->first.find('|')); | ||
| 114 | f.suppressed = it->second.suppressed; | ||
| 115 | f.elapsed = now - it->second.windowStart; | ||
| 116 | f.lastMsg = it->second.lastMsg; | ||
| 117 | out.push_back(f); | ||
| 118 | } | ||
| 119 | g_logDedup.erase(it++); | ||
| 120 | } | ||
| 121 | } | ||
| 122 | |||
| 50 | void LogPrintDedup(const char* category, const char* file, int line, const std::string& msgIn) | 123 | void LogPrintDedup(const char* category, const char* file, int line, const std::string& msgIn) |
| 51 | { | 124 | { |
| 52 | // Call sites follow the existing printf() convention of ending their | 125 | // Call sites follow the existing printf() convention of ending their |
| @@ -61,11 +134,19 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 61 | 134 | ||
| 62 | int64 now = GetTime(); | 135 | int64 now = GetTime(); |
| 63 | bool fEmitNow = false; | 136 | bool fEmitNow = false; |
| 64 | int suppressedToFlush = 0; | 137 | std::vector<LogDedupFlush> flushes; |
| 65 | std::string flushedMsg; | ||
| 66 | 138 | ||
| 67 | CRITICAL_BLOCK(cs_logDedup) | 139 | CRITICAL_BLOCK(cs_logDedup) |
| 68 | { | 140 | { |
| 141 | // At most once a second. The table holds one entry per call site that | ||
| 142 | // has fired in the last few seconds, so the walk is short, but it must | ||
| 143 | // not run once per line of a burst. | ||
| 144 | if (now != g_logDedupLastSweep) | ||
| 145 | { | ||
| 146 | g_logDedupLastSweep = now; | ||
| 147 | SweepExpiredWindowsLocked(now, flushes); | ||
| 148 | } | ||
| 149 | |||
| 69 | std::map<std::string, LogDedupState>::iterator it = g_logDedup.find(key); | 150 | std::map<std::string, LogDedupState>::iterator it = g_logDedup.find(key); |
| 70 | if (it == g_logDedup.end()) | 151 | if (it == g_logDedup.end()) |
| 71 | { | 152 | { |
| @@ -76,10 +157,18 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 76 | } | 157 | } |
| 77 | else if (now - it->second.windowStart >= DEDUP_WINDOW_SECS) | 158 | else if (now - it->second.windowStart >= DEDUP_WINDOW_SECS) |
| 78 | { | 159 | { |
| 79 | // Window rolled over: flush what was suppressed during it (if | 160 | // Window rolled over within the same second as the last sweep: |
| 80 | // anything), then start a new window with this call printed. | 161 | // flush what was suppressed during it (if anything), then start a |
| 81 | suppressedToFlush = it->second.suppressed; | 162 | // new window with this call printed. |
| 82 | flushedMsg = it->second.lastMsg; | 163 | if (it->second.suppressed > 0) |
| 164 | { | ||
| 165 | LogDedupFlush f; | ||
| 166 | f.category = category; | ||
| 167 | f.suppressed = it->second.suppressed; | ||
| 168 | f.elapsed = now - it->second.windowStart; | ||
| 169 | f.lastMsg = it->second.lastMsg; | ||
| 170 | flushes.push_back(f); | ||
| 171 | } | ||
| 83 | it->second.windowStart = now; | 172 | it->second.windowStart = now; |
| 84 | it->second.suppressed = 0; | 173 | it->second.suppressed = 0; |
| 85 | it->second.lastMsg = msg; | 174 | it->second.lastMsg = msg; |
| @@ -94,13 +183,23 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 94 | } | 183 | } |
| 95 | } | 184 | } |
| 96 | 185 | ||
| 97 | if (suppressedToFlush > 0) | 186 | for (size_t i = 0; i < flushes.size(); i++) |
| 98 | OutputDebugStringF("[%s] (%d similar in %llds, last: %s)\n", | 187 | EmitDedupSummary(flushes[i]); |
| 99 | category, suppressedToFlush, (long long)DEDUP_WINDOW_SECS, flushedMsg.c_str()); | ||
| 100 | if (fEmitNow) | 188 | if (fEmitNow) |
| 101 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); | 189 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); |
| 102 | } | 190 | } |
| 103 | 191 | ||
| 192 | // LogPrintAlways() -- see the doc comment in util.h. No window, no counting, | ||
| 193 | // no table entry: every call writes its own line. | ||
| 194 | void LogPrintNoCollapse(const char* category, const std::string& msgIn) | ||
| 195 | { | ||
| 196 | std::string msg = msgIn; | ||
| 197 | while (!msg.empty() && (msg.back() == '\n' || msg.back() == '\r')) | ||
| 198 | msg.pop_back(); | ||
| 199 | |||
| 200 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); | ||
| 201 | } | ||
| 202 | |||
| 104 | 203 | ||
| 105 | 204 | ||
| 106 | 205 | ||
| @@ -397,13 +496,37 @@ bool FileExists(const char* psz) | |||
| 397 | #endif | 496 | #endif |
| 398 | } | 497 | } |
| 399 | 498 | ||
| 400 | int GetFilesize(FILE* file) | 499 | #ifndef _WIN32 |
| 500 | // If off_t is 32 bits wide, ftello() truncates exactly like the int this | ||
| 501 | // function used to return. Fail the build rather than ship the silent | ||
| 502 | // version of the bug (32-bit hosts need -D_FILE_OFFSET_BITS=64). | ||
| 503 | static_assert(sizeof(off_t) >= 8, "GetFilesize needs a 64-bit off_t"); | ||
| 504 | #endif | ||
| 505 | |||
| 506 | // Returns the file's size in bytes, or -1 if it cannot be determined. | ||
| 507 | // | ||
| 508 | // This used to hold ftell()'s long in an int, so a file of 2 GiB or more came | ||
| 509 | // back negative. Its only caller is the debug.log roll in util.h, which skips | ||
| 510 | // the roll on a negative size -- i.e. rotation switched itself off for good at | ||
| 511 | // exactly the size the roll exists to prevent, and any cap of 2048 MB or more | ||
| 512 | // could never be exceeded at all. Both failures were silent. | ||
| 513 | int64 GetFilesize(FILE* file) | ||
| 401 | { | 514 | { |
| 402 | int nSavePos = ftell(file); | 515 | #ifdef _WIN32 |
| 403 | int nFilesize = -1; | 516 | __int64 nSavePos = _ftelli64(file); |
| 404 | if (fseek(file, 0, SEEK_END) == 0) | 517 | int64 nFilesize = -1; |
| 405 | nFilesize = ftell(file); | 518 | if (nSavePos >= 0 && _fseeki64(file, 0, SEEK_END) == 0) |
| 406 | fseek(file, nSavePos, SEEK_SET); | 519 | nFilesize = _ftelli64(file); |
| 520 | if (nSavePos >= 0) | ||
| 521 | _fseeki64(file, nSavePos, SEEK_SET); | ||
| 522 | #else | ||
| 523 | off_t nSavePos = ftello(file); | ||
| 524 | int64 nFilesize = -1; | ||
| 525 | if (nSavePos >= 0 && fseeko(file, 0, SEEK_END) == 0) | ||
| 526 | nFilesize = ftello(file); | ||
| 527 | if (nSavePos >= 0) | ||
| 528 | fseeko(file, nSavePos, SEEK_SET); | ||
| 529 | #endif | ||
| 407 | return nFilesize; | 530 | return nFilesize; |
| 408 | } | 531 | } |
| 409 | 532 | ||