Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

util/log: clean up and document the handling of stderr #49849

Merged
merged 3 commits into from
Jun 5, 2020

Conversation

knz
Copy link
Contributor

@knz knz commented Jun 3, 2020

Required by #48051

Previous work in this area of the code introduced a confusion between
two orthogonal concepts:

  • each logger might copy its log entries to the process' external
    stderr stream (e.g. the terminal during interactive use), as
    set by its "stderrThreshold" variable.

  • direct writes by Go code to process-wide file descriptor 2 (such
    as done by the Go runtime) or os.Stderr (such as done
    by 3rd party packages when doing their own ad-hoc logging)
    can be redirected to a logger's output file.

The confusion (mostly mine - @knz) was to mix the two kinds of
"stderr" and mistakenly conflating "entries submitted to this logger
via API calls" and "direct writes to fd 2 by other go code without
looking at the logging API". These are actually completely separate
and independent concepts/mechanisms.

The code clarifies the situation as follows:

  • the process' external stderr stream is always available via
    log.OrigStderr and this is meant to never change throughout
    execution.

  • the external stderr stream is the sink for Shout() API calls
    and also the copy of log entries whose severity
    exceed the "stderrThreshold" variable.

  • separately, at most one logger may redirect internal writes to fd
    2 and os.Stderr to its log file. This is determined by
    its variable "noRedirectInternalStderrWrites" (previously
    named "noRedirectStderr").

Beyond this, this commit fixes 3 bugs.

  1. the code was intending to both redirect the standard stderr file
    descriptor (fd 2 on unix, error handle on windows) and also
    os.Stderr separately, but failing to do so on unix build targets.
    It was done correctly for windows. This is now corrected so that
    os.Stderr gets assigned on all targets.

    (The separate assignment of os.Stderr is necessary because
    although Go intializes this to be equivalent to the standard
    file descriptor upon process startup, other Go code can
    assign os.Stderr after initialization.)

  2. upon encountering a write error to its output file, a logger
    would previously report that write error twice to the
    process' external stderr. This has been corrected
    so that the write error is only reported once.

  3. previously, upon a log.Fatal performed while configuration would not
    otherwise cause a copy the F entry go to the process external stderr,
    the code would override the configuration and force a copy of the
    entry to the external stderr stream.

    There is no good reason for this - either the user wants F entries
    on the external stderr and signal this desire via
    --logtostderr=FATAL or lower, or they don't want F entries there
    at all via --logtostderr=NONE. There is no reason for an
    override and the code should honor the configuration.

    (I introduced the bug together with the confusion mentioned
    at the beginning.)

Release note: None

@knz knz requested review from bdarnell and tbg June 3, 2020 21:23
@cockroach-teamcity
Copy link
Member

This change is Reviewable

@knz knz force-pushed the 20200603-stderr-redirect branch from c84f29b to d1a3351 Compare June 3, 2020 22:06
@knz knz force-pushed the 20200603-stderr-redirect branch from d1a3351 to d2c812a Compare June 4, 2020 21:29
@knz knz requested a review from a team as a code owner June 4, 2020 21:29
@knz
Copy link
Contributor Author

knz commented Jun 4, 2020

ok this has overcome TC at last. RFAL

@knz knz force-pushed the 20200603-stderr-redirect branch from d2c812a to e3389ad Compare June 5, 2020 08:18
Copy link
Member

@tbg tbg left a comment

Choose a reason for hiding this comment

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

Reviewed 14 of 14 files at r1, 4 of 4 files at r2.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @bdarnell)

@knz
Copy link
Contributor Author

knz commented Jun 5, 2020

thanks

bors r=tbg

@craig
Copy link
Contributor

craig bot commented Jun 5, 2020

Build failed

knz added 3 commits June 5, 2020 15:19
The Decommission RPC doesn't need to accept an empty node ID list
as of v20.2 since `cockroach quit --decommission` was removed.

