blob: 28c38a6abc6feb7cc2c08d7e9cb68390ce9e06e2 [file] [log] [blame]
// Copyright 2023 Google Inc. All Rights Reserved.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package logsink
import (
"bytes"
"context"
"fmt"
"strconv"
"strings"
"sync"
"time"
"github.com/golang/glog/internal/stackdump"
)
// MaxLogMessageLen is the limit on length of a formatted log message, including
// the standard line prefix and trailing newline.
//
// Chosen to match C++ glog.
const MaxLogMessageLen = 15000
// A Severity is a severity at which a message can be logged.
type Severity int8
// These constants identify the log levels in order of increasing severity.
// A message written to a high-severity log file is also written to each
// lower-severity log file.
const (
Info Severity = iota
Warning
Error
// Fatal contains logs written immediately before the process terminates.
//
// Sink implementations should not terminate the process themselves: the log
// package will perform any necessary cleanup and terminate the process as
// appropriate.
Fatal
)
func (s Severity) String() string {
switch s {
case Info:
return "INFO"
case Warning:
return "WARNING"
case Error:
return "ERROR"
case Fatal:
return "FATAL"
}
return fmt.Sprintf("%T(%d)", s, s)
}
// ParseSeverity returns the case-insensitive Severity value for the given string.
func ParseSeverity(name string) (Severity, error) {
name = strings.ToUpper(name)
for s := Info; s <= Fatal; s++ {
if s.String() == name {
return s, nil
}
}
return -1, fmt.Errorf("logsink: invalid severity %q", name)
}
// Meta is metadata about a logging call.
type Meta struct {
// The context with which the log call was made (or nil). If set, the context
// is only valid during the logsink.Structured.Printf call, it should not be
// retained.
Context context.Context
// Time is the time at which the log call was made.
Time time.Time
// File is the source file from which the log entry originates.
File string
// Line is the line offset within the source file.
Line int
// Depth is the number of stack frames between the logsink and the log call.
Depth int
Severity Severity
// Verbose indicates whether the call was made via "log.V". Log entries below
// the current verbosity threshold are not sent to the sink.
Verbose bool
// Thread ID. This can be populated with a thread ID from another source,
// such as a system we are importing logs from. In the normal case, this
// will be set to the process ID (PID), since Go doesn't have threads.
Thread int64
// Stack trace starting in the logging function. May be nil.
// A logsink should implement the StackWanter interface to request this.
//
// Even if WantStack returns false, this field may be set (e.g. if another
// sink wants a stack trace).
Stack *stackdump.Stack
}
// Structured is a logging destination that accepts structured data as input.
type Structured interface {
// Printf formats according to a fmt.Printf format specifier and writes a log
// entry. The precise result of formatting depends on the sink, but should
// aim for consistency with fmt.Printf.
//
// Printf returns the number of bytes occupied by the log entry, which
// may not be equal to the total number of bytes written.
//
// Printf returns any error encountered *if* it is severe enough that the log
// package should terminate the process.
//
// The sink must not modify the *Meta parameter, nor reference it after
// Printf has returned: it may be reused in subsequent calls.
Printf(meta *Meta, format string, a ...any) (n int, err error)
}
// StackWanter can be implemented by a logsink.Structured to indicate that it
// wants a stack trace to accompany at least some of the log messages it receives.
type StackWanter interface {
// WantStack returns true if the sink requires a stack trace for a log message
// with this metadata.
//
// NOTE: Returning true implies that meta.Stack will be non-nil. Returning
// false does NOT imply that meta.Stack will be nil.
WantStack(meta *Meta) bool
}
// Text is a logging destination that accepts pre-formatted log lines (instead of
// structured data).
type Text interface {
// Enabled returns whether this sink should output messages for the given
// Meta. If the sink returns false for a given Meta, the Printf function will
// not call Emit on it for the corresponding log message.
Enabled(*Meta) bool
// Emit writes a pre-formatted text log entry (including any applicable
// header) to the log. It returns the number of bytes occupied by the entry
// (which may differ from the length of the passed-in slice).
//
// Emit returns any error encountered *if* it is severe enough that the log
// package should terminate the process.
//
// The sink must not modify the *Meta parameter, nor reference it after
// Printf has returned: it may be reused in subsequent calls.
//
// NOTE: When developing a text sink, keep in mind the surface in which the
// logs will be displayed, and whether it's important that the sink be
// resistent to tampering in the style of b/211428300. Standard text sinks
// (like `stderrSink`) do not protect against this (e.g. by escaping
// characters) because the cases where they would show user-influenced bytes
// are vanishingly small.
Emit(*Meta, []byte) (n int, err error)
}
// bufs is a pool of *bytes.Buffer used in formatting log entries.
var bufs sync.Pool // Pool of *bytes.Buffer.
// textPrintf formats a text log entry and emits it to all specified Text sinks.
//
// The returned n is the maximum across all Emit calls.
// The returned err is the first non-nil error encountered.
// Sinks that are disabled by configuration should return (0, nil).
func textPrintf(m *Meta, textSinks []Text, format string, args ...any) (n int, err error) {
// We expect at most file, stderr, and perhaps syslog. If there are more,
// we'll end up allocating - no big deal.
const maxExpectedTextSinks = 3
var noAllocSinks [maxExpectedTextSinks]Text
sinks := noAllocSinks[:0]
for _, s := range textSinks {
if s.Enabled(m) {
sinks = append(sinks, s)
}
}
if len(sinks) == 0 && m.Severity != Fatal {
return 0, nil // No TextSinks specified; don't bother formatting.
}
bufi := bufs.Get()
var buf *bytes.Buffer
if bufi == nil {
buf = bytes.NewBuffer(nil)
bufi = buf
} else {
buf = bufi.(*bytes.Buffer)
buf.Reset()
}
// Lmmdd hh:mm:ss.uuuuuu PID/GID file:line]
//
// The "PID" entry arguably ought to be TID for consistency with other
// environments, but TID is not meaningful in a Go program due to the
// multiplexing of goroutines across threads.
//
// Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
// It's worth about 3X. Fprintf is hard.
const severityChar = "IWEF"
buf.WriteByte(severityChar[m.Severity])
_, month, day := m.Time.Date()
hour, minute, second := m.Time.Clock()
twoDigits(buf, int(month))
twoDigits(buf, day)
buf.WriteByte(' ')
twoDigits(buf, hour)
buf.WriteByte(':')
twoDigits(buf, minute)
buf.WriteByte(':')
twoDigits(buf, second)
buf.WriteByte('.')
nDigits(buf, 6, uint64(m.Time.Nanosecond()/1000), '0')
buf.WriteByte(' ')
nDigits(buf, 7, uint64(m.Thread), ' ')
buf.WriteByte(' ')
{
file := m.File
if i := strings.LastIndex(file, "/"); i >= 0 {
file = file[i+1:]
}
buf.WriteString(file)
}
buf.WriteByte(':')
{
var tmp [19]byte
buf.Write(strconv.AppendInt(tmp[:0], int64(m.Line), 10))
}
buf.WriteString("] ")
msgStart := buf.Len()
fmt.Fprintf(buf, format, args...)
if buf.Len() > MaxLogMessageLen-1 {
buf.Truncate(MaxLogMessageLen - 1)
}
msgEnd := buf.Len()
if b := buf.Bytes(); b[len(b)-1] != '\n' {
buf.WriteByte('\n')
}
for _, s := range sinks {
sn, sErr := s.Emit(m, buf.Bytes())
if sn > n {
n = sn
}
if sErr != nil && err == nil {
err = sErr
}
}
if m.Severity == Fatal {
savedM := *m
fatalMessageStore(savedEntry{
meta: &savedM,
msg: buf.Bytes()[msgStart:msgEnd],
})
} else {
bufs.Put(bufi)
}
return n, err
}
const digits = "0123456789"
// twoDigits formats a zero-prefixed two-digit integer to buf.
func twoDigits(buf *bytes.Buffer, d int) {
buf.WriteByte(digits[(d/10)%10])
buf.WriteByte(digits[d%10])
}
// nDigits formats an n-digit integer to buf, padding with pad on the left. It
// assumes d != 0.
func nDigits(buf *bytes.Buffer, n int, d uint64, pad byte) {
var tmp [20]byte
cutoff := len(tmp) - n
j := len(tmp) - 1
for ; d > 0; j-- {
tmp[j] = digits[d%10]
d /= 10
}
for ; j >= cutoff; j-- {
tmp[j] = pad
}
j++
buf.Write(tmp[j:])
}
// Printf writes a log entry to all registered TextSinks in this package, then
// to all registered StructuredSinks.
//
// The returned n is the maximum across all Emit and Printf calls.
// The returned err is the first non-nil error encountered.
// Sinks that are disabled by configuration should return (0, nil).
func Printf(m *Meta, format string, args ...any) (n int, err error) {
m.Depth++
n, err = textPrintf(m, TextSinks, format, args...)
for _, sink := range StructuredSinks {
// TODO: Support TextSinks that implement StackWanter?
if sw, ok := sink.(StackWanter); ok && sw.WantStack(m) {
if m.Stack == nil {
// First, try to find a stacktrace in args, otherwise generate one.
for _, arg := range args {
if stack, ok := arg.(stackdump.Stack); ok {
m.Stack = &stack
break
}
}
if m.Stack == nil {
stack := stackdump.Caller( /* skipDepth = */ m.Depth)
m.Stack = &stack
}
}
}
sn, sErr := sink.Printf(m, format, args...)
if sn > n {
n = sn
}
if sErr != nil && err == nil {
err = sErr
}
}
return n, err
}
// The sets of sinks to which logs should be written.
//
// These must only be modified during package init, and are read-only thereafter.
var (
// StructuredSinks is the set of Structured sink instances to which logs
// should be written.
StructuredSinks []Structured
// TextSinks is the set of Text sink instances to which logs should be
// written.
//
// These are registered separately from Structured sink implementations to
// avoid the need to repeat the work of formatting a message for each Text
// sink that writes it. The package-level Printf function writes to both sets
// independenty, so a given log destination should only register a Structured
// *or* a Text sink (not both).
TextSinks []Text
)
type savedEntry struct {
meta *Meta
msg []byte
}
// StructuredTextWrapper is a Structured sink which forwards logs to a set of Text sinks.
//
// The purpose of this sink is to allow applications to intercept logging calls before they are
// serialized and sent to Text sinks. For example, if one needs to redact PII from logging
// arguments before they reach STDERR, one solution would be to do the redacting in a Structured
// sink that forwards logs to a StructuredTextWrapper instance, and make STDERR a child of that
// StructuredTextWrapper instance. This is how one could set this up in their application:
//
// func init() {
//
// wrapper := logsink.StructuredTextWrapper{TextSinks: logsink.TextSinks}
// // sanitizersink will intercept logs and remove PII
// sanitizer := sanitizersink{Sink: &wrapper}
// logsink.StructuredSinks = append(logsink.StructuredSinks, &sanitizer)
// logsink.TextSinks = nil
//
// }
type StructuredTextWrapper struct {
// TextSinks is the set of Text sinks that should receive logs from this
// StructuredTextWrapper instance.
TextSinks []Text
}
// Printf forwards logs to all Text sinks registered in the StructuredTextWrapper.
func (w *StructuredTextWrapper) Printf(meta *Meta, format string, args ...any) (n int, err error) {
return textPrintf(meta, w.TextSinks, format, args...)
}