blob: 13bcc81a756b9ca3d68974bdc69c3114322b3378 [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.
46// -stderrthreshold=ERROR
47// 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() {
399 // Default stderrThreshold is ERROR.
400 logging.stderrThreshold = errorLog
401
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")
413 flagset.BoolVar(&logging.toStderr, "logtostderr", false, "log to standard error instead of files")
414 flagset.BoolVar(&logging.alsoToStderr, "alsologtostderr", false, "log to standard error as well as files")
415 flagset.Var(&logging.verbosity, "v", "log level for V logs")
416 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 {
742 os.Stderr.Write(data)
743 } else {
744 if alsoToStderr || l.alsoToStderr || s >= l.stderrThreshold.get() {
745 os.Stderr.Write(data)
746 }
747 if l.file[s] == nil {
748 if err := l.createFiles(s); err != nil {
749 os.Stderr.Write(data) // Make sure the message appears somewhere.
750 l.exit(err)
751 }
752 }
753 switch s {
754 case fatalLog:
755 l.file[fatalLog].Write(data)
756 fallthrough
757 case errorLog:
758 l.file[errorLog].Write(data)
759 fallthrough
760 case warningLog:
761 l.file[warningLog].Write(data)
762 fallthrough
763 case infoLog:
764 l.file[infoLog].Write(data)
765 }
766 }
767 if s == fatalLog {
768 // If we got here via Exit rather than Fatal, print no stacks.
769 if atomic.LoadUint32(&fatalNoStacks) > 0 {
770 l.mu.Unlock()
771 timeoutFlush(10 * time.Second)
772 os.Exit(1)
773 }
774 // Dump all goroutine stacks before exiting.
775 // First, make sure we see the trace for the current goroutine on standard error.
776 // If -logtostderr has been specified, the loop below will do that anyway
777 // as the first stack in the full dump.
778 if !l.toStderr {
779 os.Stderr.Write(stacks(false))
780 }
781 // Write the stack trace for all goroutines to the files.
782 trace := stacks(true)
783 logExitFunc = func(error) {} // If we get a write error, we'll still exit below.
784 for log := fatalLog; log >= infoLog; log-- {
785 if f := l.file[log]; f != nil { // Can be nil if -logtostderr is set.
786 f.Write(trace)
787 }
788 }
789 l.mu.Unlock()
790 timeoutFlush(10 * time.Second)
791 os.Exit(255) // C++ uses -1, which is silly because it's anded with 255 anyway.
792 }
793 l.putBuffer(buf)
794 l.mu.Unlock()
795 if stats := severityStats[s]; stats != nil {
796 atomic.AddInt64(&stats.lines, 1)
797 atomic.AddInt64(&stats.bytes, int64(len(data)))
798 }
799}
800
801// timeoutFlush calls Flush and returns when it completes or after timeout
802// elapses, whichever happens first. This is needed because the hooks invoked
803// by Flush may deadlock when glog.Fatal is called from a hook that holds
804// a lock.
805func timeoutFlush(timeout time.Duration) {
806 done := make(chan bool, 1)
807 go func() {
808 Flush() // calls logging.lockAndFlushAll()
809 done <- true
810 }()
811 select {
812 case <-done:
813 case <-time.After(timeout):
814 fmt.Fprintln(os.Stderr, "glog: Flush took longer than", timeout)
815 }
816}
817
818// stacks is a wrapper for runtime.Stack that attempts to recover the data for all goroutines.
819func stacks(all bool) []byte {
820 // We don't know how big the traces are, so grow a few times if they don't fit. Start large, though.
821 n := 10000
822 if all {
823 n = 100000
824 }
825 var trace []byte
826 for i := 0; i < 5; i++ {
827 trace = make([]byte, n)
828 nbytes := runtime.Stack(trace, all)
829 if nbytes < len(trace) {
830 return trace[:nbytes]
831 }
832 n *= 2
833 }
834 return trace
835}
836
837// logExitFunc provides a simple mechanism to override the default behavior
838// of exiting on error. Used in testing and to guarantee we reach a required exit
839// for fatal logs. Instead, exit could be a function rather than a method but that
840// would make its use clumsier.
841var logExitFunc func(error)
842
843// exit is called if there is trouble creating or writing log files.
844// It flushes the logs and exits the program; there's no point in hanging around.
845// l.mu is held.
846func (l *loggingT) exit(err error) {
847 fmt.Fprintf(os.Stderr, "log: exiting because of error: %s\n", err)
848 // If logExitFunc is set, we do that instead of exiting.
849 if logExitFunc != nil {
850 logExitFunc(err)
851 return
852 }
853 l.flushAll()
854 os.Exit(2)
855}
856
857// syncBuffer joins a bufio.Writer to its underlying file, providing access to the
858// file's Sync method and providing a wrapper for the Write method that provides log
859// file rotation. There are conflicting methods, so the file cannot be embedded.
860// l.mu is held for all its methods.
861type syncBuffer struct {
862 logger *loggingT
863 *bufio.Writer
864 file *os.File
865 sev severity
866 nbytes uint64 // The number of bytes written to this file
867}
868
869func (sb *syncBuffer) Sync() error {
870 return sb.file.Sync()
871}
872
873func (sb *syncBuffer) Write(p []byte) (n int, err error) {
874 if sb.nbytes+uint64(len(p)) >= MaxSize {
875 if err := sb.rotateFile(time.Now()); err != nil {
876 sb.logger.exit(err)
877 }
878 }
879 n, err = sb.Writer.Write(p)
880 sb.nbytes += uint64(n)
881 if err != nil {
882 sb.logger.exit(err)
883 }
884 return
885}
886
887// rotateFile closes the syncBuffer's file and starts a new one.
888func (sb *syncBuffer) rotateFile(now time.Time) error {
889 if sb.file != nil {
890 sb.Flush()
891 sb.file.Close()
892 }
893 var err error
894 sb.file, _, err = create(severityName[sb.sev], now)
895 sb.nbytes = 0
896 if err != nil {
897 return err
898 }
899
900 sb.Writer = bufio.NewWriterSize(sb.file, bufferSize)
901
902 // Write header.
903 var buf bytes.Buffer
904 fmt.Fprintf(&buf, "Log file created at: %s\n", now.Format("2006/01/02 15:04:05"))
905 fmt.Fprintf(&buf, "Running on machine: %s\n", host)
906 fmt.Fprintf(&buf, "Binary: Built with %s %s for %s/%s\n", runtime.Compiler, runtime.Version(), runtime.GOOS, runtime.GOARCH)
907 fmt.Fprintf(&buf, "Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg\n")
908 n, err := sb.file.Write(buf.Bytes())
909 sb.nbytes += uint64(n)
910 return err
911}
912
913// bufferSize sizes the buffer associated with each log file. It's large
914// so that log records can accumulate without the logging thread blocking
915// on disk I/O. The flushDaemon will block instead.
916const bufferSize = 256 * 1024
917
918// createFiles creates all the log files for severity from sev down to infoLog.
919// l.mu is held.
920func (l *loggingT) createFiles(sev severity) error {
921 now := time.Now()
922 // Files are created in decreasing severity order, so as soon as we find one
923 // has already been created, we can stop.
924 for s := sev; s >= infoLog && l.file[s] == nil; s-- {
925 sb := &syncBuffer{
926 logger: l,
927 sev: s,
928 }
929 if err := sb.rotateFile(now); err != nil {
930 return err
931 }
932 l.file[s] = sb
933 }
934 return nil
935}
936
937const flushInterval = 30 * time.Second
938
939// flushDaemon periodically flushes the log file buffers.
940func (l *loggingT) flushDaemon() {
941 for range time.NewTicker(flushInterval).C {
942 l.lockAndFlushAll()
943 }
944}
945
946// lockAndFlushAll is like flushAll but locks l.mu first.
947func (l *loggingT) lockAndFlushAll() {
948 l.mu.Lock()
949 l.flushAll()
950 l.mu.Unlock()
951}
952
953// flushAll flushes all the logs and attempts to "sync" their data to disk.
954// l.mu is held.
955func (l *loggingT) flushAll() {
956 // Flush from fatal down, in case there's trouble flushing.
957 for s := fatalLog; s >= infoLog; s-- {
958 file := l.file[s]
959 if file != nil {
960 file.Flush() // ignore error
961 file.Sync() // ignore error
962 }
963 }
964}
965
966// CopyStandardLogTo arranges for messages written to the Go "log" package's
967// default logs to also appear in the Google logs for the named and lower
968// severities. Subsequent changes to the standard log's default output location
969// or format may break this behavior.
970//
971// Valid names are "INFO", "WARNING", "ERROR", and "FATAL". If the name is not
972// recognized, CopyStandardLogTo panics.
973func CopyStandardLogTo(name string) {
974 sev, ok := severityByName(name)
975 if !ok {
976 panic(fmt.Sprintf("log.CopyStandardLogTo(%q): unrecognized severity name", name))
977 }
978 // Set a log format that captures the user's file and line:
979 // d.go:23: message
980 stdLog.SetFlags(stdLog.Lshortfile)
981 stdLog.SetOutput(logBridge(sev))
982}
983
984// logBridge provides the Write method that enables CopyStandardLogTo to connect
985// Go's standard logs to the logs provided by this package.
986type logBridge severity
987
988// Write parses the standard logging line and passes its components to the
989// logger for severity(lb).
990func (lb logBridge) Write(b []byte) (n int, err error) {
991 var (
992 file = "???"
993 line = 1
994 text string
995 )
996 // Split "d.go:23: message" into "d.go", "23", and "message".
997 if parts := bytes.SplitN(b, []byte{':'}, 3); len(parts) != 3 || len(parts[0]) < 1 || len(parts[2]) < 1 {
998 text = fmt.Sprintf("bad log format: %s", b)
999 } else {
1000 file = string(parts[0])
1001 text = string(parts[2][1:]) // skip leading space
1002 line, err = strconv.Atoi(string(parts[1]))
1003 if err != nil {
1004 text = fmt.Sprintf("bad line number: %s", b)
1005 line = 1
1006 }
1007 }
1008 // printWithFileLine with alsoToStderr=true, so standard log messages
1009 // always appear on standard error.
1010 logging.printWithFileLine(severity(lb), file, line, true, text)
1011 return len(b), nil
1012}
1013
1014// setV computes and remembers the V level for a given PC
1015// when vmodule is enabled.
1016// File pattern matching takes the basename of the file, stripped
1017// of its .go suffix, and uses filepath.Match, which is a little more
1018// general than the *? matching used in C++.
1019// l.mu is held.
1020func (l *loggingT) setV(pc uintptr) Level {
1021 fn := runtime.FuncForPC(pc)
1022 file, _ := fn.FileLine(pc)
1023 // The file is something like /a/b/c/d.go. We want just the d.
1024 if strings.HasSuffix(file, ".go") {
1025 file = file[:len(file)-3]
1026 }
1027 if slash := strings.LastIndex(file, "/"); slash >= 0 {
1028 file = file[slash+1:]
1029 }
1030 for _, filter := range l.vmodule.filter {
1031 if filter.match(file) {
1032 l.vmap[pc] = filter.level
1033 return filter.level
1034 }
1035 }
1036 l.vmap[pc] = 0
1037 return 0
1038}
1039
1040// Verbose is a boolean type that implements Infof (like Printf) etc.
1041// See the documentation of V for more information.
1042type Verbose bool
1043
1044// V reports whether verbosity at the call site is at least the requested level.
1045// The returned value is a boolean of type Verbose, which implements Info, Infoln
1046// and Infof. These methods will write to the Info log if called.
1047// Thus, one may write either
1048// if glog.V(2) { glog.Info("log this") }
1049// or
1050// glog.V(2).Info("log this")
1051// The second form is shorter but the first is cheaper if logging is off because it does
1052// not evaluate its arguments.
1053//
1054// Whether an individual call to V generates a log record depends on the setting of
1055// the -v and --vmodule flags; both are off by default. If the level in the call to
1056// V is at least the value of -v, or of -vmodule for the source file containing the
1057// call, the V call will log.
1058func V(level Level) Verbose {
1059 // This function tries hard to be cheap unless there's work to do.
1060 // The fast path is two atomic loads and compares.
1061
1062 // Here is a cheap but safe test to see if V logging is enabled globally.
1063 if logging.verbosity.get() >= level {
1064 return Verbose(true)
1065 }
1066
1067 // It's off globally but it vmodule may still be set.
1068 // Here is another cheap but safe test to see if vmodule is enabled.
1069 if atomic.LoadInt32(&logging.filterLength) > 0 {
1070 // Now we need a proper lock to use the logging structure. The pcs field
1071 // is shared so we must lock before accessing it. This is fairly expensive,
1072 // but if V logging is enabled we're slow anyway.
1073 logging.mu.Lock()
1074 defer logging.mu.Unlock()
1075 if runtime.Callers(2, logging.pcs[:]) == 0 {
1076 return Verbose(false)
1077 }
1078 v, ok := logging.vmap[logging.pcs[0]]
1079 if !ok {
1080 v = logging.setV(logging.pcs[0])
1081 }
1082 return Verbose(v >= level)
1083 }
1084 return Verbose(false)
1085}
1086
1087// Info is equivalent to the global Info function, guarded by the value of v.
1088// See the documentation of V for usage.
1089func (v Verbose) Info(args ...interface{}) {
1090 if v {
1091 logging.print(infoLog, args...)
1092 }
1093}
1094
1095// Infoln is equivalent to the global Infoln function, guarded by the value of v.
1096// See the documentation of V for usage.
1097func (v Verbose) Infoln(args ...interface{}) {
1098 if v {
1099 logging.println(infoLog, args...)
1100 }
1101}
1102
1103// Infof is equivalent to the global Infof function, guarded by the value of v.
1104// See the documentation of V for usage.
1105func (v Verbose) Infof(format string, args ...interface{}) {
1106 if v {
1107 logging.printf(infoLog, format, args...)
1108 }
1109}
1110
1111// Info logs to the INFO log.
1112// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1113func Info(args ...interface{}) {
1114 logging.print(infoLog, args...)
1115}
1116
1117// InfoDepth acts as Info but uses depth to determine which call frame to log.
1118// InfoDepth(0, "msg") is the same as Info("msg").
1119func InfoDepth(depth int, args ...interface{}) {
1120 logging.printDepth(infoLog, depth, args...)
1121}
1122
1123// Infoln logs to the INFO log.
1124// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1125func Infoln(args ...interface{}) {
1126 logging.println(infoLog, args...)
1127}
1128
1129// Infof logs to the INFO log.
1130// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1131func Infof(format string, args ...interface{}) {
1132 logging.printf(infoLog, format, args...)
1133}
1134
1135// Warning logs to the WARNING and INFO logs.
1136// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1137func Warning(args ...interface{}) {
1138 logging.print(warningLog, args...)
1139}
1140
1141// WarningDepth acts as Warning but uses depth to determine which call frame to log.
1142// WarningDepth(0, "msg") is the same as Warning("msg").
1143func WarningDepth(depth int, args ...interface{}) {
1144 logging.printDepth(warningLog, depth, args...)
1145}
1146
1147// Warningln logs to the WARNING and INFO logs.
1148// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1149func Warningln(args ...interface{}) {
1150 logging.println(warningLog, args...)
1151}
1152
1153// Warningf logs to the WARNING and INFO logs.
1154// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1155func Warningf(format string, args ...interface{}) {
1156 logging.printf(warningLog, format, args...)
1157}
1158
1159// Error logs to the ERROR, WARNING, and INFO logs.
1160// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1161func Error(args ...interface{}) {
1162 logging.print(errorLog, args...)
1163}
1164
1165// ErrorDepth acts as Error but uses depth to determine which call frame to log.
1166// ErrorDepth(0, "msg") is the same as Error("msg").
1167func ErrorDepth(depth int, args ...interface{}) {
1168 logging.printDepth(errorLog, depth, args...)
1169}
1170
1171// Errorln logs to the ERROR, WARNING, and INFO logs.
1172// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1173func Errorln(args ...interface{}) {
1174 logging.println(errorLog, args...)
1175}
1176
1177// Errorf logs to the ERROR, WARNING, and INFO logs.
1178// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1179func Errorf(format string, args ...interface{}) {
1180 logging.printf(errorLog, format, args...)
1181}
1182
1183// Fatal logs to the FATAL, ERROR, WARNING, and INFO logs,
1184// including a stack trace of all running goroutines, then calls os.Exit(255).
1185// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1186func Fatal(args ...interface{}) {
1187 logging.print(fatalLog, args...)
1188}
1189
1190// FatalDepth acts as Fatal but uses depth to determine which call frame to log.
1191// FatalDepth(0, "msg") is the same as Fatal("msg").
1192func FatalDepth(depth int, args ...interface{}) {
1193 logging.printDepth(fatalLog, depth, args...)
1194}
1195
1196// Fatalln logs to the FATAL, ERROR, WARNING, and INFO logs,
1197// including a stack trace of all running goroutines, then calls os.Exit(255).
1198// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1199func Fatalln(args ...interface{}) {
1200 logging.println(fatalLog, args...)
1201}
1202
1203// Fatalf logs to the FATAL, ERROR, WARNING, and INFO logs,
1204// including a stack trace of all running goroutines, then calls os.Exit(255).
1205// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1206func Fatalf(format string, args ...interface{}) {
1207 logging.printf(fatalLog, format, args...)
1208}
1209
1210// fatalNoStacks is non-zero if we are to exit without dumping goroutine stacks.
1211// It allows Exit and relatives to use the Fatal logs.
1212var fatalNoStacks uint32
1213
1214// Exit logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1215// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1216func Exit(args ...interface{}) {
1217 atomic.StoreUint32(&fatalNoStacks, 1)
1218 logging.print(fatalLog, args...)
1219}
1220
1221// ExitDepth acts as Exit but uses depth to determine which call frame to log.
1222// ExitDepth(0, "msg") is the same as Exit("msg").
1223func ExitDepth(depth int, args ...interface{}) {
1224 atomic.StoreUint32(&fatalNoStacks, 1)
1225 logging.printDepth(fatalLog, depth, args...)
1226}
1227
1228// Exitln logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1229func Exitln(args ...interface{}) {
1230 atomic.StoreUint32(&fatalNoStacks, 1)
1231 logging.println(fatalLog, args...)
1232}
1233
1234// Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1235// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1236func Exitf(format string, args ...interface{}) {
1237 atomic.StoreUint32(&fatalNoStacks, 1)
1238 logging.printf(fatalLog, format, args...)
1239}