Smarter default behavior for -printtoconsole

eklitzke commented at 10:17 pm on March 14, 2018: contributor

This makes console printing smarter when -printtoconsole is not explicitly set. The new behavior:

The series of newline separators that we send to the log when starting up are only sent to debug.log, never to stdout.
Logging to stdout is set up by default when the process is not a daemon.

The motivation for this change is that I almost always run bitcoind in foreground mode when I’m debugging or doing development work, and the new behavior makes checking log statements a lot easier in that situation. I think these semantics are also more similar to the default behavior of many other Unix programs.

fanquake added the label Utils/log/libs on Mar 14, 2018

Sjors commented at 10:32 pm on March 14, 2018: member

Concept ACK. Tested on macOS.

Needs update for -printtoconsole help text.

in src/util.cpp:341 in 92059163e8 outdated

335@@ -336,6 +336,11 @@ static std::string LogTimestampStr(const std::string &str, std::atomic_bool *fSt
336     return strStamped;
337 }
338 
339+bool IsStdoutTty()
340+{
341+    return isatty(STDOUT_FILENO);

donaloconnor commented at 10:39 pm on March 14, 2018:

I know you said that MingW includes a compatible unistd.h version for Windows but on Visual Studio/msvc isatty is deprecated and replaced by _isatty. Also STDOUT_FILENO (1) is not defined. There’s currently some PRs for msvc support so just a heads up that this will likely break things there. #11526 and #11873

practicalswift commented at 10:56 pm on March 14, 2018: contributor

Strong concept ACK. Very nice usability improvement! I’m also running bitcoind in the foreground mode for the most part.

What about reducing the number of \n:s from 20 to say 5? That should be more than enough to distinguish between to subsequent executions.

donaloconnor commented at 11:05 pm on March 14, 2018: contributor

Just a few concerns (Mainly on Windows)

There’s now no way of turning the stdout logging off when launched in foreground. It’s either on or (on by default)
On Windows output will always be shown now since deamonising isn’t possible?. (AFAIK it’s not possible to run bitcoind as a windows service?
stdout isn’t buffered very well (if at all?) so it can potentially have a perf penalty (especially if custom high freq custom logging is enabled)

BTW fPrintToDebugLog is set to true and not changed ever so the code can be simplified.

promag commented at 11:08 pm on March 14, 2018: member

Concept ACK, cool :+1:.

eklitzke commented at 11:22 pm on March 14, 2018: contributor

Now that I’ve thought about this more I don’t think the isatty() check is necessary. The situation where it wouldn’t be a TTY would be if you were running commands like:

0# stdout is a pipe, not a TTY.
1bitcoind | less
2
3# stdout is a file, not a TTY.
4bitcoind > redundantcopyofdebug.log

I don’t think either of these are things people are going to actually run, but if they did they would probably expect to see output printed. The usual use of isatty() is actually to test for features like using console escape sequences (e.g. the ASCII “bell” character) or to tell if it makes sense to print ANSI color codes.

eklitzke force-pushed on Mar 14, 2018

eklitzke commented at 11:32 pm on March 14, 2018: contributor

New version (with squashed commit) removes the isatty() check and reduces the number of newlines we print from 20 to 5. I’ve also updated the PR description to remove the commentary about isatty().

donaloconnor commented at 0:30 am on March 15, 2018: contributor

My understanding is now logging will not be sent to the log file unless -daemon is passed via command line. If that’s the case won’t this be unexpected and annoying behavior?

LogPrintStr only prints to one or the other.

I’m on the phone so it’s difficult to check

luke-jr commented at 0:40 am on March 15, 2018: member

Not sure this makes sense. I don’t know of any other software that guesses stdout vs log based on whether stdout is a tty. It seems likely to break users who do bitcoin-qt &

Why not just put printtoconsole=1 in bitcoin.conf if you prefer it by default?

eklitzke commented at 1:35 am on March 15, 2018: contributor

@lukejr The code no longer uses isatty(), I removed that code. Adding printtoconsole=1 to bitcoin.conf has the side effect that it completely suppresses logging to debug.log, which is annoying if sometimes you run bitcoin as a daemon and sometimes you run it in foreground mode.

We should probably change the LogPrintf() logic to log to both if both flags are set. But even in that case if you add printtoconsole=1 to your bitcoin.conf file you’ll get behavior where bitcoind would log all messages twice, with the stdout one going to /dev/null. This is harmless but inefficient.

eklitzke commented at 1:38 am on March 15, 2018: contributor

@donaloconnor I also just noticed that which I think is bad behavior. Updated to make these flags independent (printing to console will not affect logging to debug.log).

randolf approved

practicalswift commented at 6:46 am on March 15, 2018: contributor

utACK 23bc0aaac8d8ac7f2b41527567d6a2329429d172

in src/util.cpp:352 in 23bc0aaac8 outdated

348@@ -349,7 +349,7 @@ int LogPrintStr(const std::string &str)
349         ret = fwrite(strTimestamped.data(), 1, strTimestamped.size(), stdout);
350         fflush(stdout);
351     }
352-    else if (fPrintToDebugLog)
353+    if (fPrintToDebugLog)

laanwj commented at 3:50 pm on March 15, 2018:

I’m fine with making these non-exclusive, however we still need a way to disable logging to debug.log. Some logging setups (e.g. when using systemd) process the -printtoconsole output, and don’t need a duplicate logging to disk. Maybe -nodebuglogfile?

Sjors commented at 3:56 pm on March 15, 2018:

Maybe -debuglogfile=0 as a special case?

Sjors commented at 4:00 pm on March 15, 2018:

Nit: move brackets to same line?

practicalswift commented at 11:03 pm on March 15, 2018:

What about -debuglogfile=/dev/null as a special case .-)

