1package hclog 2 3import ( 4 "bytes" 5 "encoding" 6 "encoding/json" 7 "fmt" 8 "io" 9 "log" 10 "reflect" 11 "runtime" 12 "sort" 13 "strconv" 14 "strings" 15 "sync" 16 "sync/atomic" 17 "time" 18) 19 20// TimeFormat to use for logging. This is a version of RFC3339 that contains 21// contains millisecond precision 22const TimeFormat = "2006-01-02T15:04:05.000Z0700" 23 24// errJsonUnsupportedTypeMsg is included in log json entries, if an arg cannot be serialized to json 25const errJsonUnsupportedTypeMsg = "logging contained values that don't serialize to json" 26 27var ( 28 _levelToBracket = map[Level]string{ 29 Debug: "[DEBUG]", 30 Trace: "[TRACE]", 31 Info: "[INFO] ", 32 Warn: "[WARN] ", 33 Error: "[ERROR]", 34 } 35) 36 37// Make sure that intLogger is a Logger 38var _ Logger = &intLogger{} 39 40// intLogger is an internal logger implementation. Internal in that it is 41// defined entirely by this package. 42type intLogger struct { 43 json bool 44 caller bool 45 name string 46 timeFormat string 47 48 // This is a pointer so that it's shared by any derived loggers, since 49 // those derived loggers share the bufio.Writer as well. 50 mutex *sync.Mutex 51 writer *writer 52 level *int32 53 54 implied []interface{} 55} 56 57// New returns a configured logger. 58func New(opts *LoggerOptions) Logger { 59 if opts == nil { 60 opts = &LoggerOptions{} 61 } 62 63 output := opts.Output 64 if output == nil { 65 output = DefaultOutput 66 } 67 68 level := opts.Level 69 if level == NoLevel { 70 level = DefaultLevel 71 } 72 73 mutex := opts.Mutex 74 if mutex == nil { 75 mutex = new(sync.Mutex) 76 } 77 78 l := &intLogger{ 79 json: opts.JSONFormat, 80 caller: opts.IncludeLocation, 81 name: opts.Name, 82 timeFormat: TimeFormat, 83 mutex: mutex, 84 writer: newWriter(output), 85 level: new(int32), 86 } 87 88 if opts.TimeFormat != "" { 89 l.timeFormat = opts.TimeFormat 90 } 91 92 atomic.StoreInt32(l.level, int32(level)) 93 94 return l 95} 96 97// Log a message and a set of key/value pairs if the given level is at 98// or more severe that the threshold configured in the Logger. 99func (l *intLogger) Log(level Level, msg string, args ...interface{}) { 100 if level < Level(atomic.LoadInt32(l.level)) { 101 return 102 } 103 104 t := time.Now() 105 106 l.mutex.Lock() 107 defer l.mutex.Unlock() 108 109 if l.json { 110 l.logJSON(t, level, msg, args...) 111 } else { 112 l.log(t, level, msg, args...) 113 } 114 115 l.writer.Flush(level) 116} 117 118// Cleanup a path by returning the last 2 segments of the path only. 119func trimCallerPath(path string) string { 120 // lovely borrowed from zap 121 // nb. To make sure we trim the path correctly on Windows too, we 122 // counter-intuitively need to use '/' and *not* os.PathSeparator here, 123 // because the path given originates from Go stdlib, specifically 124 // runtime.Caller() which (as of Mar/17) returns forward slashes even on 125 // Windows. 126 // 127 // See https://github.com/golang/go/issues/3335 128 // and https://github.com/golang/go/issues/18151 129 // 130 // for discussion on the issue on Go side. 131 132 // Find the last separator. 133 idx := strings.LastIndexByte(path, '/') 134 if idx == -1 { 135 return path 136 } 137 138 // Find the penultimate separator. 139 idx = strings.LastIndexByte(path[:idx], '/') 140 if idx == -1 { 141 return path 142 } 143 144 return path[idx+1:] 145} 146 147// Non-JSON logging format function 148func (l *intLogger) log(t time.Time, level Level, msg string, args ...interface{}) { 149 l.writer.WriteString(t.Format(l.timeFormat)) 150 l.writer.WriteByte(' ') 151 152 s, ok := _levelToBracket[level] 153 if ok { 154 l.writer.WriteString(s) 155 } else { 156 l.writer.WriteString("[?????]") 157 } 158 159 if l.caller { 160 if _, file, line, ok := runtime.Caller(3); ok { 161 l.writer.WriteByte(' ') 162 l.writer.WriteString(trimCallerPath(file)) 163 l.writer.WriteByte(':') 164 l.writer.WriteString(strconv.Itoa(line)) 165 l.writer.WriteByte(':') 166 } 167 } 168 169 l.writer.WriteByte(' ') 170 171 if l.name != "" { 172 l.writer.WriteString(l.name) 173 l.writer.WriteString(": ") 174 } 175 176 l.writer.WriteString(msg) 177 178 args = append(l.implied, args...) 179 180 var stacktrace CapturedStacktrace 181 182 if args != nil && len(args) > 0 { 183 if len(args)%2 != 0 { 184 cs, ok := args[len(args)-1].(CapturedStacktrace) 185 if ok { 186 args = args[:len(args)-1] 187 stacktrace = cs 188 } else { 189 args = append(args, "<unknown>") 190 } 191 } 192 193 l.writer.WriteByte(':') 194 195 FOR: 196 for i := 0; i < len(args); i = i + 2 { 197 var ( 198 val string 199 raw bool 200 ) 201 202 switch st := args[i+1].(type) { 203 case string: 204 val = st 205 case int: 206 val = strconv.FormatInt(int64(st), 10) 207 case int64: 208 val = strconv.FormatInt(int64(st), 10) 209 case int32: 210 val = strconv.FormatInt(int64(st), 10) 211 case int16: 212 val = strconv.FormatInt(int64(st), 10) 213 case int8: 214 val = strconv.FormatInt(int64(st), 10) 215 case uint: 216 val = strconv.FormatUint(uint64(st), 10) 217 case uint64: 218 val = strconv.FormatUint(uint64(st), 10) 219 case uint32: 220 val = strconv.FormatUint(uint64(st), 10) 221 case uint16: 222 val = strconv.FormatUint(uint64(st), 10) 223 case uint8: 224 val = strconv.FormatUint(uint64(st), 10) 225 case CapturedStacktrace: 226 stacktrace = st 227 continue FOR 228 case Format: 229 val = fmt.Sprintf(st[0].(string), st[1:]...) 230 default: 231 v := reflect.ValueOf(st) 232 if v.Kind() == reflect.Slice { 233 val = l.renderSlice(v) 234 raw = true 235 } else { 236 val = fmt.Sprintf("%v", st) 237 } 238 } 239 240 l.writer.WriteByte(' ') 241 l.writer.WriteString(args[i].(string)) 242 l.writer.WriteByte('=') 243 244 if !raw && strings.ContainsAny(val, " \t\n\r") { 245 l.writer.WriteByte('"') 246 l.writer.WriteString(val) 247 l.writer.WriteByte('"') 248 } else { 249 l.writer.WriteString(val) 250 } 251 } 252 } 253 254 l.writer.WriteString("\n") 255 256 if stacktrace != "" { 257 l.writer.WriteString(string(stacktrace)) 258 } 259} 260 261func (l *intLogger) renderSlice(v reflect.Value) string { 262 var buf bytes.Buffer 263 264 buf.WriteRune('[') 265 266 for i := 0; i < v.Len(); i++ { 267 if i > 0 { 268 buf.WriteString(", ") 269 } 270 271 sv := v.Index(i) 272 273 var val string 274 275 switch sv.Kind() { 276 case reflect.String: 277 val = sv.String() 278 case reflect.Int, reflect.Int16, reflect.Int32, reflect.Int64: 279 val = strconv.FormatInt(sv.Int(), 10) 280 case reflect.Uint, reflect.Uint16, reflect.Uint32, reflect.Uint64: 281 val = strconv.FormatUint(sv.Uint(), 10) 282 default: 283 val = fmt.Sprintf("%v", sv.Interface()) 284 } 285 286 if strings.ContainsAny(val, " \t\n\r") { 287 buf.WriteByte('"') 288 buf.WriteString(val) 289 buf.WriteByte('"') 290 } else { 291 buf.WriteString(val) 292 } 293 } 294 295 buf.WriteRune(']') 296 297 return buf.String() 298} 299 300// JSON logging function 301func (l *intLogger) logJSON(t time.Time, level Level, msg string, args ...interface{}) { 302 vals := l.jsonMapEntry(t, level, msg) 303 args = append(l.implied, args...) 304 305 if args != nil && len(args) > 0 { 306 if len(args)%2 != 0 { 307 cs, ok := args[len(args)-1].(CapturedStacktrace) 308 if ok { 309 args = args[:len(args)-1] 310 vals["stacktrace"] = cs 311 } else { 312 args = append(args, "<unknown>") 313 } 314 } 315 316 for i := 0; i < len(args); i = i + 2 { 317 if _, ok := args[i].(string); !ok { 318 // As this is the logging function not much we can do here 319 // without injecting into logs... 320 continue 321 } 322 val := args[i+1] 323 switch sv := val.(type) { 324 case error: 325 // Check if val is of type error. If error type doesn't 326 // implement json.Marshaler or encoding.TextMarshaler 327 // then set val to err.Error() so that it gets marshaled 328 switch sv.(type) { 329 case json.Marshaler, encoding.TextMarshaler: 330 default: 331 val = sv.Error() 332 } 333 case Format: 334 val = fmt.Sprintf(sv[0].(string), sv[1:]...) 335 } 336 337 vals[args[i].(string)] = val 338 } 339 } 340 341 err := json.NewEncoder(l.writer).Encode(vals) 342 if err != nil { 343 if _, ok := err.(*json.UnsupportedTypeError); ok { 344 plainVal := l.jsonMapEntry(t, level, msg) 345 plainVal["@warn"] = errJsonUnsupportedTypeMsg 346 347 json.NewEncoder(l.writer).Encode(plainVal) 348 } 349 } 350} 351 352func (l intLogger) jsonMapEntry(t time.Time, level Level, msg string) map[string]interface{} { 353 vals := map[string]interface{}{ 354 "@message": msg, 355 "@timestamp": t.Format("2006-01-02T15:04:05.000000Z07:00"), 356 } 357 358 var levelStr string 359 switch level { 360 case Error: 361 levelStr = "error" 362 case Warn: 363 levelStr = "warn" 364 case Info: 365 levelStr = "info" 366 case Debug: 367 levelStr = "debug" 368 case Trace: 369 levelStr = "trace" 370 default: 371 levelStr = "all" 372 } 373 374 vals["@level"] = levelStr 375 376 if l.name != "" { 377 vals["@module"] = l.name 378 } 379 380 if l.caller { 381 if _, file, line, ok := runtime.Caller(4); ok { 382 vals["@caller"] = fmt.Sprintf("%s:%d", file, line) 383 } 384 } 385 return vals 386} 387 388// Emit the message and args at DEBUG level 389func (l *intLogger) Debug(msg string, args ...interface{}) { 390 l.Log(Debug, msg, args...) 391} 392 393// Emit the message and args at TRACE level 394func (l *intLogger) Trace(msg string, args ...interface{}) { 395 l.Log(Trace, msg, args...) 396} 397 398// Emit the message and args at INFO level 399func (l *intLogger) Info(msg string, args ...interface{}) { 400 l.Log(Info, msg, args...) 401} 402 403// Emit the message and args at WARN level 404func (l *intLogger) Warn(msg string, args ...interface{}) { 405 l.Log(Warn, msg, args...) 406} 407 408// Emit the message and args at ERROR level 409func (l *intLogger) Error(msg string, args ...interface{}) { 410 l.Log(Error, msg, args...) 411} 412 413// Indicate that the logger would emit TRACE level logs 414func (l *intLogger) IsTrace() bool { 415 return Level(atomic.LoadInt32(l.level)) == Trace 416} 417 418// Indicate that the logger would emit DEBUG level logs 419func (l *intLogger) IsDebug() bool { 420 return Level(atomic.LoadInt32(l.level)) <= Debug 421} 422 423// Indicate that the logger would emit INFO level logs 424func (l *intLogger) IsInfo() bool { 425 return Level(atomic.LoadInt32(l.level)) <= Info 426} 427 428// Indicate that the logger would emit WARN level logs 429func (l *intLogger) IsWarn() bool { 430 return Level(atomic.LoadInt32(l.level)) <= Warn 431} 432 433// Indicate that the logger would emit ERROR level logs 434func (l *intLogger) IsError() bool { 435 return Level(atomic.LoadInt32(l.level)) <= Error 436} 437 438// Return a sub-Logger for which every emitted log message will contain 439// the given key/value pairs. This is used to create a context specific 440// Logger. 441func (l *intLogger) With(args ...interface{}) Logger { 442 if len(args)%2 != 0 { 443 panic("With() call requires paired arguments") 444 } 445 446 sl := *l 447 448 result := make(map[string]interface{}, len(l.implied)+len(args)) 449 keys := make([]string, 0, len(l.implied)+len(args)) 450 451 // Read existing args, store map and key for consistent sorting 452 for i := 0; i < len(l.implied); i += 2 { 453 key := l.implied[i].(string) 454 keys = append(keys, key) 455 result[key] = l.implied[i+1] 456 } 457 // Read new args, store map and key for consistent sorting 458 for i := 0; i < len(args); i += 2 { 459 key := args[i].(string) 460 _, exists := result[key] 461 if !exists { 462 keys = append(keys, key) 463 } 464 result[key] = args[i+1] 465 } 466 467 // Sort keys to be consistent 468 sort.Strings(keys) 469 470 sl.implied = make([]interface{}, 0, len(l.implied)+len(args)) 471 for _, k := range keys { 472 sl.implied = append(sl.implied, k) 473 sl.implied = append(sl.implied, result[k]) 474 } 475 476 return &sl 477} 478 479// Create a new sub-Logger that a name decending from the current name. 480// This is used to create a subsystem specific Logger. 481func (l *intLogger) Named(name string) Logger { 482 sl := *l 483 484 if sl.name != "" { 485 sl.name = sl.name + "." + name 486 } else { 487 sl.name = name 488 } 489 490 return &sl 491} 492 493// Create a new sub-Logger with an explicit name. This ignores the current 494// name. This is used to create a standalone logger that doesn't fall 495// within the normal hierarchy. 496func (l *intLogger) ResetNamed(name string) Logger { 497 sl := *l 498 499 sl.name = name 500 501 return &sl 502} 503 504// Update the logging level on-the-fly. This will affect all subloggers as 505// well. 506func (l *intLogger) SetLevel(level Level) { 507 atomic.StoreInt32(l.level, int32(level)) 508} 509 510// Create a *log.Logger that will send it's data through this Logger. This 511// allows packages that expect to be using the standard library log to actually 512// use this logger. 513func (l *intLogger) StandardLogger(opts *StandardLoggerOptions) *log.Logger { 514 if opts == nil { 515 opts = &StandardLoggerOptions{} 516 } 517 518 return log.New(l.StandardWriter(opts), "", 0) 519} 520 521func (l *intLogger) StandardWriter(opts *StandardLoggerOptions) io.Writer { 522 return &stdlogAdapter{ 523 log: l, 524 inferLevels: opts.InferLevels, 525 forceLevel: opts.ForceLevel, 526 } 527} 528