However, `TestDecommission` still used that case and started
failing as a result. This patch fixes the test to not rely
on the behavior.

Additionally, this patch causes the RPC to return an error when no
node ID is specified, instead of silently turning into a no-op.

A discussion remains of whether the RPC should accept a way to specify
the "local" node (maybe more explicitly than via an empty list of node
IDs), like many of the other RPCs already do.

This discussion came up in a separate issues which wants that
behavior for the `node drain` command. I am expecting that `node
decommission` will want that option too. However let's address that at
that time.

Release note: None
Previous work in this area of the code introduced a confusion between
two orthogonal concepts:

- each logger might copy its log entries to the process' external
  stderr stream (e.g. the terminal during interactive use), as
  set by its "stderrThreshold" variable.

- direct writes by Go code to process-wide file descriptor 2 (such
  as done by the Go runtime)  or `os.Stderr` (such as done
  by 3rd party packages when doing their own ad-hoc logging)
  can be redirected to a logger's output file.

The confusion (mostly mine - @knz) was to mix the two kinds of
"stderr" and mistakenly conflating "entries submitted to this logger
via API calls" and "direct writes to fd 2 by other go code without
looking at the logging API". These are actually completely separate
and independent concepts/mechanisms.

The code clarifies the situation as follows:

- the process' external stderr stream is always available via
  `log.OrigStderr` and this is meant to never change throughout
  execution.

- the external stderr stream is the sink for `Shout()` API calls
  and also the copy of log entries whose severity
  exceed the "stderrThreshold" variable.

- separately, *at most one logger* may redirect internal writes to fd
  2 and os.Stderr to its log file. This is determined by
  its variable "noRedirectInternalStderrWrites" (previously
  named "noRedirectStderr").

Beyond this, this commit fixes 3 bugs.

1. the code was intending to both redirect the standard stderr file
   descriptor (fd 2 on unix, error handle on windows) and also
   `os.Stderr` separately, but failing to do so on unix build targets.
   It was done correctly for windows. This is now corrected so that
   `os.Stderr` gets assigned on all targets.

   (The separate assignment of `os.Stderr` is necessary because
   although Go intializes this to be equivalent to the standard
   file descriptor upon process startup, other Go code can
   assign `os.Stderr` after initialization.)

2. upon encountering a write error to its output file, a logger
   would previously report that write error twice to the
   process' external stderr. This has been corrected
   so that the write error is only reported once.

3. previously, upon a log.Fatal performed while configuration would not
   otherwise cause a copy the F entry go to the process external stderr,
   the code would override the configuration and force a copy of the
   entry to the external stderr stream.

   There is no good reason for this - either the user wants F entries
   on the external stderr and signal this desire via
   `--logtostderr=FATAL` or lower, or they don't want F entries there
   at all via `--logtostderr=NONE`. There is no reason for an
   override and the code should honor the configuration.

   (I introduced the bug together with the confusion mentioned
   at the beginning.)

Release note: None
There's an uncommon code path that directly writes to either
a log file or the process' external stderr:

- to report I/O errors encountered during logging (e.g. errors
  writing to the output log file)
- to copy the details of a panic object reported via `log.ReportPanic`
  to either external stderr or the log file, when the Go
  runtime would otherwise only report it to the "other side".

In these cases, previously the data would be written as-is to the
output sink, without a proper log entry header - timestamp, goroutine,
file/line, etc.
This made it hard to identify the precise moment when the
output was produced and its precise origin.

This patch enhances these cases by adding the missing log entry header.

Release note: None
@knz knz force-pushed the 20200603-stderr-redirect branch from e3389ad to ec7a7a2 Compare June 5, 2020 13:21
@knz
Copy link
Contributor Author

knz commented Jun 5, 2020

bors r=tbg

@craig
Copy link
Contributor

craig bot commented Jun 5, 2020

Build succeeded

@craig craig bot merged commit c9b9c01 into cockroachdb:master Jun 5, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants