blob: a3dddeadfcfcccde3291ee7c32fb5385eba4da24 [file] [log] [blame]
Scott Bakere7144bc2019-10-01 14:16:47 -07001// Go support for leveled logs, analogous to https://code.google.com/p/google-glog/
2//
3// Copyright 2013 Google Inc. All Rights Reserved.
4//
5// Licensed under the Apache License, Version 2.0 (the "License");
6// you may not use this file except in compliance with the License.
7// You may obtain a copy of the License at
8//
9// http://www.apache.org/licenses/LICENSE-2.0
10//
11// Unless required by applicable law or agreed to in writing, software
12// distributed under the License is distributed on an "AS IS" BASIS,
13// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14// See the License for the specific language governing permissions and
15// limitations under the License.
16
17// Package klog implements logging analogous to the Google-internal C++ INFO/ERROR/V setup.
18// It provides functions Info, Warning, Error, Fatal, plus formatting variants such as
19// Infof. It also provides V-style logging controlled by the -v and -vmodule=file=2 flags.
20//
21// Basic examples:
22//
23// glog.Info("Prepare to repel boarders")
24//
25// glog.Fatalf("Initialization failed: %s", err)
26//
27// See the documentation for the V function for an explanation of these examples:
28//
29// if glog.V(2) {
30// glog.Info("Starting transaction...")
31// }
32//
33// glog.V(2).Infoln("Processed", nItems, "elements")
34//
35// Log output is buffered and written periodically using Flush. Programs
36// should call Flush before exiting to guarantee all log output is written.
37//
38// By default, all log statements write to files in a temporary directory.
39// This package provides several flags that modify this behavior.
40// As a result, flag.Parse must be called before any logging is done.
41//
42// -logtostderr=false
43// Logs are written to standard error instead of to files.
44// -alsologtostderr=false
45// Logs are written to standard error as well as to files.
girishke7ca43b2019-10-10 12:30:03 +000046// -stderrthreshold=ERROR
Scott Bakere7144bc2019-10-01 14:16:47 -070047// Log events at or above this severity are logged to standard
48// error as well as to files.
49// -log_dir=""
50// Log files will be written to this directory instead of the
51// default temporary directory.
52//
53// Other flags provide aids to debugging.
54//
55// -log_backtrace_at=""
56// When set to a file and line number holding a logging statement,
57// such as
58// -log_backtrace_at=gopherflakes.go:234
59// a stack trace will be written to the Info log whenever execution
60// hits that statement. (Unlike with -vmodule, the ".go" must be
61// present.)
62// -v=0
63// Enable V-leveled logging at the specified level.
64// -vmodule=""
65// The syntax of the argument is a comma-separated list of pattern=N,
66// where pattern is a literal file name (minus the ".go" suffix) or
67// "glob" pattern and N is a V level. For instance,
68// -vmodule=gopher*=3
69// sets the V level to 3 in all Go files whose names begin "gopher".
70//
71package klog
72
73import (
74 "bufio"
75 "bytes"
76 "errors"
77 "flag"
78 "fmt"
79 "io"
80 stdLog "log"
girishke7ca43b2019-10-10 12:30:03 +000081 "math"
Scott Bakere7144bc2019-10-01 14:16:47 -070082 "os"
83 "path/filepath"
84 "runtime"
85 "strconv"
86 "strings"
87 "sync"
88 "sync/atomic"
89 "time"
90)
91
92// severity identifies the sort of log: info, warning etc. It also implements
93// the flag.Value interface. The -stderrthreshold flag is of type severity and
94// should be modified only through the flag.Value interface. The values match
95// the corresponding constants in C++.
96type severity int32 // sync/atomic int32
97
98// These constants identify the log levels in order of increasing severity.
99// A message written to a high-severity log file is also written to each
100// lower-severity log file.
101const (
102 infoLog severity = iota
103 warningLog
104 errorLog
105 fatalLog
106 numSeverity = 4
107)
108
109const severityChar = "IWEF"
110
111var severityName = []string{
112 infoLog: "INFO",
113 warningLog: "WARNING",
114 errorLog: "ERROR",
115 fatalLog: "FATAL",
116}
117
118// get returns the value of the severity.
119func (s *severity) get() severity {
120 return severity(atomic.LoadInt32((*int32)(s)))
121}
122
123// set sets the value of the severity.
124func (s *severity) set(val severity) {
125 atomic.StoreInt32((*int32)(s), int32(val))
126}
127
128// String is part of the flag.Value interface.
129func (s *severity) String() string {
130 return strconv.FormatInt(int64(*s), 10)
131}
132
133// Get is part of the flag.Value interface.
134func (s *severity) Get() interface{} {
135 return *s
136}
137
138// Set is part of the flag.Value interface.
139func (s *severity) Set(value string) error {
140 var threshold severity
141 // Is it a known name?
142 if v, ok := severityByName(value); ok {
143 threshold = v
144 } else {
145 v, err := strconv.Atoi(value)
146 if err != nil {
147 return err
148 }
149 threshold = severity(v)
150 }
151 logging.stderrThreshold.set(threshold)
152 return nil
153}
154
155func severityByName(s string) (severity, bool) {
156 s = strings.ToUpper(s)
157 for i, name := range severityName {
158 if name == s {
159 return severity(i), true
160 }
161 }
162 return 0, false
163}
164
165// OutputStats tracks the number of output lines and bytes written.
166type OutputStats struct {
167 lines int64
168 bytes int64
169}
170
171// Lines returns the number of lines written.
172func (s *OutputStats) Lines() int64 {
173 return atomic.LoadInt64(&s.lines)
174}
175
176// Bytes returns the number of bytes written.
177func (s *OutputStats) Bytes() int64 {
178 return atomic.LoadInt64(&s.bytes)
179}
180
181// Stats tracks the number of lines of output and number of bytes
182// per severity level. Values must be read with atomic.LoadInt64.
183var Stats struct {
184 Info, Warning, Error OutputStats
185}
186
187var severityStats = [numSeverity]*OutputStats{
188 infoLog: &Stats.Info,
189 warningLog: &Stats.Warning,
190 errorLog: &Stats.Error,
191}
192
193// Level is exported because it appears in the arguments to V and is
194// the type of the v flag, which can be set programmatically.
195// It's a distinct type because we want to discriminate it from logType.
196// Variables of type level are only changed under logging.mu.
197// The -v flag is read only with atomic ops, so the state of the logging
198// module is consistent.
199
200// Level is treated as a sync/atomic int32.
201
202// Level specifies a level of verbosity for V logs. *Level implements
203// flag.Value; the -v flag is of type Level and should be modified
204// only through the flag.Value interface.
205type Level int32
206
207// get returns the value of the Level.
208func (l *Level) get() Level {
209 return Level(atomic.LoadInt32((*int32)(l)))
210}
211
212// set sets the value of the Level.
213func (l *Level) set(val Level) {
214 atomic.StoreInt32((*int32)(l), int32(val))
215}
216
217// String is part of the flag.Value interface.
218func (l *Level) String() string {
219 return strconv.FormatInt(int64(*l), 10)
220}
221
222// Get is part of the flag.Value interface.
223func (l *Level) Get() interface{} {
224 return *l
225}
226
227// Set is part of the flag.Value interface.
228func (l *Level) Set(value string) error {
229 v, err := strconv.Atoi(value)
230 if err != nil {
231 return err
232 }
233 logging.mu.Lock()
234 defer logging.mu.Unlock()
235 logging.setVState(Level(v), logging.vmodule.filter, false)
236 return nil
237}
238
239// moduleSpec represents the setting of the -vmodule flag.
240type moduleSpec struct {
241 filter []modulePat
242}
243
244// modulePat contains a filter for the -vmodule flag.
245// It holds a verbosity level and a file pattern to match.
246type modulePat struct {
247 pattern string
248 literal bool // The pattern is a literal string
249 level Level
250}
251
252// match reports whether the file matches the pattern. It uses a string
253// comparison if the pattern contains no metacharacters.
254func (m *modulePat) match(file string) bool {
255 if m.literal {
256 return file == m.pattern
257 }
258 match, _ := filepath.Match(m.pattern, file)
259 return match
260}
261
262func (m *moduleSpec) String() string {
263 // Lock because the type is not atomic. TODO: clean this up.
264 logging.mu.Lock()
265 defer logging.mu.Unlock()
266 var b bytes.Buffer
267 for i, f := range m.filter {
268 if i > 0 {
269 b.WriteRune(',')
270 }
271 fmt.Fprintf(&b, "%s=%d", f.pattern, f.level)
272 }
273 return b.String()
274}
275
276// Get is part of the (Go 1.2) flag.Getter interface. It always returns nil for this flag type since the
277// struct is not exported.
278func (m *moduleSpec) Get() interface{} {
279 return nil
280}
281
282var errVmoduleSyntax = errors.New("syntax error: expect comma-separated list of filename=N")
283
284// Syntax: -vmodule=recordio=2,file=1,gfs*=3
285func (m *moduleSpec) Set(value string) error {
286 var filter []modulePat
287 for _, pat := range strings.Split(value, ",") {
288 if len(pat) == 0 {
289 // Empty strings such as from a trailing comma can be ignored.
290 continue
291 }
292 patLev := strings.Split(pat, "=")
293 if len(patLev) != 2 || len(patLev[0]) == 0 || len(patLev[1]) == 0 {
294 return errVmoduleSyntax
295 }
296 pattern := patLev[0]
297 v, err := strconv.Atoi(patLev[1])
298 if err != nil {
299 return errors.New("syntax error: expect comma-separated list of filename=N")
300 }
301 if v < 0 {
302 return errors.New("negative value for vmodule level")
303 }
304 if v == 0 {
305 continue // Ignore. It's harmless but no point in paying the overhead.
306 }
307 // TODO: check syntax of filter?
308 filter = append(filter, modulePat{pattern, isLiteral(pattern), Level(v)})
309 }
310 logging.mu.Lock()
311 defer logging.mu.Unlock()
312 logging.setVState(logging.verbosity, filter, true)
313 return nil
314}
315
316// isLiteral reports whether the pattern is a literal string, that is, has no metacharacters
317// that require filepath.Match to be called to match the pattern.
318func isLiteral(pattern string) bool {
319 return !strings.ContainsAny(pattern, `\*?[]`)
320}
321
322// traceLocation represents the setting of the -log_backtrace_at flag.
323type traceLocation struct {
324 file string
325 line int
326}
327
328// isSet reports whether the trace location has been specified.
329// logging.mu is held.
330func (t *traceLocation) isSet() bool {
331 return t.line > 0
332}
333
334// match reports whether the specified file and line matches the trace location.
335// The argument file name is the full path, not the basename specified in the flag.
336// logging.mu is held.
337func (t *traceLocation) match(file string, line int) bool {
338 if t.line != line {
339 return false
340 }
341 if i := strings.LastIndex(file, "/"); i >= 0 {
342 file = file[i+1:]
343 }
344 return t.file == file
345}
346
347func (t *traceLocation) String() string {
348 // Lock because the type is not atomic. TODO: clean this up.
349 logging.mu.Lock()
350 defer logging.mu.Unlock()
351 return fmt.Sprintf("%s:%d", t.file, t.line)
352}
353
354// Get is part of the (Go 1.2) flag.Getter interface. It always returns nil for this flag type since the
355// struct is not exported
356func (t *traceLocation) Get() interface{} {
357 return nil
358}
359
360var errTraceSyntax = errors.New("syntax error: expect file.go:234")
361
362// Syntax: -log_backtrace_at=gopherflakes.go:234
363// Note that unlike vmodule the file extension is included here.
364func (t *traceLocation) Set(value string) error {
365 if value == "" {
366 // Unset.
367 t.line = 0
368 t.file = ""
369 }
370 fields := strings.Split(value, ":")
371 if len(fields) != 2 {
372 return errTraceSyntax
373 }
374 file, line := fields[0], fields[1]
375 if !strings.Contains(file, ".") {
376 return errTraceSyntax
377 }
378 v, err := strconv.Atoi(line)
379 if err != nil {
380 return errTraceSyntax
381 }
382 if v <= 0 {
383 return errors.New("negative or zero value for level")
384 }
385 logging.mu.Lock()
386 defer logging.mu.Unlock()
387 t.line = v
388 t.file = file
389 return nil
390}
391
392// flushSyncWriter is the interface satisfied by logging destinations.
393type flushSyncWriter interface {
394 Flush() error
395 Sync() error
396 io.Writer
397}
398
399func init() {
girishke7ca43b2019-10-10 12:30:03 +0000400 // Default stderrThreshold is ERROR.
401 logging.stderrThreshold = errorLog
Scott Bakere7144bc2019-10-01 14:16:47 -0700402
403 logging.setVState(0, nil, false)
404 go logging.flushDaemon()
405}
406
girishke7ca43b2019-10-10 12:30:03 +0000407var initDefaultsOnce sync.Once
408
409// InitFlags is for explicitly initializing the flags.
Scott Bakere7144bc2019-10-01 14:16:47 -0700410func InitFlags(flagset *flag.FlagSet) {
girishke7ca43b2019-10-10 12:30:03 +0000411
412 // Initialize defaults.
413 initDefaultsOnce.Do(func() {
414 logging.logDir = ""
415 logging.logFile = ""
416 logging.logFileMaxSizeMB = 1800
417 logging.toStderr = true
418 logging.alsoToStderr = false
419 logging.skipHeaders = false
420 logging.skipLogHeaders = false
421 })
422
Scott Bakere7144bc2019-10-01 14:16:47 -0700423 if flagset == nil {
424 flagset = flag.CommandLine
425 }
girishke7ca43b2019-10-10 12:30:03 +0000426
427 flagset.StringVar(&logging.logDir, "log_dir", logging.logDir, "If non-empty, write log files in this directory")
428 flagset.StringVar(&logging.logFile, "log_file", logging.logFile, "If non-empty, use this log file")
429 flagset.Uint64Var(&logging.logFileMaxSizeMB, "log_file_max_size", logging.logFileMaxSizeMB,
430 "Defines the maximum size a log file can grow to. Unit is megabytes. "+
431 "If the value is 0, the maximum file size is unlimited.")
432 flagset.BoolVar(&logging.toStderr, "logtostderr", logging.toStderr, "log to standard error instead of files")
433 flagset.BoolVar(&logging.alsoToStderr, "alsologtostderr", logging.alsoToStderr, "log to standard error as well as files")
Scott Bakere7144bc2019-10-01 14:16:47 -0700434 flagset.Var(&logging.verbosity, "v", "number for the log level verbosity")
girishke7ca43b2019-10-10 12:30:03 +0000435 flagset.BoolVar(&logging.skipHeaders, "skip_headers", logging.skipHeaders, "If true, avoid header prefixes in the log messages")
436 flagset.BoolVar(&logging.skipLogHeaders, "skip_log_headers", logging.skipLogHeaders, "If true, avoid headers when opening log files")
Scott Bakere7144bc2019-10-01 14:16:47 -0700437 flagset.Var(&logging.stderrThreshold, "stderrthreshold", "logs at or above this threshold go to stderr")
438 flagset.Var(&logging.vmodule, "vmodule", "comma-separated list of pattern=N settings for file-filtered logging")
439 flagset.Var(&logging.traceLocation, "log_backtrace_at", "when logging hits line file:N, emit a stack trace")
440}
441
442// Flush flushes all pending log I/O.
443func Flush() {
444 logging.lockAndFlushAll()
445}
446
447// loggingT collects all the global state of the logging setup.
448type loggingT struct {
449 // Boolean flags. Not handled atomically because the flag.Value interface
450 // does not let us avoid the =true, and that shorthand is necessary for
451 // compatibility. TODO: does this matter enough to fix? Seems unlikely.
452 toStderr bool // The -logtostderr flag.
453 alsoToStderr bool // The -alsologtostderr flag.
454
455 // Level flag. Handled atomically.
456 stderrThreshold severity // The -stderrthreshold flag.
457
458 // freeList is a list of byte buffers, maintained under freeListMu.
459 freeList *buffer
460 // freeListMu maintains the free list. It is separate from the main mutex
461 // so buffers can be grabbed and printed to without holding the main lock,
462 // for better parallelization.
463 freeListMu sync.Mutex
464
465 // mu protects the remaining elements of this structure and is
466 // used to synchronize logging.
467 mu sync.Mutex
468 // file holds writer for each of the log types.
469 file [numSeverity]flushSyncWriter
470 // pcs is used in V to avoid an allocation when computing the caller's PC.
471 pcs [1]uintptr
472 // vmap is a cache of the V Level for each V() call site, identified by PC.
473 // It is wiped whenever the vmodule flag changes state.
474 vmap map[uintptr]Level
475 // filterLength stores the length of the vmodule filter chain. If greater
476 // than zero, it means vmodule is enabled. It may be read safely
477 // using sync.LoadInt32, but is only modified under mu.
478 filterLength int32
479 // traceLocation is the state of the -log_backtrace_at flag.
480 traceLocation traceLocation
481 // These flags are modified only under lock, although verbosity may be fetched
482 // safely using atomic.LoadInt32.
483 vmodule moduleSpec // The state of the -vmodule flag.
484 verbosity Level // V logging level, the value of the -v flag/
485
486 // If non-empty, overrides the choice of directory in which to write logs.
487 // See createLogDirs for the full list of possible destinations.
488 logDir string
489
490 // If non-empty, specifies the path of the file to write logs. mutually exclusive
491 // with the log-dir option.
492 logFile string
493
girishke7ca43b2019-10-10 12:30:03 +0000494 // When logFile is specified, this limiter makes sure the logFile won't exceeds a certain size. When exceeds, the
495 // logFile will be cleaned up. If this value is 0, no size limitation will be applied to logFile.
496 logFileMaxSizeMB uint64
497
Scott Bakere7144bc2019-10-01 14:16:47 -0700498 // If true, do not add the prefix headers, useful when used with SetOutput
499 skipHeaders bool
girishke7ca43b2019-10-10 12:30:03 +0000500
501 // If true, do not add the headers to log files
502 skipLogHeaders bool
Scott Bakere7144bc2019-10-01 14:16:47 -0700503}
504
505// buffer holds a byte Buffer for reuse. The zero value is ready for use.
506type buffer struct {
507 bytes.Buffer
508 tmp [64]byte // temporary byte array for creating headers.
509 next *buffer
510}
511
512var logging loggingT
513
514// setVState sets a consistent state for V logging.
515// l.mu is held.
516func (l *loggingT) setVState(verbosity Level, filter []modulePat, setFilter bool) {
517 // Turn verbosity off so V will not fire while we are in transition.
518 logging.verbosity.set(0)
519 // Ditto for filter length.
520 atomic.StoreInt32(&logging.filterLength, 0)
521
522 // Set the new filters and wipe the pc->Level map if the filter has changed.
523 if setFilter {
524 logging.vmodule.filter = filter
525 logging.vmap = make(map[uintptr]Level)
526 }
527
528 // Things are consistent now, so enable filtering and verbosity.
529 // They are enabled in order opposite to that in V.
530 atomic.StoreInt32(&logging.filterLength, int32(len(filter)))
531 logging.verbosity.set(verbosity)
532}
533
534// getBuffer returns a new, ready-to-use buffer.
535func (l *loggingT) getBuffer() *buffer {
536 l.freeListMu.Lock()
537 b := l.freeList
538 if b != nil {
539 l.freeList = b.next
540 }
541 l.freeListMu.Unlock()
542 if b == nil {
543 b = new(buffer)
544 } else {
545 b.next = nil
546 b.Reset()
547 }
548 return b
549}
550
551// putBuffer returns a buffer to the free list.
552func (l *loggingT) putBuffer(b *buffer) {
553 if b.Len() >= 256 {
554 // Let big buffers die a natural death.
555 return
556 }
557 l.freeListMu.Lock()
558 b.next = l.freeList
559 l.freeList = b
560 l.freeListMu.Unlock()
561}
562
563var timeNow = time.Now // Stubbed out for testing.
564
565/*
566header formats a log header as defined by the C++ implementation.
567It returns a buffer containing the formatted header and the user's file and line number.
568The depth specifies how many stack frames above lives the source line to be identified in the log message.
569
570Log lines have this form:
571 Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg...
572where the fields are defined as follows:
573 L A single character, representing the log level (eg 'I' for INFO)
574 mm The month (zero padded; ie May is '05')
575 dd The day (zero padded)
576 hh:mm:ss.uuuuuu Time in hours, minutes and fractional seconds
577 threadid The space-padded thread ID as returned by GetTID()
578 file The file name
579 line The line number
580 msg The user-supplied message
581*/
582func (l *loggingT) header(s severity, depth int) (*buffer, string, int) {
583 _, file, line, ok := runtime.Caller(3 + depth)
584 if !ok {
585 file = "???"
586 line = 1
587 } else {
588 slash := strings.LastIndex(file, "/")
589 if slash >= 0 {
590 file = file[slash+1:]
591 }
592 }
593 return l.formatHeader(s, file, line), file, line
594}
595
596// formatHeader formats a log header using the provided file name and line number.
597func (l *loggingT) formatHeader(s severity, file string, line int) *buffer {
598 now := timeNow()
599 if line < 0 {
600 line = 0 // not a real line number, but acceptable to someDigits
601 }
602 if s > fatalLog {
603 s = infoLog // for safety.
604 }
605 buf := l.getBuffer()
606 if l.skipHeaders {
607 return buf
608 }
609
610 // Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
611 // It's worth about 3X. Fprintf is hard.
612 _, month, day := now.Date()
613 hour, minute, second := now.Clock()
614 // Lmmdd hh:mm:ss.uuuuuu threadid file:line]
615 buf.tmp[0] = severityChar[s]
616 buf.twoDigits(1, int(month))
617 buf.twoDigits(3, day)
618 buf.tmp[5] = ' '
619 buf.twoDigits(6, hour)
620 buf.tmp[8] = ':'
621 buf.twoDigits(9, minute)
622 buf.tmp[11] = ':'
623 buf.twoDigits(12, second)
624 buf.tmp[14] = '.'
625 buf.nDigits(6, 15, now.Nanosecond()/1000, '0')
626 buf.tmp[21] = ' '
627 buf.nDigits(7, 22, pid, ' ') // TODO: should be TID
628 buf.tmp[29] = ' '
629 buf.Write(buf.tmp[:30])
630 buf.WriteString(file)
631 buf.tmp[0] = ':'
632 n := buf.someDigits(1, line)
633 buf.tmp[n+1] = ']'
634 buf.tmp[n+2] = ' '
635 buf.Write(buf.tmp[:n+3])
636 return buf
637}
638
639// Some custom tiny helper functions to print the log header efficiently.
640
641const digits = "0123456789"
642
643// twoDigits formats a zero-prefixed two-digit integer at buf.tmp[i].
644func (buf *buffer) twoDigits(i, d int) {
645 buf.tmp[i+1] = digits[d%10]
646 d /= 10
647 buf.tmp[i] = digits[d%10]
648}
649
650// nDigits formats an n-digit integer at buf.tmp[i],
651// padding with pad on the left.
652// It assumes d >= 0.
653func (buf *buffer) nDigits(n, i, d int, pad byte) {
654 j := n - 1
655 for ; j >= 0 && d > 0; j-- {
656 buf.tmp[i+j] = digits[d%10]
657 d /= 10
658 }
659 for ; j >= 0; j-- {
660 buf.tmp[i+j] = pad
661 }
662}
663
664// someDigits formats a zero-prefixed variable-width integer at buf.tmp[i].
665func (buf *buffer) someDigits(i, d int) int {
666 // Print into the top, then copy down. We know there's space for at least
667 // a 10-digit number.
668 j := len(buf.tmp)
669 for {
670 j--
671 buf.tmp[j] = digits[d%10]
672 d /= 10
673 if d == 0 {
674 break
675 }
676 }
677 return copy(buf.tmp[i:], buf.tmp[j:])
678}
679
680func (l *loggingT) println(s severity, args ...interface{}) {
681 buf, file, line := l.header(s, 0)
682 fmt.Fprintln(buf, args...)
683 l.output(s, buf, file, line, false)
684}
685
686func (l *loggingT) print(s severity, args ...interface{}) {
687 l.printDepth(s, 1, args...)
688}
689
690func (l *loggingT) printDepth(s severity, depth int, args ...interface{}) {
691 buf, file, line := l.header(s, depth)
692 fmt.Fprint(buf, args...)
693 if buf.Bytes()[buf.Len()-1] != '\n' {
694 buf.WriteByte('\n')
695 }
696 l.output(s, buf, file, line, false)
697}
698
699func (l *loggingT) printf(s severity, format string, args ...interface{}) {
700 buf, file, line := l.header(s, 0)
701 fmt.Fprintf(buf, format, args...)
702 if buf.Bytes()[buf.Len()-1] != '\n' {
703 buf.WriteByte('\n')
704 }
705 l.output(s, buf, file, line, false)
706}
707
708// printWithFileLine behaves like print but uses the provided file and line number. If
709// alsoLogToStderr is true, the log message always appears on standard error; it
710// will also appear in the log file unless --logtostderr is set.
711func (l *loggingT) printWithFileLine(s severity, file string, line int, alsoToStderr bool, args ...interface{}) {
712 buf := l.formatHeader(s, file, line)
713 fmt.Fprint(buf, args...)
714 if buf.Bytes()[buf.Len()-1] != '\n' {
715 buf.WriteByte('\n')
716 }
717 l.output(s, buf, file, line, alsoToStderr)
718}
719
720// redirectBuffer is used to set an alternate destination for the logs
721type redirectBuffer struct {
722 w io.Writer
723}
724
725func (rb *redirectBuffer) Sync() error {
726 return nil
727}
728
729func (rb *redirectBuffer) Flush() error {
730 return nil
731}
732
733func (rb *redirectBuffer) Write(bytes []byte) (n int, err error) {
734 return rb.w.Write(bytes)
735}
736
737// SetOutput sets the output destination for all severities
738func SetOutput(w io.Writer) {
739 for s := fatalLog; s >= infoLog; s-- {
740 rb := &redirectBuffer{
741 w: w,
742 }
743 logging.file[s] = rb
744 }
745}
746
747// SetOutputBySeverity sets the output destination for specific severity
748func SetOutputBySeverity(name string, w io.Writer) {
749 sev, ok := severityByName(name)
750 if !ok {
751 panic(fmt.Sprintf("SetOutputBySeverity(%q): unrecognized severity name", name))
752 }
753 rb := &redirectBuffer{
754 w: w,
755 }
756 logging.file[sev] = rb
757}
758
759// output writes the data to the log files and releases the buffer.
760func (l *loggingT) output(s severity, buf *buffer, file string, line int, alsoToStderr bool) {
761 l.mu.Lock()
762 if l.traceLocation.isSet() {
763 if l.traceLocation.match(file, line) {
764 buf.Write(stacks(false))
765 }
766 }
767 data := buf.Bytes()
768 if l.toStderr {
girishke7ca43b2019-10-10 12:30:03 +0000769 os.Stderr.Write(data)
Scott Bakere7144bc2019-10-01 14:16:47 -0700770 } else {
771 if alsoToStderr || l.alsoToStderr || s >= l.stderrThreshold.get() {
772 os.Stderr.Write(data)
773 }
774 if l.file[s] == nil {
775 if err := l.createFiles(s); err != nil {
776 os.Stderr.Write(data) // Make sure the message appears somewhere.
777 l.exit(err)
778 }
779 }
780 switch s {
781 case fatalLog:
782 l.file[fatalLog].Write(data)
783 fallthrough
784 case errorLog:
785 l.file[errorLog].Write(data)
786 fallthrough
787 case warningLog:
788 l.file[warningLog].Write(data)
789 fallthrough
790 case infoLog:
791 l.file[infoLog].Write(data)
792 }
793 }
794 if s == fatalLog {
795 // If we got here via Exit rather than Fatal, print no stacks.
796 if atomic.LoadUint32(&fatalNoStacks) > 0 {
797 l.mu.Unlock()
798 timeoutFlush(10 * time.Second)
799 os.Exit(1)
800 }
801 // Dump all goroutine stacks before exiting.
802 // First, make sure we see the trace for the current goroutine on standard error.
803 // If -logtostderr has been specified, the loop below will do that anyway
804 // as the first stack in the full dump.
805 if !l.toStderr {
806 os.Stderr.Write(stacks(false))
807 }
808 // Write the stack trace for all goroutines to the files.
809 trace := stacks(true)
810 logExitFunc = func(error) {} // If we get a write error, we'll still exit below.
811 for log := fatalLog; log >= infoLog; log-- {
812 if f := l.file[log]; f != nil { // Can be nil if -logtostderr is set.
813 f.Write(trace)
814 }
815 }
816 l.mu.Unlock()
817 timeoutFlush(10 * time.Second)
818 os.Exit(255) // C++ uses -1, which is silly because it's anded with 255 anyway.
819 }
820 l.putBuffer(buf)
821 l.mu.Unlock()
822 if stats := severityStats[s]; stats != nil {
823 atomic.AddInt64(&stats.lines, 1)
824 atomic.AddInt64(&stats.bytes, int64(len(data)))
825 }
826}
827
828// timeoutFlush calls Flush and returns when it completes or after timeout
829// elapses, whichever happens first. This is needed because the hooks invoked
830// by Flush may deadlock when glog.Fatal is called from a hook that holds
831// a lock.
832func timeoutFlush(timeout time.Duration) {
833 done := make(chan bool, 1)
834 go func() {
835 Flush() // calls logging.lockAndFlushAll()
836 done <- true
837 }()
838 select {
839 case <-done:
840 case <-time.After(timeout):
841 fmt.Fprintln(os.Stderr, "glog: Flush took longer than", timeout)
842 }
843}
844
845// stacks is a wrapper for runtime.Stack that attempts to recover the data for all goroutines.
846func stacks(all bool) []byte {
847 // We don't know how big the traces are, so grow a few times if they don't fit. Start large, though.
848 n := 10000
849 if all {
850 n = 100000
851 }
852 var trace []byte
853 for i := 0; i < 5; i++ {
854 trace = make([]byte, n)
855 nbytes := runtime.Stack(trace, all)
856 if nbytes < len(trace) {
857 return trace[:nbytes]
858 }
859 n *= 2
860 }
861 return trace
862}
863
864// logExitFunc provides a simple mechanism to override the default behavior
865// of exiting on error. Used in testing and to guarantee we reach a required exit
866// for fatal logs. Instead, exit could be a function rather than a method but that
867// would make its use clumsier.
868var logExitFunc func(error)
869
870// exit is called if there is trouble creating or writing log files.
871// It flushes the logs and exits the program; there's no point in hanging around.
872// l.mu is held.
873func (l *loggingT) exit(err error) {
874 fmt.Fprintf(os.Stderr, "log: exiting because of error: %s\n", err)
875 // If logExitFunc is set, we do that instead of exiting.
876 if logExitFunc != nil {
877 logExitFunc(err)
878 return
879 }
880 l.flushAll()
881 os.Exit(2)
882}
883
884// syncBuffer joins a bufio.Writer to its underlying file, providing access to the
885// file's Sync method and providing a wrapper for the Write method that provides log
886// file rotation. There are conflicting methods, so the file cannot be embedded.
887// l.mu is held for all its methods.
888type syncBuffer struct {
889 logger *loggingT
890 *bufio.Writer
girishke7ca43b2019-10-10 12:30:03 +0000891 file *os.File
892 sev severity
893 nbytes uint64 // The number of bytes written to this file
894 maxbytes uint64 // The max number of bytes this syncBuffer.file can hold before cleaning up.
Scott Bakere7144bc2019-10-01 14:16:47 -0700895}
896
897func (sb *syncBuffer) Sync() error {
898 return sb.file.Sync()
899}
900
girishke7ca43b2019-10-10 12:30:03 +0000901// CalculateMaxSize returns the real max size in bytes after considering the default max size and the flag options.
902func CalculateMaxSize() uint64 {
903 if logging.logFile != "" {
904 if logging.logFileMaxSizeMB == 0 {
905 // If logFileMaxSizeMB is zero, we don't have limitations on the log size.
906 return math.MaxUint64
907 }
908 // Flag logFileMaxSizeMB is in MB for user convenience.
909 return logging.logFileMaxSizeMB * 1024 * 1024
910 }
911 // If "log_file" flag is not specified, the target file (sb.file) will be cleaned up when reaches a fixed size.
912 return MaxSize
913}
914
Scott Bakere7144bc2019-10-01 14:16:47 -0700915func (sb *syncBuffer) Write(p []byte) (n int, err error) {
girishke7ca43b2019-10-10 12:30:03 +0000916 if sb.nbytes+uint64(len(p)) >= sb.maxbytes {
917 if err := sb.rotateFile(time.Now(), false); err != nil {
Scott Bakere7144bc2019-10-01 14:16:47 -0700918 sb.logger.exit(err)
919 }
920 }
921 n, err = sb.Writer.Write(p)
922 sb.nbytes += uint64(n)
923 if err != nil {
924 sb.logger.exit(err)
925 }
926 return
927}
928
929// rotateFile closes the syncBuffer's file and starts a new one.
girishke7ca43b2019-10-10 12:30:03 +0000930// The startup argument indicates whether this is the initial startup of klog.
931// If startup is true, existing files are opened for appending instead of truncated.
932func (sb *syncBuffer) rotateFile(now time.Time, startup bool) error {
Scott Bakere7144bc2019-10-01 14:16:47 -0700933 if sb.file != nil {
934 sb.Flush()
935 sb.file.Close()
936 }
937 var err error
girishke7ca43b2019-10-10 12:30:03 +0000938 sb.file, _, err = create(severityName[sb.sev], now, startup)
Scott Bakere7144bc2019-10-01 14:16:47 -0700939 sb.nbytes = 0
940 if err != nil {
941 return err
942 }
943
944 sb.Writer = bufio.NewWriterSize(sb.file, bufferSize)
945
girishke7ca43b2019-10-10 12:30:03 +0000946 if sb.logger.skipLogHeaders {
947 return nil
948 }
949
Scott Bakere7144bc2019-10-01 14:16:47 -0700950 // Write header.
951 var buf bytes.Buffer
952 fmt.Fprintf(&buf, "Log file created at: %s\n", now.Format("2006/01/02 15:04:05"))
953 fmt.Fprintf(&buf, "Running on machine: %s\n", host)
954 fmt.Fprintf(&buf, "Binary: Built with %s %s for %s/%s\n", runtime.Compiler, runtime.Version(), runtime.GOOS, runtime.GOARCH)
955 fmt.Fprintf(&buf, "Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg\n")
956 n, err := sb.file.Write(buf.Bytes())
957 sb.nbytes += uint64(n)
958 return err
959}
960
961// bufferSize sizes the buffer associated with each log file. It's large
962// so that log records can accumulate without the logging thread blocking
963// on disk I/O. The flushDaemon will block instead.
964const bufferSize = 256 * 1024
965
966// createFiles creates all the log files for severity from sev down to infoLog.
967// l.mu is held.
968func (l *loggingT) createFiles(sev severity) error {
969 now := time.Now()
970 // Files are created in decreasing severity order, so as soon as we find one
971 // has already been created, we can stop.
972 for s := sev; s >= infoLog && l.file[s] == nil; s-- {
973 sb := &syncBuffer{
girishke7ca43b2019-10-10 12:30:03 +0000974 logger: l,
975 sev: s,
976 maxbytes: CalculateMaxSize(),
Scott Bakere7144bc2019-10-01 14:16:47 -0700977 }
girishke7ca43b2019-10-10 12:30:03 +0000978 if err := sb.rotateFile(now, true); err != nil {
Scott Bakere7144bc2019-10-01 14:16:47 -0700979 return err
980 }
981 l.file[s] = sb
982 }
983 return nil
984}
985
986const flushInterval = 5 * time.Second
987
988// flushDaemon periodically flushes the log file buffers.
989func (l *loggingT) flushDaemon() {
990 for range time.NewTicker(flushInterval).C {
991 l.lockAndFlushAll()
992 }
993}
994
995// lockAndFlushAll is like flushAll but locks l.mu first.
996func (l *loggingT) lockAndFlushAll() {
997 l.mu.Lock()
998 l.flushAll()
999 l.mu.Unlock()
1000}
1001
1002// flushAll flushes all the logs and attempts to "sync" their data to disk.
1003// l.mu is held.
1004func (l *loggingT) flushAll() {
1005 // Flush from fatal down, in case there's trouble flushing.
1006 for s := fatalLog; s >= infoLog; s-- {
1007 file := l.file[s]
1008 if file != nil {
1009 file.Flush() // ignore error
1010 file.Sync() // ignore error
1011 }
1012 }
1013}
1014
1015// CopyStandardLogTo arranges for messages written to the Go "log" package's
1016// default logs to also appear in the Google logs for the named and lower
1017// severities. Subsequent changes to the standard log's default output location
1018// or format may break this behavior.
1019//
1020// Valid names are "INFO", "WARNING", "ERROR", and "FATAL". If the name is not
1021// recognized, CopyStandardLogTo panics.
1022func CopyStandardLogTo(name string) {
1023 sev, ok := severityByName(name)
1024 if !ok {
1025 panic(fmt.Sprintf("log.CopyStandardLogTo(%q): unrecognized severity name", name))
1026 }
1027 // Set a log format that captures the user's file and line:
1028 // d.go:23: message
1029 stdLog.SetFlags(stdLog.Lshortfile)
1030 stdLog.SetOutput(logBridge(sev))
1031}
1032
1033// logBridge provides the Write method that enables CopyStandardLogTo to connect
1034// Go's standard logs to the logs provided by this package.
1035type logBridge severity
1036
1037// Write parses the standard logging line and passes its components to the
1038// logger for severity(lb).
1039func (lb logBridge) Write(b []byte) (n int, err error) {
1040 var (
1041 file = "???"
1042 line = 1
1043 text string
1044 )
1045 // Split "d.go:23: message" into "d.go", "23", and "message".
1046 if parts := bytes.SplitN(b, []byte{':'}, 3); len(parts) != 3 || len(parts[0]) < 1 || len(parts[2]) < 1 {
1047 text = fmt.Sprintf("bad log format: %s", b)
1048 } else {
1049 file = string(parts[0])
1050 text = string(parts[2][1:]) // skip leading space
1051 line, err = strconv.Atoi(string(parts[1]))
1052 if err != nil {
1053 text = fmt.Sprintf("bad line number: %s", b)
1054 line = 1
1055 }
1056 }
1057 // printWithFileLine with alsoToStderr=true, so standard log messages
1058 // always appear on standard error.
1059 logging.printWithFileLine(severity(lb), file, line, true, text)
1060 return len(b), nil
1061}
1062
1063// setV computes and remembers the V level for a given PC
1064// when vmodule is enabled.
1065// File pattern matching takes the basename of the file, stripped
1066// of its .go suffix, and uses filepath.Match, which is a little more
1067// general than the *? matching used in C++.
1068// l.mu is held.
1069func (l *loggingT) setV(pc uintptr) Level {
1070 fn := runtime.FuncForPC(pc)
1071 file, _ := fn.FileLine(pc)
1072 // The file is something like /a/b/c/d.go. We want just the d.
1073 if strings.HasSuffix(file, ".go") {
1074 file = file[:len(file)-3]
1075 }
1076 if slash := strings.LastIndex(file, "/"); slash >= 0 {
1077 file = file[slash+1:]
1078 }
1079 for _, filter := range l.vmodule.filter {
1080 if filter.match(file) {
1081 l.vmap[pc] = filter.level
1082 return filter.level
1083 }
1084 }
1085 l.vmap[pc] = 0
1086 return 0
1087}
1088
1089// Verbose is a boolean type that implements Infof (like Printf) etc.
1090// See the documentation of V for more information.
1091type Verbose bool
1092
1093// V reports whether verbosity at the call site is at least the requested level.
1094// The returned value is a boolean of type Verbose, which implements Info, Infoln
1095// and Infof. These methods will write to the Info log if called.
1096// Thus, one may write either
1097// if glog.V(2) { glog.Info("log this") }
1098// or
1099// glog.V(2).Info("log this")
1100// The second form is shorter but the first is cheaper if logging is off because it does
1101// not evaluate its arguments.
1102//
1103// Whether an individual call to V generates a log record depends on the setting of
1104// the -v and --vmodule flags; both are off by default. If the level in the call to
1105// V is at least the value of -v, or of -vmodule for the source file containing the
1106// call, the V call will log.
1107func V(level Level) Verbose {
1108 // This function tries hard to be cheap unless there's work to do.
1109 // The fast path is two atomic loads and compares.
1110
1111 // Here is a cheap but safe test to see if V logging is enabled globally.
1112 if logging.verbosity.get() >= level {
1113 return Verbose(true)
1114 }
1115
1116 // It's off globally but it vmodule may still be set.
1117 // Here is another cheap but safe test to see if vmodule is enabled.
1118 if atomic.LoadInt32(&logging.filterLength) > 0 {
1119 // Now we need a proper lock to use the logging structure. The pcs field
1120 // is shared so we must lock before accessing it. This is fairly expensive,
1121 // but if V logging is enabled we're slow anyway.
1122 logging.mu.Lock()
1123 defer logging.mu.Unlock()
1124 if runtime.Callers(2, logging.pcs[:]) == 0 {
1125 return Verbose(false)
1126 }
1127 v, ok := logging.vmap[logging.pcs[0]]
1128 if !ok {
1129 v = logging.setV(logging.pcs[0])
1130 }
1131 return Verbose(v >= level)
1132 }
1133 return Verbose(false)
1134}
1135
1136// Info is equivalent to the global Info function, guarded by the value of v.
1137// See the documentation of V for usage.
1138func (v Verbose) Info(args ...interface{}) {
1139 if v {
1140 logging.print(infoLog, args...)
1141 }
1142}
1143
1144// Infoln is equivalent to the global Infoln function, guarded by the value of v.
1145// See the documentation of V for usage.
1146func (v Verbose) Infoln(args ...interface{}) {
1147 if v {
1148 logging.println(infoLog, args...)
1149 }
1150}
1151
1152// Infof is equivalent to the global Infof function, guarded by the value of v.
1153// See the documentation of V for usage.
1154func (v Verbose) Infof(format string, args ...interface{}) {
1155 if v {
1156 logging.printf(infoLog, format, args...)
1157 }
1158}
1159
1160// Info logs to the INFO log.
1161// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1162func Info(args ...interface{}) {
1163 logging.print(infoLog, args...)
1164}
1165
1166// InfoDepth acts as Info but uses depth to determine which call frame to log.
1167// InfoDepth(0, "msg") is the same as Info("msg").
1168func InfoDepth(depth int, args ...interface{}) {
1169 logging.printDepth(infoLog, depth, args...)
1170}
1171
1172// Infoln logs to the INFO log.
1173// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1174func Infoln(args ...interface{}) {
1175 logging.println(infoLog, args...)
1176}
1177
1178// Infof logs to the INFO log.
1179// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1180func Infof(format string, args ...interface{}) {
1181 logging.printf(infoLog, format, args...)
1182}
1183
1184// Warning logs to the WARNING and INFO logs.
1185// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1186func Warning(args ...interface{}) {
1187 logging.print(warningLog, args...)
1188}
1189
1190// WarningDepth acts as Warning but uses depth to determine which call frame to log.
1191// WarningDepth(0, "msg") is the same as Warning("msg").
1192func WarningDepth(depth int, args ...interface{}) {
1193 logging.printDepth(warningLog, depth, args...)
1194}
1195
1196// Warningln logs to the WARNING and INFO logs.
1197// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1198func Warningln(args ...interface{}) {
1199 logging.println(warningLog, args...)
1200}
1201
1202// Warningf logs to the WARNING and INFO logs.
1203// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1204func Warningf(format string, args ...interface{}) {
1205 logging.printf(warningLog, format, args...)
1206}
1207
1208// Error logs to the ERROR, WARNING, and INFO logs.
1209// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1210func Error(args ...interface{}) {
1211 logging.print(errorLog, args...)
1212}
1213
1214// ErrorDepth acts as Error but uses depth to determine which call frame to log.
1215// ErrorDepth(0, "msg") is the same as Error("msg").
1216func ErrorDepth(depth int, args ...interface{}) {
1217 logging.printDepth(errorLog, depth, args...)
1218}
1219
1220// Errorln logs to the ERROR, WARNING, and INFO logs.
1221// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1222func Errorln(args ...interface{}) {
1223 logging.println(errorLog, args...)
1224}
1225
1226// Errorf logs to the ERROR, WARNING, and INFO logs.
1227// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1228func Errorf(format string, args ...interface{}) {
1229 logging.printf(errorLog, format, args...)
1230}
1231
1232// Fatal logs to the FATAL, ERROR, WARNING, and INFO logs,
1233// including a stack trace of all running goroutines, then calls os.Exit(255).
1234// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1235func Fatal(args ...interface{}) {
1236 logging.print(fatalLog, args...)
1237}
1238
1239// FatalDepth acts as Fatal but uses depth to determine which call frame to log.
1240// FatalDepth(0, "msg") is the same as Fatal("msg").
1241func FatalDepth(depth int, args ...interface{}) {
1242 logging.printDepth(fatalLog, depth, args...)
1243}
1244
1245// Fatalln logs to the FATAL, ERROR, WARNING, and INFO logs,
1246// including a stack trace of all running goroutines, then calls os.Exit(255).
1247// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1248func Fatalln(args ...interface{}) {
1249 logging.println(fatalLog, args...)
1250}
1251
1252// Fatalf logs to the FATAL, ERROR, WARNING, and INFO logs,
1253// including a stack trace of all running goroutines, then calls os.Exit(255).
1254// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1255func Fatalf(format string, args ...interface{}) {
1256 logging.printf(fatalLog, format, args...)
1257}
1258
1259// fatalNoStacks is non-zero if we are to exit without dumping goroutine stacks.
1260// It allows Exit and relatives to use the Fatal logs.
1261var fatalNoStacks uint32
1262
1263// Exit logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1264// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1265func Exit(args ...interface{}) {
1266 atomic.StoreUint32(&fatalNoStacks, 1)
1267 logging.print(fatalLog, args...)
1268}
1269
1270// ExitDepth acts as Exit but uses depth to determine which call frame to log.
1271// ExitDepth(0, "msg") is the same as Exit("msg").
1272func ExitDepth(depth int, args ...interface{}) {
1273 atomic.StoreUint32(&fatalNoStacks, 1)
1274 logging.printDepth(fatalLog, depth, args...)
1275}
1276
1277// Exitln logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1278func Exitln(args ...interface{}) {
1279 atomic.StoreUint32(&fatalNoStacks, 1)
1280 logging.println(fatalLog, args...)
1281}
1282
1283// Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1284// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1285func Exitf(format string, args ...interface{}) {
1286 atomic.StoreUint32(&fatalNoStacks, 1)
1287 logging.printf(fatalLog, format, args...)
1288}