github.com/justinjmoses/evergreen@v0.0.0-20170530173719-1d50e381ff0d/agent/comm/logger.go (about)

     1  package comm
     2  
     3  import (
     4  	"io"
     5  	"strconv"
     6  	"strings"
     7  	"sync"
     8  	"time"
     9  	"unicode/utf8"
    10  
    11  	"github.com/evergreen-ci/evergreen"
    12  	"github.com/evergreen-ci/evergreen/model"
    13  	"github.com/mongodb/grip"
    14  	"github.com/mongodb/grip/message"
    15  	"github.com/mongodb/grip/send"
    16  	"github.com/mongodb/grip/slogger"
    17  )
    18  
    19  // StreamLogger holds a set of stream-delineated loggers. Each logger is used
    20  // to communicate different kinds of logs to the API Server or local file system.
    21  // StreamLogger is used to distinguish logs of system statistics, shell output,
    22  // and internal agent logs.
    23  type StreamLogger struct {
    24  	// Local is used for file system logging on the host the agent is running on.
    25  	Local *slogger.Logger
    26  	// System is used for logging system stats gotten from commands like df, ps, etc.
    27  	System *slogger.Logger
    28  	// Task is used for logging command input, output and errors of the task.
    29  	Task *slogger.Logger
    30  	// Execution is used for logging the agent's internal state.
    31  	Execution *slogger.Logger
    32  
    33  	// apiLogger is used to send data back to the API server.
    34  	apiLogger APILogger
    35  }
    36  
    37  // GetTaskLogWriter returns an io.Writer of the given level that writes to the task log stream.
    38  func (lgr *StreamLogger) GetTaskLogWriter(level slogger.Level) io.Writer {
    39  	return &evergreen.LoggingWriter{
    40  		Logger:   lgr.Task,
    41  		Severity: level.Priority(),
    42  	}
    43  }
    44  
    45  // GetSystemLogWriter returns an io.Writer of the given level that writes to the system log stream.
    46  func (lgr *StreamLogger) GetSystemLogWriter(level slogger.Level) io.Writer {
    47  	return &evergreen.LoggingWriter{
    48  		Logger:   lgr.System,
    49  		Severity: level.Priority(),
    50  	}
    51  }
    52  
    53  // appendMessages sends a log message to every component sender in a slogger.Logger
    54  func appendMessages(logger *slogger.Logger, msg message.Composer) {
    55  	for _, sender := range logger.Appenders {
    56  		sender.Send(msg)
    57  	}
    58  }
    59  
    60  // LogLocal logs a message to the agent logs on the machine's local file system.
    61  //
    62  // Anything logged by this method will not be sent to the server, so only use it
    63  // to log information that would only be useful when debugging locally.
    64  func (lgr *StreamLogger) LogLocal(level slogger.Level, messageFmt string, args ...interface{}) {
    65  	msg := slogger.NewPrefixedLog(lgr.Local.Name, message.NewFormattedMessage(level.Priority(), messageFmt, args...))
    66  	appendMessages(lgr.Local, msg)
    67  }
    68  
    69  // LogExecution logs a message related to the agent's internal workings.
    70  //
    71  // Internally this is used to log things like heartbeats and command internals that
    72  // would pollute the regular task test output.
    73  func (lgr *StreamLogger) LogExecution(level slogger.Level, messageFmt string, args ...interface{}) {
    74  	msg := slogger.NewPrefixedLog(lgr.Execution.Name, message.NewFormattedMessage(level.Priority(), messageFmt, args...))
    75  	appendMessages(lgr.Execution, msg)
    76  }
    77  
    78  // LogTask logs a message to the task's logs.
    79  //
    80  // This log type is for main task input and output. LogTask should be used for logging
    81  // first-class information like test results and shell script output.
    82  func (lgr *StreamLogger) LogTask(level slogger.Level, messageFmt string, args ...interface{}) {
    83  	msg := slogger.NewPrefixedLog(lgr.Task.Name, message.NewFormattedMessage(level.Priority(), messageFmt, args...))
    84  	appendMessages(lgr.Task, msg)
    85  }
    86  
    87  // LogSystem logs passive system messages.
    88  //
    89  // Internally this is used for periodically logging process information and CPU usage.
    90  func (lgr *StreamLogger) LogSystem(level slogger.Level, messageFmt string, args ...interface{}) {
    91  	msg := slogger.NewPrefixedLog(lgr.System.Name, message.NewFormattedMessage(level.Priority(), messageFmt, args...))
    92  	appendMessages(lgr.System, msg)
    93  }
    94  
    95  // Flush flushes the logs to the server. Returns immediately.
    96  func (lgr *StreamLogger) Flush() {
    97  	lgr.apiLogger.Flush()
    98  }
    99  
   100  // FlushAndWait flushes and blocks until the HTTP request to send the logs has completed.
   101  // This works in contrast with Flush, which triggers the flush asynchronously.
   102  func (lgr *StreamLogger) FlushAndWait() int {
   103  	return lgr.apiLogger.FlushAndWait()
   104  }
   105  
   106  // Wraps an Logger, with additional context about which command is currently being run.
   107  type CommandLogger struct {
   108  	commandName string
   109  	logger      *StreamLogger
   110  }
   111  
   112  func NewCommandLogger(name string, logger *StreamLogger) *CommandLogger {
   113  	return &CommandLogger{name, logger}
   114  }
   115  
   116  func (cmdLgr *CommandLogger) addCommandToMsgAndArgs(messageFmt string, args []interface{}) (string, []interface{}) {
   117  	return "[%v] " + messageFmt, append([]interface{}{cmdLgr.commandName}, args...)
   118  }
   119  
   120  func (cmdLgr *CommandLogger) GetTaskLogWriter(level slogger.Level) io.Writer {
   121  	return cmdLgr.logger.GetTaskLogWriter(level)
   122  }
   123  
   124  func (cmdLgr *CommandLogger) GetSystemLogWriter(level slogger.Level) io.Writer {
   125  	return cmdLgr.logger.GetSystemLogWriter(level)
   126  }
   127  
   128  func (cmdLgr *CommandLogger) LogLocal(level slogger.Level, messageFmt string, args ...interface{}) {
   129  	messageFmt, args = cmdLgr.addCommandToMsgAndArgs(messageFmt, args)
   130  	cmdLgr.logger.LogLocal(level, messageFmt, args...)
   131  }
   132  
   133  func (cmdLgr *CommandLogger) LogExecution(level slogger.Level, messageFmt string, args ...interface{}) {
   134  	messageFmt, args = cmdLgr.addCommandToMsgAndArgs(messageFmt, args)
   135  	cmdLgr.logger.LogExecution(level, messageFmt, args...)
   136  }
   137  
   138  func (cmdLgr *CommandLogger) LogTask(level slogger.Level, messageFmt string, args ...interface{}) {
   139  	messageFmt, args = cmdLgr.addCommandToMsgAndArgs(messageFmt, args)
   140  	cmdLgr.logger.LogTask(level, messageFmt, args...)
   141  }
   142  
   143  func (cmdLgr *CommandLogger) LogSystem(level slogger.Level, messageFmt string, args ...interface{}) {
   144  	messageFmt, args = cmdLgr.addCommandToMsgAndArgs(messageFmt, args)
   145  	cmdLgr.logger.LogSystem(level, messageFmt, args...)
   146  }
   147  
   148  func (cmdLgr *CommandLogger) Flush() {
   149  	cmdLgr.logger.Flush()
   150  }
   151  
   152  // NewStreamLogger creates a StreamLogger wrapper for the apiLogger with a given timeoutWatcher.
   153  // Any logged messages on the StreamLogger will reset the TimeoutWatcher.
   154  func NewStreamLogger(timeoutWatcher *TimeoutWatcher, apiLgr *APILogger) (*StreamLogger, error) {
   155  	defaultLoggers := []send.Sender{slogger.WrapAppender(apiLgr), grip.GetSender()}
   156  	timeoutLogger := slogger.WrapAppender(&TimeoutResetLogger{timeoutWatcher, apiLgr})
   157  
   158  	return &StreamLogger{
   159  		Local: &slogger.Logger{
   160  			Name:      "local",
   161  			Appenders: []send.Sender{grip.GetSender()},
   162  		},
   163  
   164  		System: &slogger.Logger{
   165  			Name:      model.SystemLogPrefix,
   166  			Appenders: defaultLoggers,
   167  		},
   168  
   169  		Task: &slogger.Logger{
   170  			Name:      model.TaskLogPrefix,
   171  			Appenders: []send.Sender{timeoutLogger, grip.GetSender()},
   172  		},
   173  
   174  		Execution: &slogger.Logger{
   175  			Name:      model.AgentLogPrefix,
   176  			Appenders: defaultLoggers,
   177  		},
   178  	}, nil
   179  }
   180  
   181  // TimeoutResetLogger wraps any slogger.Appender and resets a TimeoutWatcher
   182  // each time any log message is appended to it.
   183  type TimeoutResetLogger struct {
   184  	*TimeoutWatcher
   185  	*APILogger
   186  }
   187  
   188  // Append passes the message to the underlying appender, and resets the timeout
   189  func (trLgr *TimeoutResetLogger) Append(log *slogger.Log) error {
   190  	trLgr.TimeoutWatcher.CheckIn()
   191  
   192  	return trLgr.APILogger.Append(log)
   193  }
   194  
   195  // APILogger is a slogger.Appender which makes a call to the
   196  // remote service's log endpoint after SendAfterLines messages have been
   197  // received (or if set, after SendAfterDuration time has passed with no flush).
   198  type APILogger struct {
   199  	// An internal buffer of messages to send.
   200  	messages []model.LogMessage
   201  
   202  	// a mutex to ensure only one flush attempt is in progress at a time.
   203  	flushLock sync.Mutex
   204  
   205  	// mutex to protect appends to the buffer so that messages don't get lost
   206  	// if both a flush/append happen concurrently
   207  	appendLock sync.Mutex
   208  
   209  	// last time flush actually flushed lines
   210  	lastFlush time.Time
   211  
   212  	// The number of log lines that the buffer must reach to trigger a flush
   213  	SendAfterLines int
   214  
   215  	// How long to wait without any flushes before triggering one automatically
   216  	SendAfterDuration time.Duration
   217  
   218  	// Timer to trigger autoflushing based on SendAfterDuration.
   219  	// When set to nil, flushing will only happen when called directly
   220  	// or the SendAfterLines threshold is reached.
   221  	autoFlushTimer *time.Timer
   222  
   223  	// The mechanism for communicating with the remote endpoint.
   224  	TaskCommunicator
   225  }
   226  
   227  // NewAPILogger creates an initialized logger around the given TaskCommunicator.
   228  func NewAPILogger(tc TaskCommunicator) *APILogger {
   229  	sendAfterDuration := 5 * time.Second
   230  	return &APILogger{
   231  		messages:          make([]model.LogMessage, 0, 100),
   232  		flushLock:         sync.Mutex{},
   233  		appendLock:        sync.Mutex{},
   234  		SendAfterLines:    100,
   235  		SendAfterDuration: sendAfterDuration,
   236  		autoFlushTimer:    time.NewTimer(sendAfterDuration),
   237  		TaskCommunicator:  tc,
   238  	}
   239  }
   240  
   241  // Append (to satisfy the Appender interface) adds a log message to the internal
   242  // buffer, and translates the log message into a format that is used by the
   243  // remote endpoint.
   244  func (apiLgr *APILogger) Append(log *slogger.Log) error {
   245  	message := strings.TrimRight(log.Message(), "\r\t")
   246  
   247  	// MCI-972: ensure message is valid UTF-8
   248  	if !utf8.ValidString(message) {
   249  		message = strconv.QuoteToASCII(message)
   250  	}
   251  
   252  	logMessage := &model.LogMessage{
   253  		Timestamp: log.Timestamp,
   254  		Severity:  levelToString(log.Level),
   255  		Type:      log.Prefix,
   256  		Version:   evergreen.LogmessageCurrentVersion,
   257  		Message:   message,
   258  	}
   259  
   260  	apiLgr.appendLock.Lock()
   261  	defer apiLgr.appendLock.Unlock()
   262  	apiLgr.messages = append(apiLgr.messages, *logMessage)
   263  
   264  	if len(apiLgr.messages) < apiLgr.SendAfterLines ||
   265  		time.Since(apiLgr.lastFlush) < apiLgr.SendAfterDuration {
   266  		return nil
   267  	}
   268  
   269  	apiLgr.flushInternal()
   270  
   271  	return nil
   272  }
   273  
   274  func (apiLgr *APILogger) sendLogs(flushMsgs []model.LogMessage) int {
   275  	start := time.Now()
   276  	apiLgr.flushLock.Lock()
   277  	defer apiLgr.flushLock.Unlock()
   278  	if len(flushMsgs) == 0 {
   279  		return 0
   280  	}
   281  
   282  	grip.CatchError(apiLgr.TaskCommunicator.Log(flushMsgs))
   283  	grip.Infof("sent %d log messages to api server, in %s",
   284  		len(flushMsgs), time.Since(start))
   285  	return len(flushMsgs)
   286  }
   287  
   288  func (apiLgr *APILogger) FlushAndWait() int {
   289  	apiLgr.appendLock.Lock()
   290  	defer apiLgr.appendLock.Unlock()
   291  
   292  	apiLgr.lastFlush = time.Now()
   293  	if len(apiLgr.messages) == 0 {
   294  		return 0
   295  	}
   296  
   297  	numMessages := apiLgr.sendLogs(apiLgr.messages)
   298  	apiLgr.messages = make([]model.LogMessage, 0, apiLgr.SendAfterLines)
   299  
   300  	return numMessages
   301  }
   302  
   303  // flushInternal assumes that the caller already holds apiLgr.appendLock
   304  func (apiLgr *APILogger) flushInternal() {
   305  	apiLgr.lastFlush = time.Now()
   306  
   307  	messagesToSend := make([]model.LogMessage, len(apiLgr.messages))
   308  	copy(messagesToSend, apiLgr.messages)
   309  	apiLgr.messages = make([]model.LogMessage, 0, apiLgr.SendAfterLines)
   310  
   311  	go apiLgr.sendLogs(messagesToSend)
   312  }
   313  
   314  // Flush pushes log messages (asynchronously, without waiting for messages to send.)
   315  func (apiLgr *APILogger) Flush() {
   316  	apiLgr.appendLock.Lock()
   317  	defer apiLgr.appendLock.Unlock()
   318  
   319  	apiLgr.flushInternal()
   320  }
   321  
   322  func levelToString(level slogger.Level) string {
   323  	switch level {
   324  	case slogger.DEBUG:
   325  		return model.LogDebugPrefix
   326  	case slogger.INFO:
   327  		return model.LogInfoPrefix
   328  	case slogger.WARN:
   329  		return model.LogWarnPrefix
   330  	case slogger.ERROR:
   331  		return model.LogErrorPrefix
   332  	}
   333  	return "UNKNOWN"
   334  }