Skip to content

Conversation

@eklitzke
Copy link
Contributor

@eklitzke eklitzke commented Mar 14, 2018

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.

@Sjors
Copy link
Member

Sjors commented Mar 14, 2018

Concept ACK. Tested on macOS.

Needs update for -printtoconsole help text.

src/util.cpp Outdated

bool IsStdoutTty()
{
return isatty(STDOUT_FILENO);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
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
Copy link
Contributor

Just a few concerns (Mainly on Windows)

  1. There's now no way of turning the stdout logging off when launched in foreground. It's either on or (on by default)
  2. 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?
  3. 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
Copy link
Contributor

promag commented Mar 14, 2018

Concept ACK, cool 👍.

@eklitzke
Copy link
Contributor Author

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:

# stdout is a pipe, not a TTY.
bitcoind | less

# stdout is a file, not a TTY.
bitcoind > 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
Copy link
Contributor Author

eklitzke commented Mar 14, 2018

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
Copy link
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
Copy link
Member

luke-jr commented Mar 15, 2018

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
Copy link
Contributor Author

@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
Copy link
Contributor Author

@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).

@practicalswift
Copy link
Contributor

utACK 23bc0aa

src/util.cpp Outdated
fflush(stdout);
}
else if (fPrintToDebugLog)
if (fPrintToDebugLog)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe -debuglogfile=0 as a special case?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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" :-)

Copy link
Contributor

@meshcollider meshcollider Mar 17, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
Member

Sjors commented Mar 15, 2018

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

// Add newlines to the logfile to distinguish this execution from the last
// one; called before console logging is set up, so this is only sent to
// debug.log.
LogPrintf("\n\n\n\n\n");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

src/util.cpp Outdated
fflush(stdout);
}
else if (fPrintToDebugLog)
if (fPrintToDebugLog)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: move brackets to same line?

@practicalswift
Copy link
Contributor

practicalswift commented Mar 15, 2018

utACK 23bc0aa modulo @Sjors' nits :-)

@donaloconnor
Copy link
Contributor

utACK 23bc0aa though I do agree with @laanwj that disabling logging would make sense now.

@eklitzke
Copy link
Contributor Author

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
Copy link
Contributor Author

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.

# this is allowed
$ echo foo > /dev/zero

# yep, it worked
$ echo $?
0

# this fails
$ ./src/bitcoind -debuglogfile=/dev/zero


************************
EXCEPTION: N5boost10filesystem16filesystem_errorE       
boost::filesystem::file_size: Operation not permitted: "/dev/zero"       
bitcoin in AppInit()       

Something to fix another day I guess.

@laanwj
Copy link
Member

laanwj commented Mar 16, 2018

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
Copy link
Contributor Author

eklitzke commented Mar 17, 2018

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:

class ResendWalletTransactionsTest(BitcoinTestFramework):
    def set_test_params(self):
        self.num_nodes = 1
        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
Copy link
Contributor Author

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
Copy link
Member

luke-jr commented Mar 17, 2018

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
Copy link
Contributor Author

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
Copy link
Contributor

utACK - looks good

Copy link
Contributor

@ryanofsky ryanofsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

  • 6b95d6b 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)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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").

@jnewbery
Copy link
Contributor

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

@eklitzke eklitzke force-pushed the console branch 2 times, most recently from 2bbe9ff to 7cbf03d Compare March 27, 2018 04:38
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.
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.
Printing to the debug log file can be disabled with -nodebulogfile
maflcko pushed a commit that referenced this pull request Mar 30, 2018
f7683cb Track negated arguments in the argument paser. (Evan Klitzke)
4f872b2 Add additional tests for GetBoolArg() (Evan Klitzke)

Pull request description:

  This change explicitly enable tracking negated options in the option parser. A negated option is one passed with a `-no` prefix. For example, `-nofoo` is the negated form of `-foo`. Negated options were originally added in the 0.6 release.

  The change here allows code to explicitly distinguish between cases like `-nofoo` and `-foo=0`, which was not possible previously. The option parser does not have any changed semantics as a result of this change, and existing code will parse options just as it did before.

  The motivation for this change is to provide a way to disable options that are otherwise not boolean options. For example, the `-debuglogfile` option is normally interpreted as a string, where the value is the log file name. With this change a user can pass in `-nodebuglogfile` and the code can see that it was explicitly negated, and use that to disable the log file.

  This change originally split out from #12689.

Tree-SHA512: cd5a7354eb03d2d402863c7b69e512cad382781d9b8f18c1ab104fc46d45a712530818d665203082da39572c8a42313c5be09306dc2a7227cdedb20ef7314823
@maflcko
Copy link
Member

maflcko commented Mar 30, 2018

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

@maflcko
Copy link
Member

