diff options
Diffstat (limited to 'src/util.cpp')
| -rw-r--r-- | src/util.cpp | 176 |
1 files changed, 151 insertions, 25 deletions
diff --git a/src/util.cpp b/src/util.cpp index d52ca88..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 | ||
| @@ -337,7 +436,7 @@ string FormatMoney(int64 n, bool fPlus) | |||
| 337 | bool ParseMoney(const char* pszIn, int64& nRet) | 436 | bool ParseMoney(const char* pszIn, int64& nRet) |
| 338 | { | 437 | { |
| 339 | string strWhole; | 438 | string strWhole; |
| 340 | int64 nCents = 0; | 439 | int64 nUnits = 0; // fractional part, scaled to COIN (8 decimals) |
| 341 | const char* p = pszIn; | 440 | const char* p = pszIn; |
| 342 | while (isspace(*p)) | 441 | while (isspace(*p)) |
| 343 | p++; | 442 | p++; |
| @@ -348,12 +447,16 @@ bool ParseMoney(const char* pszIn, int64& nRet) | |||
| 348 | if (*p == '.') | 447 | if (*p == '.') |
| 349 | { | 448 | { |
| 350 | p++; | 449 | p++; |
| 351 | if (!isdigit(p[0]) || !isdigit(p[1])) | 450 | int64 nMult = COIN / 10; // weight of the first decimal digit |
| 352 | return false; | 451 | while (isdigit(*p) && nMult > 0) |
| 353 | nCents = atoi64(p); | 452 | { |
| 354 | if (nCents < 0 || nCents > 99) | 453 | nUnits += nMult * (*p - '0'); |
| 454 | nMult /= 10; | ||
| 455 | p++; | ||
| 456 | } | ||
| 457 | // reject more than 8 fractional digits rather than silently truncate | ||
| 458 | if (isdigit(*p)) | ||
| 355 | return false; | 459 | return false; |
| 356 | p += 2; | ||
| 357 | break; | 460 | break; |
| 358 | } | 461 | } |
| 359 | if (isspace(*p)) | 462 | if (isspace(*p)) |
| @@ -365,13 +468,12 @@ bool ParseMoney(const char* pszIn, int64& nRet) | |||
| 365 | for (; *p; p++) | 468 | for (; *p; p++) |
| 366 | if (!isspace(*p)) | 469 | if (!isspace(*p)) |
| 367 | return false; | 470 | return false; |
| 368 | if (strWhole.size() > 17) | 471 | if (strWhole.size() > 10) // 10 whole digits * COIN stays within int64 |
| 369 | return false; | 472 | return false; |
| 370 | int64 nWhole = atoi64(strWhole); | 473 | int64 nWhole = atoi64(strWhole); |
| 371 | int64 nValue = nWhole * 100 + nCents; | 474 | int64 nValue = nWhole * COIN + nUnits; |
| 372 | if (nValue / 100 != nWhole) | 475 | if (nValue < 0 || (nValue - nUnits) / COIN != nWhole) |
| 373 | return false; | 476 | return false; |
| 374 | nValue *= CENT; | ||
| 375 | nRet = nValue; | 477 | nRet = nValue; |
| 376 | return true; | 478 | return true; |
| 377 | } | 479 | } |
| @@ -394,13 +496,37 @@ bool FileExists(const char* psz) | |||
| 394 | #endif | 496 | #endif |
| 395 | } | 497 | } |
| 396 | 498 | ||
| 397 | 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) | ||
| 398 | { | 514 | { |
| 399 | int nSavePos = ftell(file); | 515 | #ifdef _WIN32 |
| 400 | int nFilesize = -1; | 516 | __int64 nSavePos = _ftelli64(file); |
| 401 | if (fseek(file, 0, SEEK_END) == 0) | 517 | int64 nFilesize = -1; |
| 402 | nFilesize = ftell(file); | 518 | if (nSavePos >= 0 && _fseeki64(file, 0, SEEK_END) == 0) |
| 403 | 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 | ||
| 404 | return nFilesize; | 530 | return nFilesize; |
| 405 | } | 531 | } |
| 406 | 532 | ||