log.go 5.6 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227
  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. // Package log provides logging utilities for the tracer.
  6. package log
  7. import (
  8. "fmt"
  9. "log"
  10. "os"
  11. "strconv"
  12. "sync"
  13. "time"
  14. "gopkg.in/DataDog/dd-trace-go.v1/internal/version"
  15. )
  16. // Level specifies the logging level that the log package prints at.
  17. type Level int
  18. const (
  19. // LevelDebug represents debug level messages.
  20. LevelDebug Level = iota
  21. // LevelWarn represents warning and errors.
  22. LevelWarn
  23. )
  24. var prefixMsg = fmt.Sprintf("Datadog Tracer %s", version.Tag)
  25. // Logger implementations are able to log given messages that the tracer might
  26. // output. This interface is duplicated here to avoid a cyclic dependency
  27. // between this package and ddtrace
  28. type Logger interface {
  29. // Log prints the given message.
  30. Log(msg string)
  31. }
  32. var (
  33. mu sync.RWMutex // guards below fields
  34. level = LevelWarn
  35. logger Logger = &defaultLogger{l: log.New(os.Stderr, "", log.LstdFlags)}
  36. )
  37. // UseLogger sets l as the active logger and returns a function to restore the
  38. // previous logger. The return value is mostly useful when testing.
  39. func UseLogger(l Logger) (undo func()) {
  40. Flush()
  41. mu.Lock()
  42. defer mu.Unlock()
  43. old := logger
  44. logger = l
  45. return func() {
  46. logger = old
  47. }
  48. }
  49. // SetLevel sets the given lvl for logging.
  50. func SetLevel(lvl Level) {
  51. mu.Lock()
  52. defer mu.Unlock()
  53. level = lvl
  54. }
  55. // DebugEnabled returns true if debug log messages are enabled. This can be used in extremely
  56. // hot code paths to avoid allocating the ...interface{} argument.
  57. func DebugEnabled() bool {
  58. mu.RLock()
  59. lvl := level
  60. mu.RUnlock()
  61. return lvl == LevelDebug
  62. }
  63. // Debug prints the given message if the level is LevelDebug.
  64. func Debug(fmt string, a ...interface{}) {
  65. if !DebugEnabled() {
  66. return
  67. }
  68. printMsg("DEBUG", fmt, a...)
  69. }
  70. // Warn prints a warning message.
  71. func Warn(fmt string, a ...interface{}) {
  72. printMsg("WARN", fmt, a...)
  73. }
  74. // Info prints an informational message.
  75. func Info(fmt string, a ...interface{}) {
  76. printMsg("INFO", fmt, a...)
  77. }
  78. var (
  79. errmu sync.RWMutex // guards below fields
  80. erragg = map[string]*errorReport{} // aggregated errors
  81. errrate = time.Minute // the rate at which errors are reported
  82. erron bool // true if errors are being aggregated
  83. )
  84. func init() {
  85. if v := os.Getenv("DD_LOGGING_RATE"); v != "" {
  86. if sec, err := strconv.ParseUint(v, 10, 64); err != nil {
  87. Warn("Invalid value for DD_LOGGING_RATE: %v", err)
  88. } else {
  89. errrate = time.Duration(sec) * time.Second
  90. }
  91. }
  92. }
  93. type errorReport struct {
  94. first time.Time // time when first error occurred
  95. err error
  96. count uint64
  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.
  100. func 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. // defaultErrorLimit specifies the maximum number of errors gathered in a report.
  127. const defaultErrorLimit = 200
  128. // reachedLimit reports whether the maximum count has been reached for this key.
  129. func reachedLimit(key string) bool {
  130. errmu.RLock()
  131. e, ok := erragg[key]
  132. confirm := ok && e.count > defaultErrorLimit
  133. errmu.RUnlock()
  134. return confirm
  135. }
  136. // Flush flushes and resets all aggregated errors to the logger.
  137. func Flush() {
  138. errmu.Lock()
  139. defer errmu.Unlock()
  140. flushLocked()
  141. }
  142. func flushLocked() {
  143. for _, report := range erragg {
  144. msg := fmt.Sprintf("%v", report.err)
  145. if report.count > defaultErrorLimit {
  146. msg += fmt.Sprintf(", %d+ additional messages skipped (first occurrence: %s)", defaultErrorLimit, report.first.Format(time.RFC822))
  147. } else if report.count > 1 {
  148. msg += fmt.Sprintf(", %d additional messages skipped (first occurrence: %s)", report.count-1, report.first.Format(time.RFC822))
  149. } else {
  150. msg += fmt.Sprintf(" (occurred: %s)", report.first.Format(time.RFC822))
  151. }
  152. printMsg("ERROR", msg)
  153. }
  154. for k := range erragg {
  155. // compiler-optimized map-clearing post go1.11 (golang/go#20138)
  156. delete(erragg, k)
  157. }
  158. erron = false
  159. }
  160. func printMsg(lvl, format string, a ...interface{}) {
  161. msg := fmt.Sprintf("%s %s: %s", prefixMsg, lvl, fmt.Sprintf(format, a...))
  162. mu.RLock()
  163. logger.Log(msg)
  164. mu.RUnlock()
  165. }
  166. type defaultLogger struct{ l *log.Logger }
  167. func (p *defaultLogger) Log(msg string) { p.l.Print(msg) }
  168. // DiscardLogger discards every call to Log().
  169. type DiscardLogger struct{}
  170. // Log implements Logger.
  171. func (d DiscardLogger) Log(msg string) {}
  172. // RecordLogger records every call to Log() and makes it available via Logs().
  173. type RecordLogger struct {
  174. m sync.Mutex
  175. logs []string
  176. }
  177. // Log implements Logger.
  178. func (r *RecordLogger) Log(msg string) {
  179. r.m.Lock()
  180. defer r.m.Unlock()
  181. r.logs = append(r.logs, msg)
  182. }
  183. // Logs returns the ordered list of logs recorded by the logger.
  184. func (r *RecordLogger) Logs() []string {
  185. r.m.Lock()
  186. defer r.m.Unlock()
  187. copied := make([]string, len(r.logs))
  188. copy(copied, r.logs)
  189. return copied
  190. }
  191. // Reset resets the logger's internal logs
  192. func (r *RecordLogger) Reset() {
  193. r.m.Lock()
  194. defer r.m.Unlock()
  195. r.logs = r.logs[:0]
  196. }