boulder/log/log.go

package log

import (
	"encoding/base64"
	"encoding/binary"
	"encoding/json"
	"errors"
	"fmt"
	"hash/crc32"
	"io"
	"log/syslog"
	"os"
	"strings"
	"sync"

	"github.com/jmhodges/clock"
	"golang.org/x/term"

	"github.com/letsencrypt/boulder/core"
)

// A Logger logs messages with explicit priority levels. It is
// implemented by a logging back-end as provided by New() or
// NewMock(). Any additions to this interface with format strings should be
// added to the govet configuration in .golangci.yml
type Logger interface {
	Err(msg string)
	Errf(format string, a ...interface{})
	Warning(msg string)
	Warningf(format string, a ...interface{})
	Info(msg string)
	Infof(format string, a ...interface{})
	InfoObject(string, interface{})
	Debug(msg string)
	Debugf(format string, a ...interface{})
	AuditInfo(msg string)
	AuditInfof(format string, a ...interface{})
	AuditObject(string, interface{})
	AuditErr(string)
	AuditErrf(format string, a ...interface{})
}

// impl implements Logger.
type impl struct {
	w writer
}

// singleton defines the object of a Singleton pattern
type singleton struct {
	once sync.Once
	log  Logger
}

// _Singleton is the single impl entity in memory
var _Singleton singleton

// The constant used to identify audit-specific messages
const auditTag = "[AUDIT]"

// New returns a new Logger that uses the given syslog.Writer as a backend
// and also writes to stdout/stderr. It is safe for concurrent use.
func New(log *syslog.Writer, stdoutLogLevel int, syslogLogLevel int) (Logger, error) {
	if log == nil {
		return nil, errors.New("Attempted to use a nil System Logger")
	}
	return &impl{
		&bothWriter{
			sync.Mutex{},
			log,
			newStdoutWriter(stdoutLogLevel),
			syslogLogLevel,
		},
	}, nil
}

// StdoutLogger returns a Logger that writes solely to stdout and stderr.
// It is safe for concurrent use.
func StdoutLogger(level int) Logger {
	return &impl{newStdoutWriter(level)}
}

func newStdoutWriter(level int) *stdoutWriter {
	prefix, clkFormat := getPrefix()
	return &stdoutWriter{
		prefix:    prefix,
		level:     level,
		clkFormat: clkFormat,
		clk:       clock.New(),
		stdout:    os.Stdout,
		stderr:    os.Stderr,
		isatty:    term.IsTerminal(int(os.Stdout.Fd())),
	}
}

// initialize is used in unit tests and called by `Get` before the logger
// is fully set up.
func initialize() {
	const defaultPriority = syslog.LOG_INFO | syslog.LOG_LOCAL0
	syslogger, err := syslog.Dial("", "", defaultPriority, "test")
	if err != nil {
		panic(err)
	}
	logger, err := New(syslogger, int(syslog.LOG_DEBUG), int(syslog.LOG_DEBUG))
	if err != nil {
		panic(err)
	}

	_ = Set(logger)
}

// Set configures the singleton Logger. This method
// must only be called once, and before calling Get the
// first time.
func Set(logger Logger) (err error) {
	if _Singleton.log != nil {
		err = errors.New("You may not call Set after it has already been implicitly or explicitly set")
		_Singleton.log.Warning(err.Error())
	} else {
		_Singleton.log = logger
	}
	return
}

// Get obtains the singleton Logger. If Set has not been called first, this
// method initializes with basic defaults.  The basic defaults cannot error, and
// subsequent access to an already-set Logger also cannot error, so this method is
// error-safe.
func Get() Logger {
	_Singleton.once.Do(func() {
		if _Singleton.log == nil {
			initialize()
		}
	})

	return _Singleton.log
}

type writer interface {
	logAtLevel(syslog.Priority, string, ...interface{})
}

// bothWriter implements writer and writes to both syslog and stdout.
type bothWriter struct {
	sync.Mutex
	*syslog.Writer
	*stdoutWriter
	syslogLevel int
}

// stdoutWriter implements writer and writes just to stdout.
type stdoutWriter struct {
	// prefix is a set of information that is the same for every log line,
	// imitating what syslog emits for us when we use the syslog writer.
	prefix    string
	level     int
	clkFormat string
	clk       clock.Clock
	stdout    io.Writer
	stderr    io.Writer
	isatty    bool
}

func LogLineChecksum(line string) string {
	crc := crc32.ChecksumIEEE([]byte(line))
	// Using the hash.Hash32 doesn't make this any easier
	// as it also returns a uint32 rather than []byte
	buf := make([]byte, binary.MaxVarintLen32)
	binary.PutUvarint(buf, uint64(crc))
	return base64.RawURLEncoding.EncodeToString(buf)
}

func checkSummed(msg string) string {
	return fmt.Sprintf("%s %s", LogLineChecksum(msg), msg)
}

