log.go

Documentation: github.com/letsencrypt/boulder/log

     1  package log
     2  
     3  import (
     4  	"encoding/base64"
     5  	"encoding/binary"
     6  	"encoding/json"
     7  	"errors"
     8  	"fmt"
     9  	"hash/crc32"
    10  	"io"
    11  	"log/syslog"
    12  	"os"
    13  	"strings"
    14  	"sync"
    15  
    16  	"github.com/jmhodges/clock"
    17  	"golang.org/x/term"
    18  
    19  	"github.com/letsencrypt/boulder/core"
    20  )
    21  
    22  // A Logger logs messages with explicit priority levels. It is
    23  // implemented by a logging back-end as provided by New() or
    24  // NewMock(). Any additions to this interface with format strings should be
    25  // added to the govet configuration in .golangci.yml
    26  type Logger interface {
    27  	Err(msg string)
    28  	Errf(format string, a ...interface{})
    29  	Warning(msg string)
    30  	Warningf(format string, a ...interface{})
    31  	Info(msg string)
    32  	Infof(format string, a ...interface{})
    33  	InfoObject(string, interface{})
    34  	Debug(msg string)
    35  	Debugf(format string, a ...interface{})
    36  	AuditInfo(msg string)
    37  	AuditInfof(format string, a ...interface{})
    38  	AuditObject(string, interface{})
    39  	AuditErr(string)
    40  	AuditErrf(format string, a ...interface{})
    41  }
    42  
    43  // impl implements Logger.
    44  type impl struct {
    45  	w writer
    46  }
    47  
    48  // singleton defines the object of a Singleton pattern
    49  type singleton struct {
    50  	once sync.Once
    51  	log  Logger
    52  }
    53  
    54  // _Singleton is the single impl entity in memory
    55  var _Singleton singleton
    56  
    57  // The constant used to identify audit-specific messages
    58  const auditTag = "[AUDIT]"
    59  
    60  // New returns a new Logger that uses the given syslog.Writer as a backend
    61  // and also writes to stdout/stderr. It is safe for concurrent use.
    62  func New(log *syslog.Writer, stdoutLogLevel int, syslogLogLevel int) (Logger, error) {
    63  	if log == nil {
    64  		return nil, errors.New("Attempted to use a nil System Logger")
    65  	}
    66  	return &impl{
    67  		&bothWriter{
    68  			sync.Mutex{},
    69  			log,
    70  			newStdoutWriter(stdoutLogLevel),
    71  			syslogLogLevel,
    72  		},
    73  	}, nil
    74  }
    75  
    76  // StdoutLogger returns a Logger that writes solely to stdout and stderr.
    77  // It is safe for concurrent use.
    78  func StdoutLogger(level int) Logger {
    79  	return &impl{newStdoutWriter(level)}
    80  }
    81  
    82  func newStdoutWriter(level int) *stdoutWriter {
    83  	prefix, clkFormat := getPrefix()
    84  	return &stdoutWriter{
    85  		prefix:    prefix,
    86  		level:     level,
    87  		clkFormat: clkFormat,
    88  		clk:       clock.New(),
    89  		stdout:    os.Stdout,
    90  		stderr:    os.Stderr,
    91  		isatty:    term.IsTerminal(int(os.Stdout.Fd())),
    92  	}
    93  }
    94  
    95  // initialize is used in unit tests and called by `Get` before the logger
    96  // is fully set up.
    97  func initialize() {
    98  	const defaultPriority = syslog.LOG_INFO | syslog.LOG_LOCAL0
    99  	syslogger, err := syslog.Dial("", "", defaultPriority, "test")
   100  	if err != nil {
   101  		panic(err)
   102  	}
   103  	logger, err := New(syslogger, int(syslog.LOG_DEBUG), int(syslog.LOG_DEBUG))
   104  	if err != nil {
   105  		panic(err)
   106  	}
   107  
   108  	_ = Set(logger)
   109  }
   110  
   111  // Set configures the singleton Logger. This method
   112  // must only be called once, and before calling Get the
   113  // first time.
   114  func Set(logger Logger) (err error) {
   115  	if _Singleton.log != nil {
   116  		err = errors.New("You may not call Set after it has already been implicitly or explicitly set")
   117  		_Singleton.log.Warning(err.Error())
   118  	} else {
   119  		_Singleton.log = logger
   120  	}
   121  	return
   122  }
   123  
   124  // Get obtains the singleton Logger. If Set has not been called first, this
   125  // method initializes with basic defaults.  The basic defaults cannot error, and
   126  // subsequent access to an already-set Logger also cannot error, so this method is
   127  // error-safe.
   128  func Get() Logger {
   129  	_Singleton.once.Do(func() {
   130  		if _Singleton.log == nil {
   131  			initialize()
   132  		}
   133  	})
   134  
   135  	return _Singleton.log
   136  }
   137  
   138  type writer interface {
   139  	logAtLevel(syslog.Priority, string, ...interface{})
   140  }
   141  
   142  // bothWriter implements writer and writes to both syslog and stdout.
   143  type bothWriter struct {
   144  	sync.Mutex
   145  	*syslog.Writer
   146  	*stdoutWriter
   147  	syslogLevel int
   148  }
   149  
   150  // stdoutWriter implements writer and writes just to stdout.
   151  type stdoutWriter struct {
   152  	// prefix is a set of information that is the same for every log line,
   153  	// imitating what syslog emits for us when we use the syslog writer.
   154  	prefix    string
   155  	level     int
   156  	clkFormat string
   157  	clk       clock.Clock
   158  	stdout    io.Writer
   159  	stderr    io.Writer
   160  	isatty    bool
   161  }
   162  
   163  func LogLineChecksum(line string) string {
   164  	crc := crc32.ChecksumIEEE([]byte(line))
   165  	// Using the hash.Hash32 doesn't make this any easier
   166  	// as it also returns a uint32 rather than []byte
   167  	buf := make([]byte, binary.MaxVarintLen32)
   168  	binary.PutUvarint(buf, uint64(crc))
   169  	return base64.RawURLEncoding.EncodeToString(buf)
   170  }
   171  
   172  func checkSummed(msg string) string {
   173  	return fmt.Sprintf("%s %s", LogLineChecksum(msg), msg)
   174  }
   175  
   176  // logAtLevel logs the provided message at the appropriate level, writing to
   177  // both stdout and the Logger
   178  func (w *bothWriter) logAtLevel(level syslog.Priority, msg string, a ...interface{}) {
   179  	var err error
   180  
   181  	// Apply conditional formatting for f functions
   182  	if a != nil {
   183  		msg = fmt.Sprintf(msg, a...)
   184  	}
   185  
   186  	// Since messages are delimited by newlines, we have to escape any internal or
   187  	// trailing newlines before generating the checksum or outputting the message.
   188  	msg = strings.Replace(msg, "\n", "\\n", -1)
   189  
   190  	w.Lock()
   191  	defer w.Unlock()
   192  
   193  	switch syslogAllowed := int(level) <= w.syslogLevel; level {
   194  	case syslog.LOG_ERR:
   195  		if syslogAllowed {
   196  			err = w.Err(checkSummed(msg))
   197  		}
   198  	case syslog.LOG_WARNING:
   199  		if syslogAllowed {
   200  			err = w.Warning(checkSummed(msg))
   201  		}
   202  	case syslog.LOG_INFO:
   203  		if syslogAllowed {
   204  			err = w.Info(checkSummed(msg))
   205  		}
   206  	case syslog.LOG_DEBUG:
   207  		if syslogAllowed {
   208  			err = w.Debug(checkSummed(msg))
   209  		}
   210  	default:
   211  		err = w.Err(fmt.Sprintf("%s (unknown logging level: %d)", checkSummed(msg), int(level)))
   212  	}
   213  
   214  	if err != nil {
   215  		fmt.Fprintf(os.Stderr, "Failed to write to syslog: %d %s (%s)\n", int(level), checkSummed(msg), err)
   216  	}
   217  
   218  	w.stdoutWriter.logAtLevel(level, msg)
   219  }
   220  
   221  // logAtLevel logs the provided message to stdout, or stderr if it is at Warning or Error level.
   222  func (w *stdoutWriter) logAtLevel(level syslog.Priority, msg string, a ...interface{}) {
   223  	if int(level) <= w.level {
   224  		output := w.stdout
   225  		if int(level) <= int(syslog.LOG_WARNING) {
   226  			output = w.stderr
   227  		}
   228  
   229  		// Apply conditional formatting for f functions
   230  		if a != nil {
   231  			msg = fmt.Sprintf(msg, a...)
   232  		}
   233  
   234  		msg = strings.Replace(msg, "\n", "\\n", -1)
   235  
   236  		var color string
   237  		var reset string
   238  
   239  		const red = "\033[31m\033[1m"
   240  		const yellow = "\033[33m"
   241  		const gray = "\033[37m\033[2m"
   242  
   243  		if w.isatty {
   244  			if int(level) == int(syslog.LOG_DEBUG) {
   245  				color = gray
   246  				reset = "\033[0m"
   247  			} else if int(level) == int(syslog.LOG_WARNING) {
   248  				color = yellow
   249  				reset = "\033[0m"
   250  			} else if int(level) <= int(syslog.LOG_ERR) {
   251  				color = red
   252  				reset = "\033[0m"
   253  			}
   254  		}
   255  
   256  		if _, err := fmt.Fprintf(output, "%s%s %s%d %s %s%s\n",
   257  			color,
   258  			w.clk.Now().UTC().Format(w.clkFormat),
   259  			w.prefix,
   260  			int(level),
   261  			core.Command(),
   262  			checkSummed(msg),
   263  			reset); err != nil {
   264  			panic(fmt.Sprintf("failed to write to stdout: %v\n", err))
   265  		}
   266  	}
   267  }
   268  
   269  func (log *impl) auditAtLevel(level syslog.Priority, msg string, a ...interface{}) {
   270  	msg = fmt.Sprintf("%s %s", auditTag, msg)
   271  	log.w.logAtLevel(level, msg, a...)
   272  }
   273  
   274  // Err level messages are always marked with the audit tag, for special handling
   275  // at the upstream system logger.
   276  func (log *impl) Err(msg string) {
   277  	log.Errf(msg)
   278  }
   279  
   280  // Errf level messages are always marked with the audit tag, for special handling
   281  // at the upstream system logger.
   282  func (log *impl) Errf(format string, a ...interface{}) {
   283  	log.auditAtLevel(syslog.LOG_ERR, format, a...)
   284  }
   285  
   286  // Warning level messages pass through normally.
   287  func (log *impl) Warning(msg string) {
   288  	log.Warningf(msg)
   289  }
   290  
   291  // Warningf level messages pass through normally.
   292  func (log *impl) Warningf(format string, a ...interface{}) {
   293  	log.w.logAtLevel(syslog.LOG_WARNING, format, a...)
   294  }
   295  
   296  // Info level messages pass through normally.
   297  func (log *impl) Info(msg string) {
   298  	log.Infof(msg)
   299  }
   300  
   301  // Infof level messages pass through normally.
   302  func (log *impl) Infof(format string, a ...interface{}) {
   303  	log.w.logAtLevel(syslog.LOG_INFO, format, a...)
   304  }
   305  
   306  // InfoObject logs an INFO level JSON-serialized object message.
   307  func (log *impl) InfoObject(msg string, obj interface{}) {
   308  	jsonObj, err := json.Marshal(obj)
   309  	if err != nil {
   310  		log.auditAtLevel(syslog.LOG_ERR, fmt.Sprintf("Object for msg %q could not be serialized to JSON. Raw: %+v", msg, obj))
   311  		return
   312  	}
   313  
   314  	log.Infof("%s JSON=%s", msg, jsonObj)
   315  }
   316  
   317  // Debug level messages pass through normally.
   318  func (log *impl) Debug(msg string) {
   319  	log.Debugf(msg)
   320  
   321  }
   322  
   323  // Debugf level messages pass through normally.
   324  func (log *impl) Debugf(format string, a ...interface{}) {
   325  	log.w.logAtLevel(syslog.LOG_DEBUG, format, a...)
   326  }
   327  
   328  // AuditInfo sends an INFO-severity message that is prefixed with the
   329  // audit tag, for special handling at the upstream system logger.
   330  func (log *impl) AuditInfo(msg string) {
   331  	log.AuditInfof(msg)
   332  }
   333  
   334  // AuditInfof sends an INFO-severity message that is prefixed with the
   335  // audit tag, for special handling at the upstream system logger.
   336  func (log *impl) AuditInfof(format string, a ...interface{}) {
   337  	log.auditAtLevel(syslog.LOG_INFO, format, a...)
   338  }
   339  
   340  // AuditObject sends an INFO-severity JSON-serialized object message that is prefixed
   341  // with the audit tag, for special handling at the upstream system logger.
   342  func (log *impl) AuditObject(msg string, obj interface{}) {
   343  	jsonObj, err := json.Marshal(obj)
   344  	if err != nil {
   345  		log.auditAtLevel(syslog.LOG_ERR, fmt.Sprintf("Object for msg %q could not be serialized to JSON. Raw: %+v", msg, obj))
   346  		return
   347  	}
   348  
   349  	log.auditAtLevel(syslog.LOG_INFO, fmt.Sprintf("%s JSON=%s", msg, jsonObj))
   350  }
   351  
   352  // AuditErr can format an error for auditing; it does so at ERR level.
   353  func (log *impl) AuditErr(msg string) {
   354  	log.AuditErrf(msg)
   355  }
   356  
   357  // AuditErrf can format an error for auditing; it does so at ERR level.
   358  func (log *impl) AuditErrf(format string, a ...interface{}) {
   359  	log.auditAtLevel(syslog.LOG_ERR, format, a...)
   360  }
   361
View as plain text