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