// logAtLevel logs the provided message at the appropriate level, writing to
// both stdout and the Logger
func (w *bothWriter) logAtLevel(level syslog.Priority, msg string, a ...interface{}) {
	var err error

	// Apply conditional formatting for f functions
	if a != nil {
		msg = fmt.Sprintf(msg, a...)
	}

	// Since messages are delimited by newlines, we have to escape any internal or
	// trailing newlines before generating the checksum or outputting the message.
	msg = strings.Replace(msg, "\n", "\\n", -1)

	w.Lock()
	defer w.Unlock()

	switch syslogAllowed := int(level) <= w.syslogLevel; level {
	case syslog.LOG_ERR:
		if syslogAllowed {
			err = w.Err(checkSummed(msg))
		}
	case syslog.LOG_WARNING:
		if syslogAllowed {
			err = w.Warning(checkSummed(msg))
		}
	case syslog.LOG_INFO:
		if syslogAllowed {
			err = w.Info(checkSummed(msg))
		}
	case syslog.LOG_DEBUG:
		if syslogAllowed {
			err = w.Debug(checkSummed(msg))
		}
	default:
		err = w.Err(fmt.Sprintf("%s (unknown logging level: %d)", checkSummed(msg), int(level)))
	}

	if err != nil {
		fmt.Fprintf(os.Stderr, "Failed to write to syslog: %d %s (%s)\n", int(level), checkSummed(msg), err)
	}

	w.stdoutWriter.logAtLevel(level, msg)
}

// logAtLevel logs the provided message to stdout, or stderr if it is at Warning or Error level.
func (w *stdoutWriter) logAtLevel(level syslog.Priority, msg string, a ...interface{}) {
	if int(level) <= w.level {
		output := w.stdout
		if int(level) <= int(syslog.LOG_WARNING) {
			output = w.stderr
		}

		// Apply conditional formatting for f functions
		if a != nil {
			msg = fmt.Sprintf(msg, a...)
		}

		msg = strings.Replace(msg, "\n", "\\n", -1)

		var color string
		var reset string

		const red = "\033[31m\033[1m"
		const yellow = "\033[33m"
		const gray = "\033[37m\033[2m"

		if w.isatty {
			if int(level) == int(syslog.LOG_DEBUG) {
				color = gray
				reset = "\033[0m"
			} else if int(level) == int(syslog.LOG_WARNING) {
				color = yellow
				reset = "\033[0m"
			} else if int(level) <= int(syslog.LOG_ERR) {
				color = red
				reset = "\033[0m"
			}
		}

		if _, err := fmt.Fprintf(output, "%s%s %s%d %s %s%s\n",
			color,
			w.clk.Now().UTC().Format(w.clkFormat),
			w.prefix,
			int(level),
			core.Command(),
			checkSummed(msg),
			reset); err != nil {
			panic(fmt.Sprintf("failed to write to stdout: %v\n", err))
		}
	}
}

func (log *impl) auditAtLevel(level syslog.Priority, msg string, a ...interface{}) {
	msg = fmt.Sprintf("%s %s", auditTag, msg)
	log.w.logAtLevel(level, msg, a...)
}

// Err level messages are always marked with the audit tag, for special handling
// at the upstream system logger.
func (log *impl) Err(msg string) {
	log.Errf(msg)
}

// Errf level messages are always marked with the audit tag, for special handling
// at the upstream system logger.
func (log *impl) Errf(format string, a ...interface{}) {
	log.auditAtLevel(syslog.LOG_ERR, format, a...)
}

// Warning level messages pass through normally.
func (log *impl) Warning(msg string) {
	log.Warningf(msg)
}

// Warningf level messages pass through normally.
func (log *impl) Warningf(format string, a ...interface{}) {
	log.w.logAtLevel(syslog.LOG_WARNING, format, a...)
}

// Info level messages pass through normally.
func (log *impl) Info(msg string) {
	log.Infof(msg)
}

// Infof level messages pass through normally.
func (log *impl) Infof(format string, a ...interface{}) {
	log.w.logAtLevel(syslog.LOG_INFO, format, a...)
}

// InfoObject logs an INFO level JSON-serialized object message.
func (log *impl) InfoObject(msg string, obj interface{}) {
	jsonObj, err := json.Marshal(obj)
	if err != nil {
		log.auditAtLevel(syslog.LOG_ERR, fmt.Sprintf("Object for msg %q could not be serialized to JSON. Raw: %+v", msg, obj))
		return
	}

	log.Infof("%s JSON=%s", msg, jsonObj)
}

// Debug level messages pass through normally.
func (log *impl) Debug(msg string) {
	log.Debugf(msg)

}

// Debugf level messages pass through normally.
func (log *impl) Debugf(format string, a ...interface{}) {
	log.w.logAtLevel(syslog.LOG_DEBUG, format, a...)
}

// AuditInfo sends an INFO-severity message that is prefixed with the
// audit tag, for special handling at the upstream system logger.
func (log *impl) AuditInfo(msg string) {
	log.AuditInfof(msg)
}

// AuditInfof sends an INFO-severity message that is prefixed with the
// audit tag, for special handling at the upstream system logger.
func (log *impl) AuditInfof(format string, a ...interface{}) {
	log.auditAtLevel(syslog.LOG_INFO, format, a...)
}

// AuditObject sends an INFO-severity JSON-serialized object message that is prefixed
// with the audit tag, for special handling at the upstream system logger.
func (log *impl) AuditObject(msg string, obj interface{}) {
	jsonObj, err := json.Marshal(obj)
	if err != nil {
		log.auditAtLevel(syslog.LOG_ERR, fmt.Sprintf("Object for msg %q could not be serialized to JSON. Raw: %+v", msg, obj))
		return
	}

	log.auditAtLevel(syslog.LOG_INFO, fmt.Sprintf("%s JSON=%s", msg, jsonObj))
}

// AuditErr can format an error for auditing; it does so at ERR level.
func (log *impl) AuditErr(msg string) {
	log.AuditErrf(msg)
}

// AuditErrf can format an error for auditing; it does so at ERR level.
func (log *impl) AuditErrf(format string, a ...interface{}) {
	log.auditAtLevel(syslog.LOG_ERR, format, a...)
}