1 // Copyright 2018 The gVisor Authors.
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 log implements a library for logging.
16 //
17 // This is separate from the standard logging package because logging may be a
18 // high-impact activity, and therefore we wanted to provide as much flexibility
19 // as possible in the underlying implementation.
20 //
21 // Note that logging should still be considered high-impact, and should not be
22 // done in the hot path. If necessary, logging statements should be protected
23 // with guards regarding the logging level. For example,
24 //
25 // if log.IsLogging(log.Debug) {
26 // log.Debugf(...)
27 // }
28 //
29 // This is because the log.Debugf(...) statement alone will generate a
30 // significant amount of garbage and churn in many cases, even if no log
31 // message is ultimately emitted.
32 //
33 // +checkalignedignore
34 package log
35 36 import (
37 "fmt"
38 "io"
39 stdlog "log"
40 "os"
41 "regexp"
42 "runtime"
43 "sync/atomic"
44 "time"
45 46 "gvisor.dev/gvisor/pkg/linewriter"
47 "gvisor.dev/gvisor/pkg/sync"
48 )
49 50 // Level is the log level.
51 type Level uint32
52 53 // The following levels are fixed, and can never be changed. Since some control
54 // RPCs allow for changing the level as an integer, it is only possible to add
55 // additional levels, and the existing one cannot be removed.
56 const (
57 // Warning indicates that output should always be emitted.
58 Warning Level = iota
59 60 // Info indicates that output should normally be emitted.
61 Info
62 63 // Debug indicates that output should not normally be emitted.
64 Debug
65 )
66 67 func (l Level) String() string {
68 switch l {
69 case Warning:
70 return "Warning"
71 case Info:
72 return "Info"
73 case Debug:
74 return "Debug"
75 default:
76 return fmt.Sprintf("Invalid level: %d", l)
77 }
78 }
79 80 // Emitter is the final destination for logs.
81 type Emitter interface {
82 // Emit emits the given log statement. This allows for control over the
83 // timestamp used for logging.
84 Emit(depth int, level Level, timestamp time.Time, format string, v ...any)
85 }
86 87 // Writer writes the output to the given writer.
88 type Writer struct {
89 // Next is where output is written.
90 Next io.Writer
91 92 // mu protects fields below.
93 mu sync.Mutex
94 95 // errors counts failures to write log messages so it can be reported
96 // when writer start to work again. Needs to be accessed using atomics
97 // to make race detector happy because it's read outside the mutex.
98 // +checklocks
99 atomicErrors int32
100 }
101 102 // Write writes out the given bytes, handling non-blocking sockets.
103 func (l *Writer) Write(data []byte) (int, error) {
104 n := 0
105 106 for n < len(data) {
107 w, err := l.Next.Write(data[n:])
108 n += w
109 110 // Is it a non-blocking socket?
111 if pathErr, ok := err.(*os.PathError); ok && pathErr.Timeout() {
112 runtime.Gosched()
113 continue
114 }
115 116 // Some other error?
117 if err != nil {
118 l.mu.Lock()
119 atomic.AddInt32(&l.atomicErrors, 1)
120 l.mu.Unlock()
121 return n, err
122 }
123 }
124 125 // Do we need to end with a '\n'?
126 if len(data) == 0 || data[len(data)-1] != '\n' {
127 l.Write([]byte{'\n'})
128 }
129 130 // Dirty read in case there were errors (rare).
131 if atomic.LoadInt32(&l.atomicErrors) > 0 {
132 l.mu.Lock()
133 defer l.mu.Unlock()
134 135 // Recheck condition under lock.
136 if e := atomic.LoadInt32(&l.atomicErrors); e > 0 {
137 msg := fmt.Sprintf("\n*** Dropped %d log messages ***\n", e)
138 if _, err := l.Next.Write([]byte(msg)); err == nil {
139 atomic.StoreInt32(&l.atomicErrors, 0)
140 }
141 }
142 }
143 144 return n, nil
145 }
146 147 // Emit emits the message.
148 func (l *Writer) Emit(_ int, _ Level, _ time.Time, format string, args ...any) {
149 fmt.Fprintf(l, format, args...)
150 }
151 152 // MultiEmitter is an emitter that emits to multiple Emitters.
153 type MultiEmitter []Emitter
154 155 // Emit emits to all emitters.
156 func (m *MultiEmitter) Emit(depth int, level Level, timestamp time.Time, format string, v ...any) {
157 for _, e := range *m {
158 e.Emit(1+depth, level, timestamp, format, v...)
159 }
160 }
161 162 // TestLogger is implemented by testing.T and testing.B.
163 type TestLogger interface {
164 Logf(format string, v ...any)
165 }
166 167 // TestEmitter may be used for wrapping tests.
168 type TestEmitter struct {
169 TestLogger
170 }
171 172 // Emit emits to the TestLogger.
173 func (t *TestEmitter) Emit(_ int, level Level, timestamp time.Time, format string, v ...any) {
174 t.Logf(format, v...)
175 }
176 177 // Logger is a high-level logging interface. It is in fact, not used within the
178 // log package. Rather it is provided for others to provide contextual loggers
179 // that may append some addition information to log statement. BasicLogger
180 // satisfies this interface, and may be passed around as a Logger.
181 type Logger interface {
182 // Debugf logs a debug statement.
183 Debugf(format string, v ...any)
184 185 // Infof logs at an info level.
186 Infof(format string, v ...any)
187 188 // Warningf logs at a warning level.
189 Warningf(format string, v ...any)
190 191 // IsLogging returns true iff this level is being logged. This may be
192 // used to short-circuit expensive operations for debugging calls.
193 IsLogging(level Level) bool
194 }
195 196 // BasicLogger is the default implementation of Logger.
197 type BasicLogger struct {
198 Level
199 Emitter
200 }
201 202 // Debugf implements logger.Debugf.
203 func (l *BasicLogger) Debugf(format string, v ...any) {
204 l.DebugfAtDepth(1, format, v...)
205 }
206 207 // Infof implements logger.Infof.
208 func (l *BasicLogger) Infof(format string, v ...any) {
209 l.InfofAtDepth(1, format, v...)
210 }
211 212 // Warningf implements logger.Warningf.
213 func (l *BasicLogger) Warningf(format string, v ...any) {
214 l.WarningfAtDepth(1, format, v...)
215 }
216 217 // DebugfAtDepth logs at a specific depth.
218 func (l *BasicLogger) DebugfAtDepth(depth int, format string, v ...any) {
219 if l.IsLogging(Debug) {
220 l.Emit(1+depth, Debug, time.Now(), format, v...)
221 }
222 }
223 224 // InfofAtDepth logs at a specific depth.
225 func (l *BasicLogger) InfofAtDepth(depth int, format string, v ...any) {
226 if l.IsLogging(Info) {
227 l.Emit(1+depth, Info, time.Now(), format, v...)
228 }
229 }
230 231 // WarningfAtDepth logs at a specific depth.
232 func (l *BasicLogger) WarningfAtDepth(depth int, format string, v ...any) {
233 if l.IsLogging(Warning) {
234 l.Emit(1+depth, Warning, time.Now(), format, v...)
235 }
236 }
237 238 // IsLogging implements logger.IsLogging.
239 func (l *BasicLogger) IsLogging(level Level) bool {
240 return atomic.LoadUint32((*uint32)(&l.Level)) >= uint32(level)
241 }
242 243 // SetLevel sets the logging level.
244 func (l *BasicLogger) SetLevel(level Level) {
245 atomic.StoreUint32((*uint32)(&l.Level), uint32(level))
246 }
247 248 // logMu protects Log below. We use atomic operations to read the value, but
249 // updates require logMu to ensure consistency.
250 var logMu sync.Mutex
251 252 // log is the default logger.
253 var log atomic.Pointer[BasicLogger]
254 255 // Log retrieves the global logger.
256 func Log() *BasicLogger {
257 return log.Load()
258 }
259 260 // SetTarget sets the log target.
261 //
262 // This is not thread safe and shouldn't be called concurrently with any
263 // logging calls.
264 //
265 // SetTarget should be called before any instances of log.Log() to avoid race conditions
266 func SetTarget(target Emitter) {
267 logMu.Lock()
268 defer logMu.Unlock()
269 oldLog := Log()
270 log.Store(&BasicLogger{Level: oldLog.Level, Emitter: target})
271 }
272 273 // SetLevel sets the log level.
274 func SetLevel(newLevel Level) {
275 Log().SetLevel(newLevel)
276 }
277 278 // Debugf logs to the global logger.
279 func Debugf(format string, v ...any) {
280 Log().DebugfAtDepth(1, format, v...)
281 }
282 283 // Infof logs to the global logger.
284 func Infof(format string, v ...any) {
285 Log().InfofAtDepth(1, format, v...)
286 }
287 288 // Warningf logs to the global logger.
289 func Warningf(format string, v ...any) {
290 Log().WarningfAtDepth(1, format, v...)
291 }
292 293 // DebugfAtDepth logs to the global logger.
294 func DebugfAtDepth(depth int, format string, v ...any) {
295 Log().DebugfAtDepth(1+depth, format, v...)
296 }
297 298 // InfofAtDepth logs to the global logger.
299 func InfofAtDepth(depth int, format string, v ...any) {
300 Log().InfofAtDepth(1+depth, format, v...)
301 }
302 303 // WarningfAtDepth logs to the global logger.
304 func WarningfAtDepth(depth int, format string, v ...any) {
305 Log().WarningfAtDepth(1+depth, format, v...)
306 }
307 308 // defaultStackSize is the default buffer size to allocate for stack traces.
309 const defaultStackSize = 1 << 16 // 64KB
310 311 // maxStackSize is the maximum buffer size to allocate for stack traces.
312 const maxStackSize = 1 << 26 // 64MB
313 314 // Stacks returns goroutine stacks, like panic.
315 func Stacks(all bool) []byte {
316 var trace []byte
317 for s := defaultStackSize; s <= maxStackSize; s *= 4 {
318 trace = make([]byte, s)
319 nbytes := runtime.Stack(trace, all)
320 if nbytes == s {
321 continue
322 }
323 return trace[:nbytes]
324 }
325 trace = append(trace, []byte("\n\n...<too large, truncated>")...)
326 return trace
327 }
328 329 // stackRegexp matches one level within a stack trace.
330 var stackRegexp = regexp.MustCompile("(?m)^\\S+\\(.*\\)$\\r?\\n^\\t\\S+:\\d+.*$\\r?\\n")
331 332 // LocalStack returns the local goroutine stack, excluding the top N entries.
333 // LocalStack's own entry is excluded by default and does not need to be counted in excludeTopN.
334 func LocalStack(excludeTopN int) []byte {
335 replaceNext := excludeTopN + 1
336 return stackRegexp.ReplaceAllFunc(Stacks(false), func(s []byte) []byte {
337 if replaceNext > 0 {
338 replaceNext--
339 return nil
340 }
341 return s
342 })
343 }
344 345 // Traceback logs the given message and dumps a stacktrace of the current
346 // goroutine.
347 //
348 // This will be print a traceback, tb, as Warningf(format+":\n%s", v..., tb).
349 func Traceback(format string, v ...any) {
350 v = append(v, Stacks(false))
351 Warningf(format+":\n%s", v...)
352 }
353 354 // TracebackAll logs the given message and dumps a stacktrace of all goroutines.
355 //
356 // This will be print a traceback, tb, as Warningf(format+":\n%s", v..., tb).
357 func TracebackAll(format string, v ...any) {
358 v = append(v, Stacks(true))
359 Warningf(format+":\n%s", v...)
360 }
361 362 // IsLogging returns whether the global logger is logging.
363 func IsLogging(level Level) bool {
364 return Log().IsLogging(level)
365 }
366 367 // CopyStandardLogTo redirects the stdlib log package global output to the global
368 // logger for the specified level.
369 func CopyStandardLogTo(l Level) error {
370 var f func(string, ...any)
371 372 switch l {
373 case Debug:
374 f = Debugf
375 case Info:
376 f = Infof
377 case Warning:
378 f = Warningf
379 default:
380 return fmt.Errorf("unknown log level %v", l)
381 }
382 383 stdlog.SetOutput(linewriter.NewWriter(func(p []byte) {
384 // We must not retain p, but log formatting is not required to
385 // be synchronous (though the in-package implementations are),
386 // so we must make a copy.
387 b := make([]byte, len(p))
388 copy(b, p)
389 390 f("%s", b)
391 }))
392 393 return nil
394 }
395 396 func init() {
397 // Store the initial value for the log.
398 log.Store(&BasicLogger{Level: Info, Emitter: GoogleEmitter{&Writer{Next: os.Stderr}}})
399 }
400