logsink.go 12 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393
  1. // Copyright 2023 Google Inc. All Rights Reserved.
  2. //
  3. // Licensed under the Apache License, Version 2.0 (the "License");
  4. // you may not use this file except in compliance with the License.
  5. // You may obtain a copy of the License at
  6. //
  7. // http://www.apache.org/licenses/LICENSE-2.0
  8. //
  9. // Unless required by applicable law or agreed to in writing, software
  10. // distributed under the License is distributed on an "AS IS" BASIS,
  11. // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  12. // See the License for the specific language governing permissions and
  13. // limitations under the License.
  14. package logsink
  15. import (
  16. "bytes"
  17. "context"
  18. "fmt"
  19. "strconv"
  20. "strings"
  21. "sync"
  22. "time"
  23. "github.com/golang/glog/internal/stackdump"
  24. )
  25. // MaxLogMessageLen is the limit on length of a formatted log message, including
  26. // the standard line prefix and trailing newline.
  27. //
  28. // Chosen to match C++ glog.
  29. const MaxLogMessageLen = 15000
  30. // A Severity is a severity at which a message can be logged.
  31. type Severity int8
  32. // These constants identify the log levels in order of increasing severity.
  33. // A message written to a high-severity log file is also written to each
  34. // lower-severity log file.
  35. const (
  36. Info Severity = iota
  37. Warning
  38. Error
  39. // Fatal contains logs written immediately before the process terminates.
  40. //
  41. // Sink implementations should not terminate the process themselves: the log
  42. // package will perform any necessary cleanup and terminate the process as
  43. // appropriate.
  44. Fatal
  45. )
  46. func (s Severity) String() string {
  47. switch s {
  48. case Info:
  49. return "INFO"
  50. case Warning:
  51. return "WARNING"
  52. case Error:
  53. return "ERROR"
  54. case Fatal:
  55. return "FATAL"
  56. }
  57. return fmt.Sprintf("%T(%d)", s, s)
  58. }
  59. // ParseSeverity returns the case-insensitive Severity value for the given string.
  60. func ParseSeverity(name string) (Severity, error) {
  61. name = strings.ToUpper(name)
  62. for s := Info; s <= Fatal; s++ {
  63. if s.String() == name {
  64. return s, nil
  65. }
  66. }
  67. return -1, fmt.Errorf("logsink: invalid severity %q", name)
  68. }
  69. // Meta is metadata about a logging call.
  70. type Meta struct {
  71. // The context with which the log call was made (or nil). If set, the context
  72. // is only valid during the logsink.Structured.Printf call, it should not be
  73. // retained.
  74. Context context.Context
  75. // Time is the time at which the log call was made.
  76. Time time.Time
  77. // File is the source file from which the log entry originates.
  78. File string
  79. // Line is the line offset within the source file.
  80. Line int
  81. // Depth is the number of stack frames between the logsink and the log call.
  82. Depth int
  83. Severity Severity
  84. // Verbose indicates whether the call was made via "log.V". Log entries below
  85. // the current verbosity threshold are not sent to the sink.
  86. Verbose bool
  87. // Thread ID. This can be populated with a thread ID from another source,
  88. // such as a system we are importing logs from. In the normal case, this
  89. // will be set to the process ID (PID), since Go doesn't have threads.
  90. Thread int64
  91. // Stack trace starting in the logging function. May be nil.
  92. // A logsink should implement the StackWanter interface to request this.
  93. //
  94. // Even if WantStack returns false, this field may be set (e.g. if another
  95. // sink wants a stack trace).
  96. Stack *stackdump.Stack
  97. }
  98. // Structured is a logging destination that accepts structured data as input.
  99. type Structured interface {
  100. // Printf formats according to a fmt.Printf format specifier and writes a log
  101. // entry. The precise result of formatting depends on the sink, but should
  102. // aim for consistency with fmt.Printf.
  103. //
  104. // Printf returns the number of bytes occupied by the log entry, which
  105. // may not be equal to the total number of bytes written.
  106. //
  107. // Printf returns any error encountered *if* it is severe enough that the log
  108. // package should terminate the process.
  109. //
  110. // The sink must not modify the *Meta parameter, nor reference it after
  111. // Printf has returned: it may be reused in subsequent calls.
  112. Printf(meta *Meta, format string, a ...any) (n int, err error)
  113. }
  114. // StackWanter can be implemented by a logsink.Structured to indicate that it
  115. // wants a stack trace to accompany at least some of the log messages it receives.
  116. type StackWanter interface {
  117. // WantStack returns true if the sink requires a stack trace for a log message
  118. // with this metadata.
  119. //
  120. // NOTE: Returning true implies that meta.Stack will be non-nil. Returning
  121. // false does NOT imply that meta.Stack will be nil.
  122. WantStack(meta *Meta) bool
  123. }
  124. // Text is a logging destination that accepts pre-formatted log lines (instead of
  125. // structured data).
  126. type Text interface {
  127. // Enabled returns whether this sink should output messages for the given
  128. // Meta. If the sink returns false for a given Meta, the Printf function will
  129. // not call Emit on it for the corresponding log message.
  130. Enabled(*Meta) bool
  131. // Emit writes a pre-formatted text log entry (including any applicable
  132. // header) to the log. It returns the number of bytes occupied by the entry
  133. // (which may differ from the length of the passed-in slice).
  134. //
  135. // Emit returns any error encountered *if* it is severe enough that the log
  136. // package should terminate the process.
  137. //
  138. // The sink must not modify the *Meta parameter, nor reference it after
  139. // Printf has returned: it may be reused in subsequent calls.
  140. //
  141. // NOTE: When developing a text sink, keep in mind the surface in which the
  142. // logs will be displayed, and whether it's important that the sink be
  143. // resistent to tampering in the style of b/211428300. Standard text sinks
  144. // (like `stderrSink`) do not protect against this (e.g. by escaping
  145. // characters) because the cases where they would show user-influenced bytes
  146. // are vanishingly small.
  147. Emit(*Meta, []byte) (n int, err error)
  148. }
  149. // bufs is a pool of *bytes.Buffer used in formatting log entries.
  150. var bufs sync.Pool // Pool of *bytes.Buffer.
  151. // textPrintf formats a text log entry and emits it to all specified Text sinks.
  152. //
  153. // The returned n is the maximum across all Emit calls.
  154. // The returned err is the first non-nil error encountered.
  155. // Sinks that are disabled by configuration should return (0, nil).
  156. func textPrintf(m *Meta, textSinks []Text, format string, args ...any) (n int, err error) {
  157. // We expect at most file, stderr, and perhaps syslog. If there are more,
  158. // we'll end up allocating - no big deal.
  159. const maxExpectedTextSinks = 3
  160. var noAllocSinks [maxExpectedTextSinks]Text
  161. sinks := noAllocSinks[:0]
  162. for _, s := range textSinks {
  163. if s.Enabled(m) {
  164. sinks = append(sinks, s)
  165. }
  166. }
  167. if len(sinks) == 0 && m.Severity != Fatal {
  168. return 0, nil // No TextSinks specified; don't bother formatting.
  169. }
  170. bufi := bufs.Get()
  171. var buf *bytes.Buffer
  172. if bufi == nil {
  173. buf = bytes.NewBuffer(nil)
  174. bufi = buf
  175. } else {
  176. buf = bufi.(*bytes.Buffer)
  177. buf.Reset()
  178. }
  179. // Lmmdd hh:mm:ss.uuuuuu PID/GID file:line]
  180. //
  181. // The "PID" entry arguably ought to be TID for consistency with other
  182. // environments, but TID is not meaningful in a Go program due to the
  183. // multiplexing of goroutines across threads.
  184. //
  185. // Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
  186. // It's worth about 3X. Fprintf is hard.
  187. const severityChar = "IWEF"
  188. buf.WriteByte(severityChar[m.Severity])
  189. _, month, day := m.Time.Date()
  190. hour, minute, second := m.Time.Clock()
  191. twoDigits(buf, int(month))
  192. twoDigits(buf, day)
  193. buf.WriteByte(' ')
  194. twoDigits(buf, hour)
  195. buf.WriteByte(':')
  196. twoDigits(buf, minute)
  197. buf.WriteByte(':')
  198. twoDigits(buf, second)
  199. buf.WriteByte('.')
  200. nDigits(buf, 6, uint64(m.Time.Nanosecond()/1000), '0')
  201. buf.WriteByte(' ')
  202. nDigits(buf, 7, uint64(m.Thread), ' ')
  203. buf.WriteByte(' ')
  204. {
  205. file := m.File
  206. if i := strings.LastIndex(file, "/"); i >= 0 {
  207. file = file[i+1:]
  208. }
  209. buf.WriteString(file)
  210. }
  211. buf.WriteByte(':')
  212. {
  213. var tmp [19]byte
  214. buf.Write(strconv.AppendInt(tmp[:0], int64(m.Line), 10))
  215. }
  216. buf.WriteString("] ")
  217. msgStart := buf.Len()
  218. fmt.Fprintf(buf, format, args...)
  219. if buf.Len() > MaxLogMessageLen-1 {
  220. buf.Truncate(MaxLogMessageLen - 1)
  221. }
  222. msgEnd := buf.Len()
  223. if b := buf.Bytes(); b[len(b)-1] != '\n' {
  224. buf.WriteByte('\n')
  225. }
  226. for _, s := range sinks {
  227. sn, sErr := s.Emit(m, buf.Bytes())
  228. if sn > n {
  229. n = sn
  230. }
  231. if sErr != nil && err == nil {
  232. err = sErr
  233. }
  234. }
  235. if m.Severity == Fatal {
  236. savedM := *m
  237. fatalMessageStore(savedEntry{
  238. meta: &savedM,
  239. msg: buf.Bytes()[msgStart:msgEnd],
  240. })
  241. } else {
  242. bufs.Put(bufi)
  243. }
  244. return n, err
  245. }
  246. const digits = "0123456789"
  247. // twoDigits formats a zero-prefixed two-digit integer to buf.
  248. func twoDigits(buf *bytes.Buffer, d int) {
  249. buf.WriteByte(digits[(d/10)%10])
  250. buf.WriteByte(digits[d%10])
  251. }
  252. // nDigits formats an n-digit integer to buf, padding with pad on the left. It
  253. // assumes d != 0.
  254. func nDigits(buf *bytes.Buffer, n int, d uint64, pad byte) {
  255. var tmp [20]byte
  256. cutoff := len(tmp) - n
  257. j := len(tmp) - 1
  258. for ; d > 0; j-- {
  259. tmp[j] = digits[d%10]
  260. d /= 10
  261. }
  262. for ; j >= cutoff; j-- {
  263. tmp[j] = pad
  264. }
  265. j++
  266. buf.Write(tmp[j:])
  267. }
  268. // Printf writes a log entry to all registered TextSinks in this package, then
  269. // to all registered StructuredSinks.
  270. //
  271. // The returned n is the maximum across all Emit and Printf calls.
  272. // The returned err is the first non-nil error encountered.
  273. // Sinks that are disabled by configuration should return (0, nil).
  274. func Printf(m *Meta, format string, args ...any) (n int, err error) {
  275. m.Depth++
  276. n, err = textPrintf(m, TextSinks, format, args...)
  277. for _, sink := range StructuredSinks {
  278. // TODO: Support TextSinks that implement StackWanter?
  279. if sw, ok := sink.(StackWanter); ok && sw.WantStack(m) {
  280. if m.Stack == nil {
  281. // First, try to find a stacktrace in args, otherwise generate one.
  282. for _, arg := range args {
  283. if stack, ok := arg.(stackdump.Stack); ok {
  284. m.Stack = &stack
  285. break
  286. }
  287. }
  288. if m.Stack == nil {
  289. stack := stackdump.Caller( /* skipDepth = */ m.Depth)
  290. m.Stack = &stack
  291. }
  292. }
  293. }
  294. sn, sErr := sink.Printf(m, format, args...)
  295. if sn > n {
  296. n = sn
  297. }
  298. if sErr != nil && err == nil {
  299. err = sErr
  300. }
  301. }
  302. return n, err
  303. }
  304. // The sets of sinks to which logs should be written.
  305. //
  306. // These must only be modified during package init, and are read-only thereafter.
  307. var (
  308. // StructuredSinks is the set of Structured sink instances to which logs
  309. // should be written.
  310. StructuredSinks []Structured
  311. // TextSinks is the set of Text sink instances to which logs should be
  312. // written.
  313. //
  314. // These are registered separately from Structured sink implementations to
  315. // avoid the need to repeat the work of formatting a message for each Text
  316. // sink that writes it. The package-level Printf function writes to both sets
  317. // independenty, so a given log destination should only register a Structured
  318. // *or* a Text sink (not both).
  319. TextSinks []Text
  320. )
  321. type savedEntry struct {
  322. meta *Meta
  323. msg []byte
  324. }
  325. // StructuredTextWrapper is a Structured sink which forwards logs to a set of Text sinks.
  326. //
  327. // The purpose of this sink is to allow applications to intercept logging calls before they are
  328. // serialized and sent to Text sinks. For example, if one needs to redact PII from logging
  329. // arguments before they reach STDERR, one solution would be to do the redacting in a Structured
  330. // sink that forwards logs to a StructuredTextWrapper instance, and make STDERR a child of that
  331. // StructuredTextWrapper instance. This is how one could set this up in their application:
  332. //
  333. // func init() {
  334. //
  335. // wrapper := logsink.StructuredTextWrapper{TextSinks: logsink.TextSinks}
  336. // // sanitizersink will intercept logs and remove PII
  337. // sanitizer := sanitizersink{Sink: &wrapper}
  338. // logsink.StructuredSinks = append(logsink.StructuredSinks, &sanitizer)
  339. // logsink.TextSinks = nil
  340. //
  341. // }
  342. type StructuredTextWrapper struct {
  343. // TextSinks is the set of Text sinks that should receive logs from this
  344. // StructuredTextWrapper instance.
  345. TextSinks []Text
  346. }
  347. // Printf forwards logs to all Text sinks registered in the StructuredTextWrapper.
  348. func (w *StructuredTextWrapper) Printf(meta *Meta, format string, args ...any) (n int, err error) {
  349. return textPrintf(meta, w.TextSinks, format, args...)
  350. }