1// Unless explicitly stated otherwise all files in this repository are licensed
2// under the Apache License Version 2.0.
3// This product includes software developed at Datadog (https://www.datadoghq.com/).
4// Copyright 2016 Datadog, Inc.
5
6// Package log provides logging utilities for the tracer.
7package log
8
9import (
10	"fmt"
11	"log"
12	"os"
13	"strconv"
14	"sync"
15	"time"
16
17	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace"
18	"gopkg.in/DataDog/dd-trace-go.v1/internal/version"
19)
20
21// Level specifies the logging level that the log package prints at.
22type Level int
23
24const (
25	// LevelDebug represents debug level messages.
26	LevelDebug Level = iota
27	// LevelWarn represents warning and errors.
28	LevelWarn
29)
30
31var prefixMsg = fmt.Sprintf("Datadog Tracer %s", version.Tag)
32
33var (
34	mu     sync.RWMutex   // guards below fields
35	level                 = LevelWarn
36	logger ddtrace.Logger = &defaultLogger{l: log.New(os.Stderr, "", log.LstdFlags)}
37)
38
39// UseLogger sets l as the active logger.
40func UseLogger(l ddtrace.Logger) {
41	Flush()
42	mu.Lock()
43	defer mu.Unlock()
44	logger = l
45}
46
47// SetLevel sets the given lvl for logging.
48func SetLevel(lvl Level) {
49	mu.Lock()
50	defer mu.Unlock()
51	level = lvl
52}
53
54// Debug prints the given message if the level is LevelDebug.
55func Debug(fmt string, a ...interface{}) {
56	mu.RLock()
57	lvl := level
58	mu.RUnlock()
59	if lvl != LevelDebug {
60		return
61	}
62	printMsg("DEBUG", fmt, a...)
63}
64
65// Warn prints a warning message.
66func Warn(fmt string, a ...interface{}) {
67	printMsg("WARN", fmt, a...)
68}
69
70// Info prints an informational message.
71func Info(fmt string, a ...interface{}) {
72	printMsg("INFO", fmt, a...)
73}
74
75var (
76	errmu   sync.RWMutex                // guards below fields
77	erragg  = map[string]*errorReport{} // aggregated errors
78	errrate = time.Minute               // the rate at which errors are reported
79	erron   bool                        // true if errors are being aggregated
80)
81
82func init() {
83	if v := os.Getenv("DD_LOGGING_RATE"); v != "" {
84		if sec, err := strconv.ParseUint(v, 10, 64); err != nil {
85			Warn("Invalid value for DD_LOGGING_RATE: %v", err)
86		} else {
87			errrate = time.Duration(sec) * time.Second
88		}
89	}
90}
91
92type errorReport struct {
93	first time.Time // time when first error occurred
94	err   error
95	count uint64
96}
97
98// Error reports an error. Errors get aggregated and logged periodically. The
99// default is once per minute or once every DD_LOGGING_RATE number of seconds.
100func Error(format string, a ...interface{}) {
101	key := format // format should 99.9% of the time be constant
102	if reachedLimit(key) {
103		// avoid too much lock contention on spammy errors
104		return
105	}
106	errmu.Lock()
107	defer errmu.Unlock()
108	report, ok := erragg[key]
109	if !ok {
110		erragg[key] = &errorReport{
111			err:   fmt.Errorf(format, a...),
112			first: time.Now(),
113		}
114		report = erragg[key]
115	}
116	report.count++
117	if errrate == 0 {
118		flushLocked()
119		return
120	}
121	if !erron {
122		erron = true
123		time.AfterFunc(errrate, Flush)
124	}
125}
126
127// defaultErrorLimit specifies the maximum number of errors gathered in a report.
128const defaultErrorLimit = 200
129
130// reachedLimit reports whether the maximum count has been reached for this key.
131func reachedLimit(key string) bool {
132	errmu.RLock()
133	e, ok := erragg[key]
134	confirm := ok && e.count > defaultErrorLimit
135	errmu.RUnlock()
136	return confirm
137}
138
139// Flush flushes and resets all aggregated errors to the logger.
140func Flush() {
141	errmu.Lock()
142	defer errmu.Unlock()
143	flushLocked()
144}
145
146func flushLocked() {
147	for _, report := range erragg {
148		msg := fmt.Sprintf("%v", report.err)
149		if report.count > defaultErrorLimit {
150			msg += fmt.Sprintf(", %d+ additional messages skipped (first occurrence: %s)", defaultErrorLimit, report.first.Format(time.RFC822))
151		} else if report.count > 1 {
152			msg += fmt.Sprintf(", %d additional messages skipped (first occurrence: %s)", report.count-1, report.first.Format(time.RFC822))
153		} else {
154			msg += fmt.Sprintf(" (occurred: %s)", report.first.Format(time.RFC822))
155		}
156		printMsg("ERROR", msg)
157	}
158	for k := range erragg {
159		// compiler-optimized map-clearing post go1.11 (golang/go#20138)
160		delete(erragg, k)
161	}
162	erron = false
163}
164
165func printMsg(lvl, format string, a ...interface{}) {
166	msg := fmt.Sprintf("%s %s: %s", prefixMsg, lvl, fmt.Sprintf(format, a...))
167	mu.RLock()
168	logger.Log(msg)
169	mu.RUnlock()
170}
171
172type defaultLogger struct{ l *log.Logger }
173
174func (p *defaultLogger) Log(msg string) { p.l.Print(msg) }
175