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