If we are to add a separate option, then perhaps something starting with -disable to make it consistent with -disablewallet? We don’t have any bitcoind command-line options starting with -no AFAIK.

Also -nodebuglogfile can be parsed as “node bug logfile” :-)

meshcollider commented at 11:15 pm on March 17, 2018:

Actually -noX is interpreted by the args manager as -X=0 implicitly anyway, converted by the InterpretNegativeSetting() function. So @laanwj and @Sjors suggestions are equivalent :) EDIT: just saw further conversation, this was pointed out

Sjors commented at 3:53 pm on March 15, 2018: member

Tested 23bc0aa on macOS, still works.

Removing the isatty() check makes sense; another example would be using bitcoind | grep the_thing_I_care_about. @luke-jr bitcoin-qt does not output anything to the console (not sure why).

in src/init.cpp:818 in 23bc0aaac8 outdated

835 {
836-    fPrintToConsole = gArgs.GetBoolArg("-printtoconsole", false);
837+    // Add newlines to the logfile to distinguish this execution from the last
838+    // one; called before console logging is set up, so this is only sent to
839+    // debug.log.
840+    LogPrintf("\n\n\n\n\n");

Sjors commented at 3:58 pm on March 15, 2018:

std::string(NUMBER_OF_BLANK_LINES_BETWEEN_SESSIONS_IN_LOG_TO_PREEMPT_BIKESHEDDING, '\n')? :-P

practicalswift commented at 4:08 pm on March 15, 2018: contributor

utACK 23bc0aaac8d8ac7f2b41527567d6a2329429d172 modulo @Sjors’ nits :-)

donaloconnor commented at 7:34 pm on March 15, 2018: contributor

utACK https://github.com/bitcoin/bitcoin/commit/23bc0aaac8d8ac7f2b41527567d6a2329429d172 though I do agree with @laanwj that disabling logging would make sense now.

eklitzke commented at 7:21 am on March 16, 2018: contributor

I could not resist the temptation to add -nodebuglog because I found the “node bug log” thing to be so funny. I added it as a “secret” option (meaning it’s suppressed by default from -help output). You can also use -debuglogfile=/dev/null and -debuglogfile=0 to disable logging. There are also Python test cases for all three methods. So I believe everyone got what they asked for :-D

Interestingly, before this change -debuglogfile=/dev/null did not work, because FileTruncate() does not check that its argument is a regular file. This is yet-another Unix compatibility thing that I would like Bitcoin to support better! I believe this means that master will fail if you try to log to e.g. a named pipe created with mkfifo(1), which is not common but still an unfortunate bug.

One question I have about this change: I was originally going to update the -debuglogfile help string but realized it would require it to be re-translated. Since developers are probably the only ones who want this option it might just make sense to have a one line changelog note about the change? I’m not sure what the protocol is for this.

eklitzke commented at 7:30 am on March 16, 2018: contributor

I tested and you actually can use a named pipe, because the operation that’s failing is a file size check in boost. But you can’t use other special files, e.g. /dev/zero which swallows input the same was as /dev/null.

 0# this is allowed
 1$ echo foo > /dev/zero
 2
 3# yep, it worked
 4$ echo $?
 50
 6
 7# this fails
 8$ ./src/bitcoind -debuglogfile=/dev/zero
 9
