481 lines
11 KiB
Go
481 lines
11 KiB
Go
|
// Package golog implements logging functions that log errors to stderr and
|
||
|
|
// debug messages to stdout. Trace logging is also supported.
|
||
|
|
// Trace logs go to stdout as well, but they are only written if the program
|
||
|
|
// is run with environment variable "TRACE=true".
|
||
|
|
// A stack dump will be printed after the message if "PRINT_STACK=true".
|
||
|
|
package golog
|
||
|
|
|
||
|
|
import (
|
||
|
|
"bufio"
|
||
|
|
"bytes"
|
||
|
|
"fmt"
|
||
|
|
"io"
|
||
|
|
"io/ioutil"
|
||
|
|
"log"
|
||
|
|
"os"
|
||
|
|
"path/filepath"
|
||
|
|
"runtime"
|
||
|
|
"sort"
|
||
|
|
"strconv"
|
||
|
|
"strings"
|
||
|
|
"sync"
|
||
|
|
"sync/atomic"
|
||
|
|
|
||
|
|
"github.com/getlantern/errors"
|
||
|
|
"github.com/getlantern/hidden"
|
||
|
|
"github.com/getlantern/ops"
|
||
|
|
"github.com/oxtoacart/bpool"
|
||
|
|
)
|
||
|
|
|
||
|
|
const (
|
||
|
|
// ERROR is an error Severity
|
||
|
|
ERROR = 500
|
||
|
|
|
||
|
|
// FATAL is an error Severity
|
||
|
|
FATAL = 600
|
||
|
|
)
|
||
|
|
|
||
|
|
var (
|
||
|
|
outs atomic.Value
|
||
|
|
prepender atomic.Value
|
||
|
|
reporters []ErrorReporter
|
||
|
|
reportersMutex sync.RWMutex
|
||
|
|
|
||
|
|
bufferPool = bpool.NewBufferPool(200)
|
||
|
|
|
||
|
|
onFatal atomic.Value
|
||
|
|
)
|
||
|
|
|
||
|
|
// Severity is a level of error (higher values are more severe)
|
||
|
|
type Severity int
|
||
|
|
|
||
|
|
func (s Severity) String() string {
|
||
|
|
switch s {
|
||
|
|
case ERROR:
|
||
|
|
return "ERROR"
|
||
|
|
case FATAL:
|
||
|
|
return "FATAL"
|
||
|
|
default:
|
||
|
|
return "UNKNOWN"
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
func init() {
|
||
|
|
DefaultOnFatal()
|
||
|
|
ResetOutputs()
|
||
|
|
ResetPrepender()
|
||
|
|
}
|
||
|
|
|
||
|
|
// SetPrepender sets a function to write something, e.g., the timestamp, before
|
||
|
|
// each line of the log.
|
||
|
|
func SetPrepender(p func(io.Writer)) {
|
||
|
|
prepender.Store(p)
|
||
|
|
}
|
||
|
|
|
||
|
|
func ResetPrepender() {
|
||
|
|
SetPrepender(func(io.Writer) {})
|
||
|
|
}
|
||
|
|
|
||
|
|
func GetPrepender() func(io.Writer) {
|
||
|
|
return prepender.Load().(func(io.Writer))
|
||
|
|
}
|
||
|
|
|
||
|
|
// SetOutputs sets the outputs for error and debug logs to use the given writers.
|
||
|
|
// Returns a function that resets outputs to their original values prior to calling SetOutputs.
|
||
|
|
func SetOutputs(errorOut io.Writer, debugOut io.Writer) (reset func()) {
|
||
|
|
oldOuts := outs.Load()
|
||
|
|
outs.Store(&outputs{
|
||
|
|
ErrorOut: errorOut,
|
||
|
|
DebugOut: debugOut,
|
||
|
|
})
|
||
|
|
return func() {
|
||
|
|
outs.Store(oldOuts)
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
// Deprecated: instead of calling ResetOutputs, use the reset function returned by SetOutputs.
|
||
|
|
func ResetOutputs() {
|
||
|
|
SetOutputs(os.Stderr, os.Stdout)
|
||
|
|
}
|
||
|
|
|
||
|
|
func GetOutputs() *outputs {
|
||
|
|
return outs.Load().(*outputs)
|
||
|
|
}
|
||
|
|
|
||
|
|
// RegisterReporter registers the given ErrorReporter. All logged Errors are
|
||
|
|
// sent to this reporter.
|
||
|
|
func RegisterReporter(reporter ErrorReporter) {
|
||
|
|
reportersMutex.Lock()
|
||
|
|
reporters = append(reporters, reporter)
|
||
|
|
reportersMutex.Unlock()
|
||
|
|
}
|
||
|
|
|
||
|
|
// OnFatal configures golog to call the given function on any FATAL error. By
|
||
|
|
// default, golog calls os.Exit(1) on any FATAL error.
|
||
|
|
func OnFatal(fn func(err error)) {
|
||
|
|
onFatal.Store(fn)
|
||
|
|
}
|
||
|
|
|
||
|
|
// DefaultOnFatal enables the default behavior for OnFatal
|
||
|
|
func DefaultOnFatal() {
|
||
|
|
onFatal.Store(func(err error) {
|
||
|
|
os.Exit(1)
|
||
|
|
})
|
||
|
|
}
|
||
|
|
|
||
|
|
type outputs struct {
|
||
|
|
ErrorOut io.Writer
|
||
|
|
DebugOut io.Writer
|
||
|
|
}
|
||
|
|
|
||
|
|
// MultiLine is an interface for arguments that support multi-line output.
|
||
|
|
type MultiLine interface {
|
||
|
|
// MultiLinePrinter returns a function that can be used to print the
|
||
|
|
// multi-line output. The returned function writes one line to the buffer and
|
||
|
|
// returns true if there are more lines to write. This function does not need
|
||
|
|
// to take care of trailing carriage returns, golog handles that
|
||
|
|
// automatically.
|
||
|
|
MultiLinePrinter() func(buf *bytes.Buffer) bool
|
||
|
|
}
|
||
|
|
|
||
|
|
// ErrorReporter is a function to which the logger will report errors.
|
||
|
|
// It the given error and corresponding message along with associated ops
|
||
|
|
// context. This should return quickly as it executes on the critical code
|
||
|
|
// path. The recommended approach is to buffer as much as possible and discard
|
||
|
|
// new reports if the buffer becomes saturated.
|
||
|
|
type ErrorReporter func(err error, severity Severity, ctx map[string]interface{})
|
||
|
|
|
||
|
|
type Logger interface {
|
||
|
|
// Debug logs to stdout
|
||
|
|
Debug(arg interface{})
|
||
|
|
// Debugf logs to stdout
|
||
|
|
Debugf(message string, args ...interface{})
|
||
|
|
|
||
|
|
// Error logs to stderr
|
||
|
|
Error(arg interface{}) error
|
||
|
|
// Errorf logs to stderr. It returns the first argument that's an error, or
|
||
|
|
// a new error built using fmt.Errorf if none of the arguments are errors.
|
||
|
|
Errorf(message string, args ...interface{}) error
|
||
|
|
|
||
|
|
// Fatal logs to stderr and then exits with status 1
|
||
|
|
Fatal(arg interface{})
|
||
|
|
// Fatalf logs to stderr and then exits with status 1
|
||
|
|
Fatalf(message string, args ...interface{})
|
||
|
|
|
||
|
|
// Trace logs to stderr only if TRACE=true
|
||
|
|
Trace(arg interface{})
|
||
|
|
// Tracef logs to stderr only if TRACE=true
|
||
|
|
Tracef(message string, args ...interface{})
|
||
|
|
|
||
|
|
// TraceOut provides access to an io.Writer to which trace information can
|
||
|
|
// be streamed. If running with environment variable "TRACE=true", TraceOut
|
||
|
|
// will point to os.Stderr, otherwise it will point to a ioutil.Discared.
|
||
|
|
// Each line of trace information will be prefixed with this Logger's
|
||
|
|
// prefix.
|
||
|
|
TraceOut() io.Writer
|
||
|
|
|
||
|
|
// IsTraceEnabled() indicates whether or not tracing is enabled for this
|
||
|
|
// logger.
|
||
|
|
IsTraceEnabled() bool
|
||
|
|
|
||
|
|
// AsStdLogger returns an standard logger
|
||
|
|
AsStdLogger() *log.Logger
|
||
|
|
}
|
||
|
|
|
||
|
|
func LoggerFor(prefix string) Logger {
|
||
|
|
l := &logger{
|
||
|
|
prefix: prefix + ": ",
|
||
|
|
pc: make([]uintptr, 10),
|
||
|
|
}
|
||
|
|
|
||
|
|
trace := os.Getenv("TRACE")
|
||
|
|
l.traceOn, _ = strconv.ParseBool(trace)
|
||
|
|
if !l.traceOn {
|
||
|
|
prefixes := strings.Split(trace, ",")
|
||
|
|
for _, p := range prefixes {
|
||
|
|
if prefix == strings.Trim(p, " ") {
|
||
|
|
l.traceOn = true
|
||
|
|
break
|
||
|
|
}
|
||
|
|
}
|
||
|
|
}
|
||
|
|
if l.traceOn {
|
||
|
|
l.traceOut = l.newTraceWriter()
|
||
|
|
} else {
|
||
|
|
l.traceOut = ioutil.Discard
|
||
|
|
}
|
||
|
|
|
||
|
|
printStack := os.Getenv("PRINT_STACK")
|
||
|
|
l.printStack, _ = strconv.ParseBool(printStack)
|
||
|
|
|
||
|
|
return l
|
||
|
|
}
|
||
|
|
|
||
|
|
type logger struct {
|
||
|
|
prefix string
|
||
|
|
traceOn bool
|
||
|
|
traceOut io.Writer
|
||
|
|
printStack bool
|
||
|
|
outs atomic.Value
|
||
|
|
pc []uintptr
|
||
|
|
funcForPc *runtime.Func
|
||
|
|
}
|
||
|
|
|
||
|
|
// attaches the file and line number corresponding to
|
||
|
|
// the log message
|
||
|
|
func (l *logger) linePrefix(skipFrames int) string {
|
||
|
|
runtime.Callers(skipFrames, l.pc)
|
||
|
|
funcForPc := runtime.FuncForPC(l.pc[0])
|
||
|
|
file, line := funcForPc.FileLine(l.pc[0] - 1)
|
||
|
|
return fmt.Sprintf("%s%s:%d ", l.prefix, filepath.Base(file), line)
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) print(out io.Writer, skipFrames int, severity string, arg interface{}) {
|
||
|
|
buf := bufferPool.Get()
|
||
|
|
defer bufferPool.Put(buf)
|
||
|
|
|
||
|
|
GetPrepender()(buf)
|
||
|
|
linePrefix := l.linePrefix(skipFrames)
|
||
|
|
writeHeader := func() {
|
||
|
|
buf.WriteString(severity)
|
||
|
|
buf.WriteString(" ")
|
||
|
|
buf.WriteString(linePrefix)
|
||
|
|
}
|
||
|
|
if arg != nil {
|
||
|
|
ml, isMultiline := arg.(MultiLine)
|
||
|
|
if !isMultiline {
|
||
|
|
writeHeader()
|
||
|
|
fmt.Fprintf(buf, "%v", arg)
|
||
|
|
printContext(buf, arg)
|
||
|
|
buf.WriteByte('\n')
|
||
|
|
} else {
|
||
|
|
mlp := ml.MultiLinePrinter()
|
||
|
|
first := true
|
||
|
|
for {
|
||
|
|
writeHeader()
|
||
|
|
more := mlp(buf)
|
||
|
|
if first {
|
||
|
|
printContext(buf, arg)
|
||
|
|
first = false
|
||
|
|
}
|
||
|
|
buf.WriteByte('\n')
|
||
|
|
if !more {
|
||
|
|
break
|
||
|
|
}
|
||
|
|
}
|
||
|
|
}
|
||
|
|
}
|
||
|
|
b := []byte(hidden.Clean(buf.String()))
|
||
|
|
_, err := out.Write(b)
|
||
|
|
if err != nil {
|
||
|
|
errorOnLogging(err)
|
||
|
|
}
|
||
|
|
if l.printStack {
|
||
|
|
l.doPrintStack()
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) printf(out io.Writer, skipFrames int, severity string, err error, message string, args ...interface{}) {
|
||
|
|
buf := bufferPool.Get()
|
||
|
|
defer bufferPool.Put(buf)
|
||
|
|
|
||
|
|
GetPrepender()(buf)
|
||
|
|
linePrefix := l.linePrefix(skipFrames)
|
||
|
|
buf.WriteString(severity)
|
||
|
|
buf.WriteString(" ")
|
||
|
|
buf.WriteString(linePrefix)
|
||
|
|
fmt.Fprintf(buf, message, args...)
|
||
|
|
printContext(buf, err)
|
||
|
|
buf.WriteByte('\n')
|
||
|
|
b := []byte(hidden.Clean(buf.String()))
|
||
|
|
_, err2 := out.Write(b)
|
||
|
|
if err2 != nil {
|
||
|
|
errorOnLogging(err2)
|
||
|
|
}
|
||
|
|
if l.printStack {
|
||
|
|
l.doPrintStack()
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) Debug(arg interface{}) {
|
||
|
|
l.print(GetOutputs().DebugOut, 4, "DEBUG", arg)
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) Debugf(message string, args ...interface{}) {
|
||
|
|
l.printf(GetOutputs().DebugOut, 4, "DEBUG", nil, message, args...)
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) Error(arg interface{}) error {
|
||
|
|
return l.errorSkipFrames(arg, 1, ERROR)
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) Errorf(message string, args ...interface{}) error {
|
||
|
|
return l.errorSkipFrames(errors.NewOffset(1, message, args...), 1, ERROR)
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) Fatal(arg interface{}) {
|
||
|
|
fatal(l.errorSkipFrames(arg, 1, FATAL))
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) Fatalf(message string, args ...interface{}) {
|
||
|
|
fatal(l.errorSkipFrames(errors.NewOffset(1, message, args...), 1, FATAL))
|
||
|
|
}
|
||
|
|
|
||
|
|
func fatal(err error) {
|
||
|
|
fn := onFatal.Load().(func(err error))
|
||
|
|
fn(err)
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) errorSkipFrames(arg interface{}, skipFrames int, severity Severity) error {
|
||
|
|
var err error
|
||
|
|
switch e := arg.(type) {
|
||
|
|
case error:
|
||
|
|
err = e
|
||
|
|
default:
|
||
|
|
err = fmt.Errorf("%v", e)
|
||
|
|
}
|
||
|
|
l.print(GetOutputs().ErrorOut, skipFrames+4, severity.String(), err)
|
||
|
|
return report(err, severity)
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) Trace(arg interface{}) {
|
||
|
|
if l.traceOn {
|
||
|
|
l.print(GetOutputs().DebugOut, 4, "TRACE", arg)
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) Tracef(message string, args ...interface{}) {
|
||
|
|
if l.traceOn {
|
||
|
|
l.printf(GetOutputs().DebugOut, 4, "TRACE", nil, message, args...)
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) TraceOut() io.Writer {
|
||
|
|
return l.traceOut
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) IsTraceEnabled() bool {
|
||
|
|
return l.traceOn
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) newTraceWriter() io.Writer {
|
||
|
|
pr, pw := io.Pipe()
|
||
|
|
br := bufio.NewReader(pr)
|
||
|
|
|
||
|
|
if !l.traceOn {
|
||
|
|
return pw
|
||
|
|
}
|
||
|
|
go func() {
|
||
|
|
defer func() {
|
||
|
|
if err := pr.Close(); err != nil {
|
||
|
|
errorOnLogging(err)
|
||
|
|
}
|
||
|
|
}()
|
||
|
|
defer func() {
|
||
|
|
if err := pw.Close(); err != nil {
|
||
|
|
errorOnLogging(err)
|
||
|
|
}
|
||
|
|
}()
|
||
|
|
|
||
|
|
for {
|
||
|
|
line, err := br.ReadString('\n')
|
||
|
|
if err == nil {
|
||
|
|
// Log the line (minus the trailing newline)
|
||
|
|
l.print(GetOutputs().DebugOut, 6, "TRACE", line[:len(line)-1])
|
||
|
|
} else {
|
||
|
|
l.printf(GetOutputs().DebugOut, 6, "TRACE", nil, "TraceWriter closed due to unexpected error: %v", err)
|
||
|
|
return
|
||
|
|
}
|
||
|
|
}
|
||
|
|
}()
|
||
|
|
|
||
|
|
return pw
|
||
|
|
}
|
||
|
|
|
||
|
|
type errorWriter struct {
|
||
|
|
l *logger
|
||
|
|
}
|
||
|
|
|
||
|
|
// Write implements method of io.Writer, due to different call depth,
|
||
|
|
// it will not log correct file and line prefix
|
||
|
|
func (w *errorWriter) Write(p []byte) (n int, err error) {
|
||
|
|
s := string(p)
|
||
|
|
if s[len(s)-1] == '\n' {
|
||
|
|
s = s[:len(s)-1]
|
||
|
|
}
|
||
|
|
w.l.print(GetOutputs().ErrorOut, 6, "ERROR", s)
|
||
|
|
return len(p), nil
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) AsStdLogger() *log.Logger {
|
||
|
|
return log.New(&errorWriter{l}, "", 0)
|
||
|
|
}
|
||
|
|
|
||
|
|
func (l *logger) doPrintStack() {
|
||
|
|
var b []byte
|
||
|
|
buf := bytes.NewBuffer(b)
|
||
|
|
for _, pc := range l.pc {
|
||
|
|
funcForPc := runtime.FuncForPC(pc)
|
||
|
|
if funcForPc == nil {
|
||
|
|
break
|
||
|
|
}
|
||
|
|
name := funcForPc.Name()
|
||
|
|
if strings.HasPrefix(name, "runtime.") {
|
||
|
|
break
|
||
|
|
}
|
||
|
|
file, line := funcForPc.FileLine(pc)
|
||
|
|
fmt.Fprintf(buf, "\t%s\t%s: %d\n", name, file, line)
|
||
|
|
}
|
||
|
|
if _, err := buf.WriteTo(os.Stderr); err != nil {
|
||
|
|
errorOnLogging(err)
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
func errorOnLogging(err error) {
|
||
|
|
fmt.Fprintf(os.Stderr, "Unable to log: %v\n", err)
|
||
|
|
}
|
||
|
|
|
||
|
|
func printContext(buf *bytes.Buffer, err interface{}) {
|
||
|
|
// Note - we don't include globals when printing in order to avoid polluting the text log
|
||
|
|
values := ops.AsMap(err, false)
|
||
|
|
if len(values) == 0 {
|
||
|
|
return
|
||
|
|
}
|
||
|
|
buf.WriteString(" [")
|
||
|
|
var keys []string
|
||
|
|
for key := range values {
|
||
|
|
keys = append(keys, key)
|
||
|
|
}
|
||
|
|
sort.Strings(keys)
|
||
|
|
for i, key := range keys {
|
||
|
|
value := values[key]
|
||
|
|
if i > 0 {
|
||
|
|
buf.WriteString(" ")
|
||
|
|
}
|
||
|
|
buf.WriteString(key)
|
||
|
|
buf.WriteString("=")
|
||
|
|
fmt.Fprintf(buf, "%v", value)
|
||
|
|
}
|
||
|
|
buf.WriteByte(']')
|
||
|
|
}
|
||
|
|
|
||
|
|
func report(err error, severity Severity) error {
|
||
|
|
var reportersCopy []ErrorReporter
|
||
|
|
reportersMutex.RLock()
|
||
|
|
if len(reporters) > 0 {
|
||
|
|
reportersCopy = make([]ErrorReporter, len(reporters))
|
||
|
|
copy(reportersCopy, reporters)
|
||
|
|
}
|
||
|
|
reportersMutex.RUnlock()
|
||
|
|
|
||
|
|
if len(reportersCopy) > 0 {
|
||
|
|
ctx := ops.AsMap(err, true)
|
||
|
|
ctx["severity"] = severity.String()
|
||
|
|
for _, reporter := range reportersCopy {
|
||
|
|
// We include globals when reporting
|
||
|
|
reporter(err, severity, ctx)
|
||
|
|
}
|
||
|
|
}
|
||
|
|
return err
|
||
|
|
}
|