util: Log early messages #16112

pull MarcoFalke wants to merge 3 commits into bitcoin:master from MarcoFalke:1905-bufferLog changing 4 files +63 −41
  1. MarcoFalke commented at 12:36 PM on May 28, 2019: member

    Early log messages are dropped on the floor and they'd never make it to the console or debug log. This can be tested by running the test included in this pull request without re-compiling the bitcoind.

    Fix that by buffering early messages and flushing them as soon as all logging options have been initialized and logging has been started.

    This pull request is identical to "Log early messages with -printtoconsole" (#13088) by ajtowns, with the following changes:

    • Rebased
    • Added docstrings for m_buffering and StartLogging
    • Switch CCriticalSection (aka RecursiveMutex) to just Mutex in the last commit
    • Added tests

    Fixes #16098 Fixes #13157 Closes #13088

  2. DrahtBot added the label Tests on May 28, 2019
  3. DrahtBot added the label Utils/log/libs on May 28, 2019
  4. MarcoFalke removed the label Tests on May 28, 2019
  5. MarcoFalke force-pushed on May 28, 2019
  6. MarcoFalke force-pushed on May 28, 2019
  7. in src/init.cpp:1248 in 2b0f4e1726 outdated 
    1248 | @@ -1249,10 +1249,10 @@ bool AppInitMain(InitInterfaces& interfaces)
1249 |              // and because this needs to happen before any other debug.log printing
1250 |              LogInstance().ShrinkDebugFile();
1251 |          }
1252 | -        if (!LogInstance().OpenDebugLog()) {
1253 | +    }
1254 | +    if (!LogInstance().StartLogging()) {
1255 |              return InitError(strprintf("Could not open debug log file %s",
    MarcoFalke commented at 10:03 PM on June 17, 2019:

    Leaving it to minimize the diff

  8. promag commented at 1:40 PM on May 28, 2019: member

    Tested ACK https://github.com/bitcoin/bitcoin/pull/16112/commits/fa9bc80718b21719452144d63e7c3f7258b06494, I don't see a problem regarding the new circular dependency.

  9. MarcoFalke force-pushed on May 28, 2019
  10. MarcoFalke force-pushed on May 28, 2019
  11. MarcoFalke force-pushed on May 28, 2019
  12. MarcoFalke force-pushed on May 28, 2019
  13. MarcoFalke commented at 2:38 PM on May 28, 2019: member

    I don't see a problem regarding the new circular dependency.

    It would lead to issues in debug builds when a potential deadlock was detected, so I've reverted that for now.

  14. MarcoFalke cross-referenced this on May 28, 2019 from issue test: Handle timestamps without microseconds in combine_logs by laanwj
  15. in src/init.cpp:1246 in faaba72237 outdated 
    1242 | @@ -1249,10 +1243,10 @@ bool AppInitMain(InitInterfaces& interfaces)
1243 |              // and because this needs to happen before any other debug.log printing
1244 |              LogInstance().ShrinkDebugFile();
1245 |          }
1246 | -        if (!LogInstance().OpenDebugLog()) {
1247 | -            return InitError(strprintf("Could not open debug log file %s",
1248 | +    }
    hebasto commented at 3:44 PM on May 28, 2019:

    Two ifs above could be combined now.

    MarcoFalke commented at 10:02 PM on June 17, 2019:

    Leaving it to minimize the diff

  16. in src/logging.cpp:230 in faaba72237 outdated 
     228 | @@ -214,32 +229,31 @@ void BCLog::Logger::LogPrintStr(const std::string &str)
 229 |  
 230 |      m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
    hebasto commented at 3:50 PM on May 28, 2019:

    May I suggest to replace str[str.size()-1] with str.back()?

    MarcoFalke commented at 10:02 PM on June 17, 2019:

    Leaving it to minimize the diff

  17. in src/test/setup_common.cpp:50 in faaba72237 outdated 
      48 | +    static bool g_have_singletons_initialized = false;
  49 | +    if (!g_have_singletons_initialized) {
  50 | +        LogInstance().StartLogging();
  51 |          noui_connect();
  52 | -        noui_connected = true;
  53 | +        g_have_singletons_initialized = true;
    hebasto commented at 3:54 PM on May 28, 2019:

    If we mean singleton, could it be in singular?

  18. DrahtBot commented at 3:56 PM on May 28, 2019: contributor

    <!--e57a25ab6845829454e8d69fc972939a-->

    The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

    <!--174a7506f384e20aa4161008e828411d-->

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #16224 (gui: Bilingual GUI error messages by hebasto)
    • #16115 (On bitcoind startup, write config args to debug.log by LarryRuane)

    If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

  19. in src/init.cpp:1248 in faaba72237 outdated 
    1242 | @@ -1249,10 +1243,10 @@ bool AppInitMain(InitInterfaces& interfaces)
1243 |              // and because this needs to happen before any other debug.log printing
1244 |              LogInstance().ShrinkDebugFile();
1245 |          }
1246 | -        if (!LogInstance().OpenDebugLog()) {
1247 | -            return InitError(strprintf("Could not open debug log file %s",
1248 | +    }
1249 | +    if (!LogInstance().StartLogging()) {
1250 | +        return InitError(strprintf("Could not open debug log file %s",
    hebasto commented at 3:58 PM on May 28, 2019:

    Could this message be translated? Ref: Translation Strings Policy

    MarcoFalke commented at 10:02 PM on June 17, 2019:

    Leaving it to minimize the diff

  20. hebasto commented at 3:59 PM on May 28, 2019: member

    Concept ACK.

  21. Replace OpenDebugLog() with StartLogging()
    StartLogging() is used to mark the start of logging generically, whether
using -printtoconsole or -debuglogfile.
    412987430c
  22. Log early messages with -printtoconsole
    This ensures log messages prior to StartLogging() are replayed to
the console as well as to the debug log file.
    0b282f9b00
  23. logging: Add threadsafety comments faa2a47cd7
  24. MarcoFalke force-pushed on May 28, 2019
  25. sipa commented at 8:08 PM on May 28, 2019: member

    Concept ACK

  26. MarcoFalke force-pushed on May 29, 2019
  27. ajtowns cross-referenced this on May 29, 2019 from issue Log early messages with -printtoconsole by ajtowns
  28. practicalswift commented at 7:23 AM on May 29, 2019: contributor

    Is there any reason to buffer the writing to stdout (m_print_to_console)?

  29. ajtowns commented at 1:37 AM on May 31, 2019: contributor

    Is there any reason to buffer the writing to stdout (m_print_to_console)?

    If you have bitcoind -noconnect=0 but have printtoconsole=0 in bitcoind.conf, then the "confusing double-negative" error will be queued when parsing the command line, but m_print_to_console can't be set to false until later when the config file is actually read.

  30. ajtowns cross-referenced this on May 31, 2019 from issue More thread safety annotation coverage by ajtowns
  31. ajtowns commented at 2:07 AM on May 31, 2019: contributor

    I've done #16127 to see what it would take to keep the thread safety annotations without the dependency loop (and hopefully also without the bugs), and what it'd look like to do the same thing elsewhere. Seems better to do that later (or not at all) than to add it to this PR to me...

  32. ajtowns commented at 2:52 AM on May 31, 2019: contributor

    utACK faa2a47cd7bcdbd187035c76f8dbd0442f6818dc

  33. MarcoFalke renamed this:
    log: Log early messages
    util: Log early messages
    on Jun 11, 2019
  34. kristapsk approved
  35. kristapsk commented at 11:44 PM on June 11, 2019: contributor

    ACK faa2a47cd7bcdbd187035c76f8dbd0442f6818dc (ran added functional test before / after recompiling, didn't do additional testing)

  36. practicalswift commented at 7:16 AM on June 12, 2019: contributor

    @MarcoFalke, why buffer also the writing to stdout? Don't we want to print to stdout as soon as possible to be on the safe side? I think it makes sense to keep the "print to console" code path as simple/dumb as possible. Especially given the amount of trouble we've had with getting "just-after-process-launch-logging" working robustly :-)

    Is there any reason to buffer the writing to stdout (m_print_to_console)?

  37. MarcoFalke commented at 10:01 PM on June 17, 2019: member

    @practicalswift See #16112 (comment)

  38. MarcoFalke commented at 10:03 PM on June 17, 2019: member

    Unless there are objections, this will be merged tomorrow

  39. hebasto commented at 10:16 AM on June 18, 2019: member

    Unless there are objections, this will be merged tomorrow

    Going to test in a few hours.

  40. hebasto commented at 2:47 PM on June 18, 2019: member

    ACK faa2a47cd7bcdbd187035c76f8dbd0442f6818dc

    Tested on Linux Mint 19.1:

    • the patched test/functional/feature_config_args.py fails on master (22b6c4ed7562a23e4363e8f0fd889b92c7653d5f)
    • #16098 is fixed:
    $ cat ~/.bitcoin/bitcoin.conf
trash=1

$ src/qt/bitcoin-qt -noonion=0

$ head ~/.bitcoin/debug.log 





2019-06-18T14:40:23Z Warning: parsed potentially confusing double-negative -onion=0
2019-06-18T14:40:23Z Ignoring unknown configuration value trash
2019-06-18T14:40:23Z Bitcoin Core version v0.18.99.0-10ae3a70e (release build)
2019-06-18T14:40:23Z GUI: QObject::connect: invalid null parameter
2019-06-18T14:40:23Z Assuming ancestors of block 0000000000000000000f1c54590ee18d15ec70e68c8cd4cfbadb1b4f11697eee have valid signatures.

    Nit: could the test for https://github.com/bitcoin/bitcoin/blob/8ab4f282c06d67074b872dbda0be37636fdd5186/src/util/system.cpp#L864 be added?

  41. MarcoFalke merged this on Jun 18, 2019
  42. MarcoFalke closed this on Jun 18, 2019
  43. MarcoFalke referenced this in commit 0853d8d2fd on Jun 18, 2019
  44. MarcoFalke deleted the branch on Jun 18, 2019
  45. MarcoFalke cross-referenced this on Jun 18, 2019 from issue test: Add test for unknown args by MarcoFalke
  46. sidhujag referenced this in commit 6347640464 on Jun 19, 2019
  47. deadalnix referenced this in commit d0af7ae7df on Mar 26, 2020
  48. MarcoFalke referenced this in commit 55b4c65bd1 on May 27, 2020
  49. sidhujag referenced this in commit 7924b5fb3e on May 28, 2020
  50. kwvg referenced this in commit 11226425a5 on Jun 5, 2021
  51. kwvg cross-referenced this on Jun 5, 2021 from issue merge #11640, #11599, #16112, #16127, #18635, #19249: thread safety and locking improvements by kwvg
  52. kwvg referenced this in commit ff6feaedc8 on Jun 6, 2021
  53. kwvg referenced this in commit 3b38165f85 on Jun 6, 2021
  54. kwvg referenced this in commit 8863abf6d7 on Jun 6, 2021
  55. UdjinM6 referenced this in commit ec35812be5 on Jun 6, 2021
  56. kwvg referenced this in commit 002e5ba26d on Jun 7, 2021
  57. kwvg referenced this in commit 8bc1cae8e2 on Jun 8, 2021
  58. UdjinM6 referenced this in commit a8aee57447 on Jun 11, 2021
  59. bitcoin locked this on Dec 16, 2021
Contributors
MarcoFalkepromaghebastoDrahtBotsipapracticalswiftajtownskristapsk
Labels
Utils/log/libs
Linked (view graph)
#13088 Log early messages with -printtoconsole#13157 test: Handle timestamps without microseconds in combine_logs#16098 LogPrintf() fails due to premature call before InitLogging()#16127 More thread safety annotation coverage#16234 test: Add test for unknown args#26781 Release `LockData::dd_mutex` before calling `*_detected` functions
github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-05-19 06:54 UTC