10
11************************
12EXCEPTION: N5boost10filesystem16filesystem_errorE       
13boost::filesystem::file_size: Operation not permitted: "/dev/zero"       
14bitcoin in AppInit()

Something to fix another day I guess.

laanwj commented at 9:55 am on March 16, 2018: member

use -debuglogfile=/dev/null

Right, what bothered me about /dev/null is that it’s OS-specific. I don’t think providing arbitrary device files as debug log files (such as /dev/zero, /dev/urandom etc) should be really a goal. It mentions file in the name :) Better to have a dedicated option for it, thanks.

eklitzke commented at 0:20 am on March 17, 2018: contributor

I spent way longer on this than I’d like to admit, due to strange behavior in the Bitcoin option parser.

There’s a little-known feature in the option parser where -nofoo is the same as -foo=0 when updating the value map. So you can’t actually create an option with a name like -nodebuglog, because looking up the value from the map still uses the nodebuglog value, but the value is actually set in the map as debuglog. I thought this was really neat, because my last update to this diff had special cased -nodebuglog and -debuglogfile=0, so I thought I could just use gArgs.GetBoolArg("-debuglogfile"). That would be really nice because then I could delete a bunch of lines from my last diff and not treat those as special cases.

Nope, doesn’t work. I digged in and here’s where it gets really weird. The option parser uses atoi() to interpret boolean arguments. The thing is, the return value of atoi() is undefined if you pass it non-integer values, as there’s no way to tell from the return value whether an error occurred.

Here’s where it gets kind of weird. We had a test in ResendWalletTransactionsTest() that was setting a flag like this:

0class ResendWalletTransactionsTest(BitcoinTestFramework):
1    def set_test_params(self):
2        self.num_nodes = 1
3        self.extra_args = [['--walletbroadcast=false']]

So what happens when the option parser sees this… is it calls atoi("false"). That returns 0 like we want, but only because atoi() happens to return false for invalid input… a fact that I want to again emphasize is undefined. On another libc implementation atoi() is allowed to e.g. return an uninitialized value in this situation. This also means that -walletbroadcast=true would disable wallet broadcast, for the same reason.

Since there’s a test case in Bitcoin that was using a “false” flag, I think it’s possible that there are other people in the wild relying on this behavior. So now the option parser treasts only 0 and false as false, and no other values. If people had configs that were setting values to false, this will still work. I really wanted to add C++ tests for this code, but the methods I wanted to test are defined static in the util.cpp file.**

I also made it so if you use -debuglogfile=/dev/null on a Unix system, it won’t crash. But that’s just because I fixed ShrinkDebugLogFile(), not because I’m special casing it. Setting -debuglogfile=/dev/null will actually open /dev/null and write data to it.

A lot yak shaving, but it makes the option parser more robust so probably worth it.

** Technically this means that -debuglogfile=false will not write to a file named “false”. Of course, -debuglogfile=./false would be perfectly fine. I thought about abusing this to add a Python test case for the option parsing by testing those two flavors in this test, but it felt too weird.

eklitzke commented at 0:33 am on March 17, 2018: contributor

Actually it looks like I can add C++ test for the option parser, I’m going to put up another commit adding that.

luke-jr commented at 1:27 am on March 17, 2018: member

atoi is well-defined for all null-terminated input strings.

The strtol, strtoll, strtoul, and strtoull functions return the converted value, if any. If no conversion could be performed, zero is returned.

eklitzke commented at 1:29 am on March 17, 2018: contributor

Interesting, that’s not documented in the man pages on my system, but cppreference.com agrees that it must return 0 in such a case.

donaloconnor commented at 11:49 am on March 17, 2018: contributor

utACK - looks good

in src/util.cpp:436 in dca1a864f5 outdated