maflcko commented Apr 7, 2018

Marked "up for grabs"

@sipa
Copy link
Member

sipa commented Apr 8, 2018

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

Copy link
Contributor

@ryanofsky ryanofsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

utACK ef6fa1c. 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 4490871 (#12713), so they can be ignored.

@fanquake fanquake closed this Apr 17, 2018
laanwj added a commit that referenced this pull request Apr 17, 2018
6a3b0d3 Print to console by default when not run with -daemon (Evan Klitzke)

Pull request description:

  Cherry-picked ef6fa1c from the "up for grabs" PR: "Smarter default behavior for -printtoconsole" (#12689).

  See previous review in #12689.

Tree-SHA512: 8923a89b9c8973286d53e960d3c464b1cd026cd5a5911ba62f9f972c83684417dc4004101815dfe987fc1e1baaec1fdd90748a0866bb5548e974d77b3135d43b
PastaPastaPasta pushed a commit to PastaPastaPasta/dash that referenced this pull request May 9, 2020
f7683cb Track negated arguments in the argument paser. (Evan Klitzke)
4f872b2 Add additional tests for GetBoolArg() (Evan Klitzke)

Pull request description:

  This change explicitly enable tracking negated options in the option parser. A negated option is one passed with a `-no` prefix. For example, `-nofoo` is the negated form of `-foo`. Negated options were originally added in the 0.6 release.

  The change here allows code to explicitly distinguish between cases like `-nofoo` and `-foo=0`, which was not possible previously. The option parser does not have any changed semantics as a result of this change, and existing code will parse options just as it did before.

  The motivation for this change is to provide a way to disable options that are otherwise not boolean options. For example, the `-debuglogfile` option is normally interpreted as a string, where the value is the log file name. With this change a user can pass in `-nodebuglogfile` and the code can see that it was explicitly negated, and use that to disable the log file.

  This change originally split out from bitcoin#12689.

Tree-SHA512: cd5a7354eb03d2d402863c7b69e512cad382781d9b8f18c1ab104fc46d45a712530818d665203082da39572c8a42313c5be09306dc2a7227cdedb20ef7314823
PastaPastaPasta pushed a commit to PastaPastaPasta/dash that referenced this pull request Apr 13, 2021
…aemon

6a3b0d3 Print to console by default when not run with -daemon (Evan Klitzke)

Pull request description:

  Cherry-picked ef6fa1c from the "up for grabs" PR: "Smarter default behavior for -printtoconsole" (bitcoin#12689).

  See previous review in bitcoin#12689.

Tree-SHA512: 8923a89b9c8973286d53e960d3c464b1cd026cd5a5911ba62f9f972c83684417dc4004101815dfe987fc1e1baaec1fdd90748a0866bb5548e974d77b3135d43b
PastaPastaPasta pushed a commit to PastaPastaPasta/dash that referenced this pull request Apr 18, 2021
…aemon

6a3b0d3 Print to console by default when not run with -daemon (Evan Klitzke)

Pull request description:

  Cherry-picked ef6fa1c from the "up for grabs" PR: "Smarter default behavior for -printtoconsole" (bitcoin#12689).

  See previous review in bitcoin#12689.

Tree-SHA512: 8923a89b9c8973286d53e960d3c464b1cd026cd5a5911ba62f9f972c83684417dc4004101815dfe987fc1e1baaec1fdd90748a0866bb5548e974d77b3135d43b
gades pushed a commit to cosanta/cosanta-core that referenced this pull request Jun 30, 2021
f7683cb Track negated arguments in the argument paser. (Evan Klitzke)
4f872b2 Add additional tests for GetBoolArg() (Evan Klitzke)

Pull request description:

  This change explicitly enable tracking negated options in the option parser. A negated option is one passed with a `-no` prefix. For example, `-nofoo` is the negated form of `-foo`. Negated options were originally added in the 0.6 release.

  The change here allows code to explicitly distinguish between cases like `-nofoo` and `-foo=0`, which was not possible previously. The option parser does not have any changed semantics as a result of this change, and existing code will parse options just as it did before.

  The motivation for this change is to provide a way to disable options that are otherwise not boolean options. For example, the `-debuglogfile` option is normally interpreted as a string, where the value is the log file name. With this change a user can pass in `-nodebuglogfile` and the code can see that it was explicitly negated, and use that to disable the log file.

  This change originally split out from bitcoin#12689.

Tree-SHA512: cd5a7354eb03d2d402863c7b69e512cad382781d9b8f18c1ab104fc46d45a712530818d665203082da39572c8a42313c5be09306dc2a7227cdedb20ef7314823
@bitcoin bitcoin locked as resolved and limited conversation to collaborators Sep 8, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Projects

None yet

Development

Successfully merging this pull request may close these issues.