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