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 }