431@@ -423,16 +432,14 @@ void ReleaseDirectoryLocks()
432 /** Interpret string as boolean, for argument parsing */
433 static bool InterpretBool(const std::string& strValue)
434 {
435-    if (strValue.empty())
436-        return true;
437-    return (atoi(strValue) != 0);
438+    // These values mean false, anything else (including empty string) is true.
439+    return strValue != "0" && strValue != "false";

MarcoFalke commented at 3:13 pm on March 17, 2018:

I think this has nothing to do with printtoconsole. Mind to split it up into a separate pull?

eklitzke commented at 2:13 am on March 18, 2018:

It has to do with the behavior I wanted for disabling the debug log, but you’re right that it’s technically orthogonal. I will split it out.

meshcollider commented at 11:23 pm on March 17, 2018: contributor

utACK https://github.com/bitcoin/bitcoin/pull/12689/commits/dca1a864f5395a69c6dc2952dcd1dca0d71976e9, nice :)

eklitzke referenced this in commit cdf4df7ebe on Mar 18, 2018

eklitzke referenced this in commit 6ad2a13cfd on Mar 18, 2018

eklitzke commented at 2:44 am on March 18, 2018: contributor

I’ve split the option parsing code out into another change as Marco asked. Once that is merged I can rebase and squash this branch.

in test/functional/wallet_resendwallettransactions.py:13 in 13641e6345 outdated

 9@@ -10,7 +10,7 @@
10 class ResendWalletTransactionsTest(BitcoinTestFramework):
11     def set_test_params(self):
12         self.num_nodes = 1
13-        self.extra_args = [['--walletbroadcast=false']]
14+        self.extra_args = [['-walletbroadcast=0']]

jimpo commented at 11:02 pm on March 18, 2018:

Feels like this should also be in #12713.

Sjors commented at 2:34 pm on March 21, 2018:

This has been moved to the other commit.

in src/util.cpp:193 in dca1a864f5 outdated

192@@ -193,6 +193,17 @@ fs::path GetDebugLogPath()
193     return AbsPathForConfigVal(logfile);
194 }
195 
196+bool ShouldOpenDebugLog()

jimpo commented at 11:09 pm on March 18, 2018:

Feels non-obvious based on the name that this would toggle the state of a global variable. Now that the bool option parsing is fixed, I don’t think there’s a need for this function. But even if you want to keep it, I think it would be clearer if the code in AppInitMain set fPrintToDebugLog = ShouldOpenDebugLog().

in src/init.cpp:823 in dca1a864f5 outdated

818+ * Used when -printtoconsole is not explicitly set to determine if it makes
819+ * sense to log messages to stdout.
820+ *
821+ * @return true if we should log to stdout, false otherwise.
822+ */
823+static bool ShouldPrintToConsole()

jimpo commented at 11:11 pm on March 18, 2018:

nit: PrintToConsoleDefault() is seems more accurate. Otherwise the function name makes it sound like it takes -printtoconsole into account.

MarcoFalke commented at 11:24 pm on March 18, 2018:

Since it is only called once, you could also inline it and call the variable const bool default_printtoconsole = !gArgs.GetBoolArg("-daemon", false);

eklitzke commented at 5:08 am on March 19, 2018:

It’s already inlined by the compiler, there’s no difference in the executable produced by GCC either way. The only reason it’s still a method is because it originally called isatty(). If I can get #12713 merged I am happy to remove this method.

eklitzke referenced this in commit e944ec998f on Mar 19, 2018

eklitzke referenced this in commit 6094cb7405 on Mar 20, 2018

eklitzke referenced this in commit 777cf8b3e6 on Mar 20, 2018

eklitzke force-pushed on Mar 20, 2018

eklitzke commented at 8:21 am on March 20, 2018: contributor

@MarcoFalke This branch now contains two commits: the one from #12713 , and then a second commit with changes actually related to console printing. Both commits should pass the test suite.

eklitzke referenced this in commit d340565be5 on Mar 21, 2018

eklitzke referenced this in commit 8ef4c697f1 on Mar 21, 2018

eklitzke force-pushed on Mar 21, 2018

eklitzke commented at 6:02 am on March 21, 2018: contributor

Updated again with changes from #12713.

eklitzke referenced this in commit 6b95d6bd6e on Mar 21, 2018

eklitzke force-pushed on Mar 21, 2018

Sjors approved

Sjors commented at 2:42 pm on March 21, 2018: member

tACK c389e87 on macOS.

Would be nice if you update the RPC help though:

-printtoconsole says instead of debug.log file which is not true

in test/functional/feature_logging.py:70 in c389e870be outdated

65+        self.start_node(0, ["-nodebuglogfile"])
66+        assert not os.path.isfile(default_log_path)
67+
68+        # just sanity check no crash here
69+        self.stop_node(0)
70+        self.start_node(0, ["-debuglogfile=/dev/null"])

jnewbery commented at 3:43 pm on March 21, 2018:

Will this work on non-linux platforms? Is os.devnull better? https://docs.python.org/3/library/os.html#os.devnull

jnewbery commented at 3:49 pm on March 21, 2018: member

Change seems good to me. However, this causes debug log to be spewed to console when running individual functional tests (ie not through the test_runner). I think you’ll need to update:

https://github.com/bitcoin/bitcoin/blob/4ad3b3c72c73d61e0a0cab541dca20acf651320d/test/functional/test_framework/test_node.py#L67

to include -noprinttoconsole

Also one nit in the new test.

in test/functional/feature_logging.py:69 in 60086ad871 outdated

66@@ -67,7 +67,7 @@ def run_test(self):
67 
68         # just sanity check no crash here
69         self.stop_node(0)
70-        self.start_node(0, ["-debuglogfile=/dev/null"])
71+        self.start_node(0, ["-debuglogfile=%s" % os.devnull])

ryanofsky commented at 1:10 pm on March 22, 2018:

In commit “stop printing to console in test runner”

This change looks like it should go in the previous commit (“Enable -printtoconsole by default if bitcoind is not a daemon”).

ryanofsky commented at 1:16 pm on March 22, 2018: member

utACK for the last two commits that aren’t part of #12713:

6b95d6bd6e81030605d6b4ad42dd83cd3bc69bfd Improve boolean option parsing (1/3)
c389e870beaf5e8b84ca09ef8e7ba3c981ca6988 Enable -printtoconsole by default if bitcoind is not a daemon (2/3)
60086ad871cb1a756c152a3d3e19fcea52660123 stop printing to console in test runner (3/3)

jnewbery commented at 2:11 pm on March 22, 2018: member

utACK 60086ad871cb1a756c152a3d3e19fcea52660123. I think that commit can be squashed with the previous.

eklitzke force-pushed on Mar 27, 2018

eklitzke referenced this in commit b8dafbb806 on Mar 27, 2018

Add additional tests for GetBoolArg()

This is meant to be an intermediate commit to prove that the next does not
introduce any changes in the semantics of boolean option parsing.

4f872b2450

Track negated arguments in the argument paser.

This commit adds tracking for negated arguments. This change will be used in a
future commit that allows disabling the debug.log file using -nodebuglogfile.

f7683cba7b

Print to console by default when not run with -daemon

Printing to the debug log file can be disabled with -nodebulogfile

ef6fa1c38e

eklitzke force-pushed on Mar 28, 2018

MarcoFalke referenced this in commit 4490871ed7 on Mar 30, 2018

MarcoFalke commented at 7:19 pm on March 30, 2018: member

Needs rebase to get rid of the already-merged diff.

MarcoFalke added the label Up for grabs on Apr 7, 2018

MarcoFalke commented at 7:37 pm on April 7, 2018: member

Marked “up for grabs”

sipa commented at 10:19 pm on April 8, 2018: member

./contrib/devtools/clang-format-diff.py:74:1: F401 ‘string’ imported but unused

ryanofsky commented at 9:42 pm on April 16, 2018: member

utACK ef6fa1c38e1bd115d1cce155907023d79da379d8. No changes since the last review other than squash & rebase. Note: The first two commits shown in this PR are already merged into master since 4490871ed7eb8de0b644ba8545789f2cc702434e (#12713), so they can be ignored.

fanquake closed this on Apr 17, 2018

fanquake removed the label Up for grabs on Apr 17, 2018

laanwj referenced this in commit 58bbc55212 on Apr 17, 2018

UdjinM6 referenced this in commit d52809132a on Apr 29, 2020

PastaPastaPasta referenced this in commit 6289bda49e on Apr 30, 2020

PastaPastaPasta referenced this in commit 7a89b916d1 on May 9, 2020

ckti referenced this in commit 51e01f00f5 on Mar 28, 2021

PastaPastaPasta referenced this in commit 6b9a091c16 on Apr 13, 2021

PastaPastaPasta referenced this in commit 4726423359 on Apr 15, 2021

PastaPastaPasta referenced this in commit 5d24bff413 on Apr 17, 2021

PastaPastaPasta referenced this in commit 90bc40d297 on Apr 18, 2021

kittywhiskers referenced this in commit 0f59ed213b on Apr 23, 2021

gades referenced this in commit 5886e19161 on Jun 30, 2021

MarcoFalke locked this on Sep 8, 2021

Smarter default behavior for -printtoconsole #12689