Commit ec7a7a25 authored by Raphael 'kena' Poss's avatar Raphael 'kena' Poss

util/log: add an entry header incl timestamp to direct writes

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
parent df3cee6c
......@@ -8,12 +8,10 @@ spawn /bin/bash
send "PS1=':''/# '\r"
eexpect ":/# "
start_test "Check that a server encountering a fatal error when not logging to stderr shows the fatal error."
start_test "Check that a server encountering a fatal error when not logging to stderr exits with the right code."
send "$argv start-single-node -s=path=logs/db --insecure\r"
eexpect "CockroachDB node starting"
system "$argv sql --insecure -e \"select crdb_internal.force_log_fatal('helloworld')\" || true"
eexpect "\r\nF"
eexpect "helloworld"
eexpect ":/# "
send "echo \$?\r"
eexpect "255"
......@@ -36,7 +34,7 @@ eexpect ":/# "
# is only reported on the logger which is writing first after stderr
# is has been broken, and that may be the secondary logger.
send "tail -F `find logs/db/logs -type l`\r"
eexpect "log: exiting because of error: write /dev/stderr: broken pipe"
eexpect "error: write /dev/stderr: broken pipe"
interrupt
eexpect ":/# "
end_test
......
......@@ -363,14 +363,14 @@ func DumpStacks(ctx context.Context) {
Infof(ctx, "stack traces:\n%s", allStacks)
}
// printPanicToFile copies the panic details to the log file. This is
// useful when the internal stderr writes are not redirected to the
// log file (!stderrRedirected), as the go runtime hardcodes
// its writes to file descriptor 2.
// printPanicToFile is used by ReportPanic() to copy the panic details to the log file. This is
// used when we understand that the Go runtime will only automatically
// print the panic details to the external stderr stream (e.g.
// when we're not redirecting that to a file).
//
// TODO(knz): Create a log entry header for the panic details, to
// get a timestamp and later a redactable marker.
func (l *loggerT) printPanicToFile(r interface{}) {
// This function is a lightweight version of outputLogEntry() which
// does not exit the process in case of error.
func (l *loggerT) printPanicToFile(depth int, r interface{}) {
if !l.logDir.IsSet() {
// There's no log file. Can't do anything.
return
......@@ -386,11 +386,34 @@ func (l *loggerT) printPanicToFile(r interface{}) {
return
}
panicBytes := []byte(fmt.Sprintf("%v\n\n%s\n", r, debug.Stack()))
if err := l.writeToFile(panicBytes); err != nil {
// Create a fully structured log entry. This ensures there a
// timestamp in front of the panic object.
entry := makeEntryForPanicObject(depth+1, r)
buf := logging.processForFile(entry, debug.Stack())
defer putBuffer(buf)
// Actually write the panic object to a file.
if err := l.writeToFile(buf.Bytes()); err != nil {
// Ditto; report the error but continue. We're terminating anyway.
l.reportErrorEverywhereLocked(err)
return
}
}
func makeEntryForPanicObject(depth int, r interface{}) Entry {
file, line, _ := caller.Lookup(depth + 1)
return MakeEntry(Severity_ERROR, timeutil.Now().UnixNano(), file, line, fmt.Sprintf("panic: %v", r))
}
// printPanicToExternalStderr is used by ReportPanic() in case we
// understand that the Go runtime will not print the panic object to
// the external stderr itself (e.g. because we've redirected it to a
// file).
func (l *loggerT) printPanicToExternalStderr(depth int, r interface{}) {
entry := makeEntryForPanicObject(depth+1, r)
if err := l.outputToStderr(entry, debug.Stack()); err != nil {
l.mu.Lock()
defer l.mu.Unlock()
l.reportErrorEverywhereLocked(err)
}
}
......
......@@ -13,7 +13,6 @@ package log
import (
"context"
"fmt"
"runtime/debug"
"time"
"github.com/cockroachdb/cockroach/pkg/build"
......@@ -106,6 +105,15 @@ var Safe = errors.Safe
// ReportPanic reports a panic has occurred on the real stderr.
func ReportPanic(ctx context.Context, sv *settings.Values, r interface{}, depth int) {
// Announce the panic has occurred to all places. The purpose
// of this call is double:
// - it ensures there's a notice on the terminal, in case
// logging would only go to file otherwise;
// - it places a timestamp in front of the panic object,
// in case the various configuration options make
// the Go runtime solely responsible for printing
// out the panic object to the log file.
// (The go runtime doesn't time stamp its output.)
Shout(ctx, Severity_ERROR, "a panic has occurred!")
if stderrLog.redirectInternalStderrWrites() {
......@@ -121,9 +129,7 @@ func ReportPanic(ctx context.Context, sv *settings.Values, r interface{}, depth
// as an indication they also want to see panic details
// there. Do it here.
if LoggingToStderr(Severity_FATAL) {
// TODO(knz): Produce a log entry header to get a timestamp
// here.
fmt.Fprintf(OrigStderr, "%v\n\n%s\n", r, debug.Stack())
stderrLog.printPanicToExternalStderr(depth+1, r)
}
} else {
// If we are not redirecting internal stderr writes, then the
......@@ -132,7 +138,7 @@ func ReportPanic(ctx context.Context, sv *settings.Values, r interface{}, depth
//
// However, we actually want to persist these details. So print
// them in the log file ourselves.
stderrLog.printPanicToFile(r)
stderrLog.printPanicToFile(depth+1, r)
}
sendCrashReport(ctx, sv, PanicAsError(depth+1, r), ReportTypePanic)
......
......@@ -14,6 +14,9 @@ import (
"fmt"
"io"
"os"
"github.com/cockroachdb/cockroach/pkg/util/caller"
"github.com/cockroachdb/cockroach/pkg/util/timeutil"
)
// SetExitFunc allows setting a function that will be called to exit
......@@ -74,10 +77,21 @@ func (l *loggerT) exitLocked(err error) {
// reportErrorEverywhereLocked writes the error details to both the
// process' original stderr and the log file if configured.
//
// TODO(knz): Create a log entry header for this error, to get a
// timestamp and later a redactable marker.
func (l *loggerT) reportErrorEverywhereLocked(err error) {
// Make a valid log entry for this error.
file, line, _ := caller.Lookup(1)
entry := MakeEntry(Severity_ERROR, timeutil.Now().UnixNano(), file, line,
fmt.Sprintf("logging error: %v", err))
// Format the entry for output below. Note how this formatting is
// done just once here for both the stderr and file outputs below,
// and thus misses out on TTY colors if configured. We afford this
// simplification because we only arrive here in case of
// likely-unrecoverable error, and there's not much incentive to be
// overly aesthetic in this case.
buf := logging.formatLogEntry(entry, nil /*stacks*/, nil /*color profile*/)
defer putBuffer(buf)
// Either stderr or our log file is broken. Try writing the error to both
// streams in the hope that one still works or else the user will have no idea
// why we crashed.
......@@ -94,7 +108,9 @@ func (l *loggerT) reportErrorEverywhereLocked(err error) {
if w == nil {
continue
}
fmt.Fprintf(w, "log: exiting because of error: %s\n", err)
// We're already in error. If an additional error is encountered
// here, we can't do anything but raise our hands in the air.
_, _ = w.Write(buf.Bytes())
}
l.flushAndSync(true /*doSync*/)
}
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment