util: Log early messages

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

DrahtBot added the label Tests on May 28, 2019

DrahtBot added the label Utils/log/libs on May 28, 2019

MarcoFalke removed the label Tests on May 28, 2019

MarcoFalke force-pushed on May 28, 2019

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",

promag commented at 1:29 pm on May 28, 2019:

https://github.com/bitcoin/bitcoin/pull/16112/commits/2b0f4e1726379150fd3fc1e3f7bc127303ad850b

nit, could fix indentation.

MarcoFalke commented at 10:03 pm on June 17, 2019:

Leaving it to minimize the diff

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.~~

MarcoFalke force-pushed on May 28, 2019

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.

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

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

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?

DrahtBot commented at 3:56 pm on May 28, 2019: member

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

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.

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

hebasto commented at 3:59 pm on May 28, 2019: member

Concept ACK.

Replace OpenDebugLog() with StartLogging()

StartLogging() is used to mark the start of logging generically, whether
using -printtoconsole or -debuglogfile.

412987430c

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

logging: Add threadsafety comments faa2a47cd7

MarcoFalke force-pushed on May 28, 2019

sipa commented at 8:08 pm on May 28, 2019: member

Concept ACK

MarcoFalke force-pushed on May 29, 2019

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)?

ajtowns commented at 1:37 am on May 31, 2019: member

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.

ajtowns commented at 2:07 am on May 31, 2019: member

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…

ajtowns commented at 2:52 am on May 31, 2019: member

utACK faa2a47cd7bcdbd187035c76f8dbd0442f6818dc

MarcoFalke renamed this:
~~log: Log early messages~~
util: Log early messages
on Jun 11, 2019

kristapsk approved

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)

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)?

MarcoFalke commented at 10:01 pm on June 17, 2019: member

@practicalswift See #16112 (comment)

MarcoFalke commented at 10:03 pm on June 17, 2019: member

Unless there are objections, this will be merged tomorrow

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.

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:

 0$ cat ~/.bitcoin/bitcoin.conf
 1trash=1
 2
 3$ src/qt/bitcoin-qt -noonion=0
 4
 5$ head ~/.bitcoin/debug.log 
 6
 7
 8
 9
10
112019-06-18T14:40:23Z Warning: parsed potentially confusing double-negative -onion=0
122019-06-18T14:40:23Z Ignoring unknown configuration value trash
132019-06-18T14:40:23Z Bitcoin Core version v0.18.99.0-10ae3a70e (release build)
142019-06-18T14:40:23Z GUI: QObject::connect: invalid null parameter
152019-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?

MarcoFalke merged this on Jun 18, 2019

MarcoFalke closed this on Jun 18, 2019

MarcoFalke referenced this in commit 0853d8d2fd on Jun 18, 2019

MarcoFalke deleted the branch on Jun 18, 2019

sidhujag referenced this in commit 6347640464 on Jun 19, 2019

deadalnix referenced this in commit d0af7ae7df on Mar 26, 2020

MarcoFalke referenced this in commit 55b4c65bd1 on May 27, 2020

sidhujag referenced this in commit 7924b5fb3e on May 28, 2020

kittywhiskers referenced this in commit 11226425a5 on Jun 5, 2021

kittywhiskers referenced this in commit ff6feaedc8 on Jun 6, 2021

kittywhiskers referenced this in commit 3b38165f85 on Jun 6, 2021

kittywhiskers referenced this in commit 8863abf6d7 on Jun 6, 2021

UdjinM6 referenced this in commit ec35812be5 on Jun 6, 2021

kittywhiskers referenced this in commit 002e5ba26d on Jun 7, 2021

kittywhiskers referenced this in commit 8bc1cae8e2 on Jun 8, 2021

UdjinM6 referenced this in commit a8aee57447 on Jun 11, 2021

DrahtBot locked this on Dec 16, 2021

util: Log early messages #16112

Conflicts