blob: 54bd7afdcabec4769e849f2c067b53e24a139fd8 [file] [log] [blame]
Zack Williamse940c7a2019-08-21 14:25:39 -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 glog 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 glog
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 flag.BoolVar(&logging.toStderr, "logtostderr", false, "log to standard error instead of files")
400 flag.BoolVar(&logging.alsoToStderr, "alsologtostderr", false, "log to standard error as well as files")
401 flag.Var(&logging.verbosity, "v", "log level for V logs")
402 flag.Var(&logging.stderrThreshold, "stderrthreshold", "logs at or above this threshold go to stderr")
403 flag.Var(&logging.vmodule, "vmodule", "comma-separated list of pattern=N settings for file-filtered logging")
404 flag.Var(&logging.traceLocation, "log_backtrace_at", "when logging hits line file:N, emit a stack trace")
405
406 // Default stderrThreshold is ERROR.
407 logging.stderrThreshold = errorLog
408
409 logging.setVState(0, nil, false)
410 go logging.flushDaemon()
411}
412
413// Flush flushes all pending log I/O.
414func Flush() {
415 logging.lockAndFlushAll()
416}
417
418// loggingT collects all the global state of the logging setup.
419type loggingT struct {
420 // Boolean flags. Not handled atomically because the flag.Value interface
421 // does not let us avoid the =true, and that shorthand is necessary for
422 // compatibility. TODO: does this matter enough to fix? Seems unlikely.
423 toStderr bool // The -logtostderr flag.
424 alsoToStderr bool // The -alsologtostderr flag.
425
426 // Level flag. Handled atomically.
427 stderrThreshold severity // The -stderrthreshold flag.
428
429 // freeList is a list of byte buffers, maintained under freeListMu.
430 freeList *buffer
431 // freeListMu maintains the free list. It is separate from the main mutex
432 // so buffers can be grabbed and printed to without holding the main lock,
433 // for better parallelization.
434 freeListMu sync.Mutex
435
436 // mu protects the remaining elements of this structure and is
437 // used to synchronize logging.
438 mu sync.Mutex
439 // file holds writer for each of the log types.
440 file [numSeverity]flushSyncWriter
441 // pcs is used in V to avoid an allocation when computing the caller's PC.
442 pcs [1]uintptr
443 // vmap is a cache of the V Level for each V() call site, identified by PC.
444 // It is wiped whenever the vmodule flag changes state.
445 vmap map[uintptr]Level
446 // filterLength stores the length of the vmodule filter chain. If greater
447 // than zero, it means vmodule is enabled. It may be read safely
448 // using sync.LoadInt32, but is only modified under mu.
449 filterLength int32
450 // traceLocation is the state of the -log_backtrace_at flag.
451 traceLocation traceLocation
452 // These flags are modified only under lock, although verbosity may be fetched
453 // safely using atomic.LoadInt32.
454 vmodule moduleSpec // The state of the -vmodule flag.
455 verbosity Level // V logging level, the value of the -v flag/
456}
457
458// buffer holds a byte Buffer for reuse. The zero value is ready for use.
459type buffer struct {
460 bytes.Buffer
461 tmp [64]byte // temporary byte array for creating headers.
462 next *buffer
463}
464
465var logging loggingT
466
467// setVState sets a consistent state for V logging.
468// l.mu is held.
469func (l *loggingT) setVState(verbosity Level, filter []modulePat, setFilter bool) {
470 // Turn verbosity off so V will not fire while we are in transition.
471 logging.verbosity.set(0)
472 // Ditto for filter length.
473 atomic.StoreInt32(&logging.filterLength, 0)
474
475 // Set the new filters and wipe the pc->Level map if the filter has changed.
476 if setFilter {
477 logging.vmodule.filter = filter
478 logging.vmap = make(map[uintptr]Level)
479 }
480
481 // Things are consistent now, so enable filtering and verbosity.
482 // They are enabled in order opposite to that in V.
483 atomic.StoreInt32(&logging.filterLength, int32(len(filter)))
484 logging.verbosity.set(verbosity)
485}
486
487// getBuffer returns a new, ready-to-use buffer.
488func (l *loggingT) getBuffer() *buffer {
489 l.freeListMu.Lock()
490 b := l.freeList
491 if b != nil {
492 l.freeList = b.next
493 }
494 l.freeListMu.Unlock()
495 if b == nil {
496 b = new(buffer)
497 } else {
498 b.next = nil
499 b.Reset()
500 }
501 return b
502}
503
504// putBuffer returns a buffer to the free list.
505func (l *loggingT) putBuffer(b *buffer) {
506 if b.Len() >= 256 {
507 // Let big buffers die a natural death.
508 return
509 }
510 l.freeListMu.Lock()
511 b.next = l.freeList
512 l.freeList = b
513 l.freeListMu.Unlock()
514}
515
516var timeNow = time.Now // Stubbed out for testing.
517
518/*
519header formats a log header as defined by the C++ implementation.
520It returns a buffer containing the formatted header and the user's file and line number.
521The depth specifies how many stack frames above lives the source line to be identified in the log message.
522
523Log lines have this form:
524 Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg...
525where the fields are defined as follows:
526 L A single character, representing the log level (eg 'I' for INFO)
527 mm The month (zero padded; ie May is '05')
528 dd The day (zero padded)
529 hh:mm:ss.uuuuuu Time in hours, minutes and fractional seconds
530 threadid The space-padded thread ID as returned by GetTID()
531 file The file name
532 line The line number
533 msg The user-supplied message
534*/
535func (l *loggingT) header(s severity, depth int) (*buffer, string, int) {
536 _, file, line, ok := runtime.Caller(3 + depth)
537 if !ok {
538 file = "???"
539 line = 1
540 } else {
541 slash := strings.LastIndex(file, "/")
542 if slash >= 0 {
543 file = file[slash+1:]
544 }
545 }
546 return l.formatHeader(s, file, line), file, line
547}
548
549// formatHeader formats a log header using the provided file name and line number.
550func (l *loggingT) formatHeader(s severity, file string, line int) *buffer {
551 now := timeNow()
552 if line < 0 {
553 line = 0 // not a real line number, but acceptable to someDigits
554 }
555 if s > fatalLog {
556 s = infoLog // for safety.
557 }
558 buf := l.getBuffer()
559
560 // Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
561 // It's worth about 3X. Fprintf is hard.
562 _, month, day := now.Date()
563 hour, minute, second := now.Clock()
564 // Lmmdd hh:mm:ss.uuuuuu threadid file:line]
565 buf.tmp[0] = severityChar[s]
566 buf.twoDigits(1, int(month))
567 buf.twoDigits(3, day)
568 buf.tmp[5] = ' '
569 buf.twoDigits(6, hour)
570 buf.tmp[8] = ':'
571 buf.twoDigits(9, minute)
572 buf.tmp[11] = ':'
573 buf.twoDigits(12, second)
574 buf.tmp[14] = '.'
575 buf.nDigits(6, 15, now.Nanosecond()/1000, '0')
576 buf.tmp[21] = ' '
577 buf.nDigits(7, 22, pid, ' ') // TODO: should be TID
578 buf.tmp[29] = ' '
579 buf.Write(buf.tmp[:30])
580 buf.WriteString(file)
581 buf.tmp[0] = ':'
582 n := buf.someDigits(1, line)
583 buf.tmp[n+1] = ']'
584 buf.tmp[n+2] = ' '
585 buf.Write(buf.tmp[:n+3])
586 return buf
587}
588
589// Some custom tiny helper functions to print the log header efficiently.
590
591const digits = "0123456789"
592
593// twoDigits formats a zero-prefixed two-digit integer at buf.tmp[i].
594func (buf *buffer) twoDigits(i, d int) {
595 buf.tmp[i+1] = digits[d%10]
596 d /= 10
597 buf.tmp[i] = digits[d%10]
598}
599
600// nDigits formats an n-digit integer at buf.tmp[i],
601// padding with pad on the left.
602// It assumes d >= 0.
603func (buf *buffer) nDigits(n, i, d int, pad byte) {
604 j := n - 1
605 for ; j >= 0 && d > 0; j-- {
606 buf.tmp[i+j] = digits[d%10]
607 d /= 10
608 }
609 for ; j >= 0; j-- {
610 buf.tmp[i+j] = pad
611 }
612}
613
614// someDigits formats a zero-prefixed variable-width integer at buf.tmp[i].
615func (buf *buffer) someDigits(i, d int) int {
616 // Print into the top, then copy down. We know there's space for at least
617 // a 10-digit number.
618 j := len(buf.tmp)
619 for {
620 j--
621 buf.tmp[j] = digits[d%10]
622 d /= 10
623 if d == 0 {
624 break
625 }
626 }
627 return copy(buf.tmp[i:], buf.tmp[j:])
628}
629
630func (l *loggingT) println(s severity, args ...interface{}) {
631 buf, file, line := l.header(s, 0)
632 fmt.Fprintln(buf, args...)
633 l.output(s, buf, file, line, false)
634}
635
636func (l *loggingT) print(s severity, args ...interface{}) {
637 l.printDepth(s, 1, args...)
638}
639
640func (l *loggingT) printDepth(s severity, depth int, args ...interface{}) {
641 buf, file, line := l.header(s, depth)
642 fmt.Fprint(buf, args...)
643 if buf.Bytes()[buf.Len()-1] != '\n' {
644 buf.WriteByte('\n')
645 }
646 l.output(s, buf, file, line, false)
647}
648
649func (l *loggingT) printf(s severity, format string, args ...interface{}) {
650 buf, file, line := l.header(s, 0)
651 fmt.Fprintf(buf, format, args...)
652 if buf.Bytes()[buf.Len()-1] != '\n' {
653 buf.WriteByte('\n')
654 }
655 l.output(s, buf, file, line, false)
656}
657
658// printWithFileLine behaves like print but uses the provided file and line number. If
659// alsoLogToStderr is true, the log message always appears on standard error; it
660// will also appear in the log file unless --logtostderr is set.
661func (l *loggingT) printWithFileLine(s severity, file string, line int, alsoToStderr bool, args ...interface{}) {
662 buf := l.formatHeader(s, file, line)
663 fmt.Fprint(buf, args...)
664 if buf.Bytes()[buf.Len()-1] != '\n' {
665 buf.WriteByte('\n')
666 }
667 l.output(s, buf, file, line, alsoToStderr)
668}
669
670// output writes the data to the log files and releases the buffer.
671func (l *loggingT) output(s severity, buf *buffer, file string, line int, alsoToStderr bool) {
672 l.mu.Lock()
673 if l.traceLocation.isSet() {
674 if l.traceLocation.match(file, line) {
675 buf.Write(stacks(false))
676 }
677 }
678 data := buf.Bytes()
679 if !flag.Parsed() {
680 os.Stderr.Write([]byte("ERROR: logging before flag.Parse: "))
681 os.Stderr.Write(data)
682 } else if l.toStderr {
683 os.Stderr.Write(data)
684 } else {
685 if alsoToStderr || l.alsoToStderr || s >= l.stderrThreshold.get() {
686 os.Stderr.Write(data)
687 }
688 if l.file[s] == nil {
689 if err := l.createFiles(s); err != nil {
690 os.Stderr.Write(data) // Make sure the message appears somewhere.
691 l.exit(err)
692 }
693 }
694 switch s {
695 case fatalLog:
696 l.file[fatalLog].Write(data)
697 fallthrough
698 case errorLog:
699 l.file[errorLog].Write(data)
700 fallthrough
701 case warningLog:
702 l.file[warningLog].Write(data)
703 fallthrough
704 case infoLog:
705 l.file[infoLog].Write(data)
706 }
707 }
708 if s == fatalLog {
709 // If we got here via Exit rather than Fatal, print no stacks.
710 if atomic.LoadUint32(&fatalNoStacks) > 0 {
711 l.mu.Unlock()
712 timeoutFlush(10 * time.Second)
713 os.Exit(1)
714 }
715 // Dump all goroutine stacks before exiting.
716 // First, make sure we see the trace for the current goroutine on standard error.
717 // If -logtostderr has been specified, the loop below will do that anyway
718 // as the first stack in the full dump.
719 if !l.toStderr {
720 os.Stderr.Write(stacks(false))
721 }
722 // Write the stack trace for all goroutines to the files.
723 trace := stacks(true)
724 logExitFunc = func(error) {} // If we get a write error, we'll still exit below.
725 for log := fatalLog; log >= infoLog; log-- {
726 if f := l.file[log]; f != nil { // Can be nil if -logtostderr is set.
727 f.Write(trace)
728 }
729 }
730 l.mu.Unlock()
731 timeoutFlush(10 * time.Second)
732 os.Exit(255) // C++ uses -1, which is silly because it's anded with 255 anyway.
733 }
734 l.putBuffer(buf)
735 l.mu.Unlock()
736 if stats := severityStats[s]; stats != nil {
737 atomic.AddInt64(&stats.lines, 1)
738 atomic.AddInt64(&stats.bytes, int64(len(data)))
739 }
740}
741
742// timeoutFlush calls Flush and returns when it completes or after timeout
743// elapses, whichever happens first. This is needed because the hooks invoked
744// by Flush may deadlock when glog.Fatal is called from a hook that holds
745// a lock.
746func timeoutFlush(timeout time.Duration) {
747 done := make(chan bool, 1)
748 go func() {
749 Flush() // calls logging.lockAndFlushAll()
750 done <- true
751 }()
752 select {
753 case <-done:
754 case <-time.After(timeout):
755 fmt.Fprintln(os.Stderr, "glog: Flush took longer than", timeout)
756 }
757}
758
759// stacks is a wrapper for runtime.Stack that attempts to recover the data for all goroutines.
760func stacks(all bool) []byte {
761 // We don't know how big the traces are, so grow a few times if they don't fit. Start large, though.
762 n := 10000
763 if all {
764 n = 100000
765 }
766 var trace []byte
767 for i := 0; i < 5; i++ {
768 trace = make([]byte, n)
769 nbytes := runtime.Stack(trace, all)
770 if nbytes < len(trace) {
771 return trace[:nbytes]
772 }
773 n *= 2
774 }
775 return trace
776}
777
778// logExitFunc provides a simple mechanism to override the default behavior
779// of exiting on error. Used in testing and to guarantee we reach a required exit
780// for fatal logs. Instead, exit could be a function rather than a method but that
781// would make its use clumsier.
782var logExitFunc func(error)
783
784// exit is called if there is trouble creating or writing log files.
785// It flushes the logs and exits the program; there's no point in hanging around.
786// l.mu is held.
787func (l *loggingT) exit(err error) {
788 fmt.Fprintf(os.Stderr, "log: exiting because of error: %s\n", err)
789 // If logExitFunc is set, we do that instead of exiting.
790 if logExitFunc != nil {
791 logExitFunc(err)
792 return
793 }
794 l.flushAll()
795 os.Exit(2)
796}
797
798// syncBuffer joins a bufio.Writer to its underlying file, providing access to the
799// file's Sync method and providing a wrapper for the Write method that provides log
800// file rotation. There are conflicting methods, so the file cannot be embedded.
801// l.mu is held for all its methods.
802type syncBuffer struct {
803 logger *loggingT
804 *bufio.Writer
805 file *os.File
806 sev severity
807 nbytes uint64 // The number of bytes written to this file
808}
809
810func (sb *syncBuffer) Sync() error {
811 return sb.file.Sync()
812}
813
814func (sb *syncBuffer) Write(p []byte) (n int, err error) {
815 if sb.nbytes+uint64(len(p)) >= MaxSize {
816 if err := sb.rotateFile(time.Now()); err != nil {
817 sb.logger.exit(err)
818 }
819 }
820 n, err = sb.Writer.Write(p)
821 sb.nbytes += uint64(n)
822 if err != nil {
823 sb.logger.exit(err)
824 }
825 return
826}
827
828// rotateFile closes the syncBuffer's file and starts a new one.
829func (sb *syncBuffer) rotateFile(now time.Time) error {
830 if sb.file != nil {
831 sb.Flush()
832 sb.file.Close()
833 }
834 var err error
835 sb.file, _, err = create(severityName[sb.sev], now)
836 sb.nbytes = 0
837 if err != nil {
838 return err
839 }
840
841 sb.Writer = bufio.NewWriterSize(sb.file, bufferSize)
842
843 // Write header.
844 var buf bytes.Buffer
845 fmt.Fprintf(&buf, "Log file created at: %s\n", now.Format("2006/01/02 15:04:05"))
846 fmt.Fprintf(&buf, "Running on machine: %s\n", host)
847 fmt.Fprintf(&buf, "Binary: Built with %s %s for %s/%s\n", runtime.Compiler, runtime.Version(), runtime.GOOS, runtime.GOARCH)
848 fmt.Fprintf(&buf, "Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg\n")
849 n, err := sb.file.Write(buf.Bytes())
850 sb.nbytes += uint64(n)
851 return err
852}
853
854// bufferSize sizes the buffer associated with each log file. It's large
855// so that log records can accumulate without the logging thread blocking
856// on disk I/O. The flushDaemon will block instead.
857const bufferSize = 256 * 1024
858
859// createFiles creates all the log files for severity from sev down to infoLog.
860// l.mu is held.
861func (l *loggingT) createFiles(sev severity) error {
862 now := time.Now()
863 // Files are created in decreasing severity order, so as soon as we find one
864 // has already been created, we can stop.
865 for s := sev; s >= infoLog && l.file[s] == nil; s-- {
866 sb := &syncBuffer{
867 logger: l,
868 sev: s,
869 }
870 if err := sb.rotateFile(now); err != nil {
871 return err
872 }
873 l.file[s] = sb
874 }
875 return nil
876}
877
878const flushInterval = 30 * time.Second
879
880// flushDaemon periodically flushes the log file buffers.
881func (l *loggingT) flushDaemon() {
882 for _ = range time.NewTicker(flushInterval).C {
883 l.lockAndFlushAll()
884 }
885}
886
887// lockAndFlushAll is like flushAll but locks l.mu first.
888func (l *loggingT) lockAndFlushAll() {
889 l.mu.Lock()
890 l.flushAll()
891 l.mu.Unlock()
892}
893
894// flushAll flushes all the logs and attempts to "sync" their data to disk.
895// l.mu is held.
896func (l *loggingT) flushAll() {
897 // Flush from fatal down, in case there's trouble flushing.
898 for s := fatalLog; s >= infoLog; s-- {
899 file := l.file[s]
900 if file != nil {
901 file.Flush() // ignore error
902 file.Sync() // ignore error
903 }
904 }
905}
906
907// CopyStandardLogTo arranges for messages written to the Go "log" package's
908// default logs to also appear in the Google logs for the named and lower
909// severities. Subsequent changes to the standard log's default output location
910// or format may break this behavior.
911//
912// Valid names are "INFO", "WARNING", "ERROR", and "FATAL". If the name is not
913// recognized, CopyStandardLogTo panics.
914func CopyStandardLogTo(name string) {
915 sev, ok := severityByName(name)
916 if !ok {
917 panic(fmt.Sprintf("log.CopyStandardLogTo(%q): unrecognized severity name", name))
918 }
919 // Set a log format that captures the user's file and line:
920 // d.go:23: message
921 stdLog.SetFlags(stdLog.Lshortfile)
922 stdLog.SetOutput(logBridge(sev))
923}
924
925// logBridge provides the Write method that enables CopyStandardLogTo to connect
926// Go's standard logs to the logs provided by this package.
927type logBridge severity
928
929// Write parses the standard logging line and passes its components to the
930// logger for severity(lb).
931func (lb logBridge) Write(b []byte) (n int, err error) {
932 var (
933 file = "???"
934 line = 1
935 text string
936 )
937 // Split "d.go:23: message" into "d.go", "23", and "message".
938 if parts := bytes.SplitN(b, []byte{':'}, 3); len(parts) != 3 || len(parts[0]) < 1 || len(parts[2]) < 1 {
939 text = fmt.Sprintf("bad log format: %s", b)
940 } else {
941 file = string(parts[0])
942 text = string(parts[2][1:]) // skip leading space
943 line, err = strconv.Atoi(string(parts[1]))
944 if err != nil {
945 text = fmt.Sprintf("bad line number: %s", b)
946 line = 1
947 }
948 }
949 // printWithFileLine with alsoToStderr=true, so standard log messages
950 // always appear on standard error.
951 logging.printWithFileLine(severity(lb), file, line, true, text)
952 return len(b), nil
953}
954
955// setV computes and remembers the V level for a given PC
956// when vmodule is enabled.
957// File pattern matching takes the basename of the file, stripped
958// of its .go suffix, and uses filepath.Match, which is a little more
959// general than the *? matching used in C++.
960// l.mu is held.
961func (l *loggingT) setV(pc uintptr) Level {
962 fn := runtime.FuncForPC(pc)
963 file, _ := fn.FileLine(pc)
964 // The file is something like /a/b/c/d.go. We want just the d.
965 if strings.HasSuffix(file, ".go") {
966 file = file[:len(file)-3]
967 }
968 if slash := strings.LastIndex(file, "/"); slash >= 0 {
969 file = file[slash+1:]
970 }
971 for _, filter := range l.vmodule.filter {
972 if filter.match(file) {
973 l.vmap[pc] = filter.level
974 return filter.level
975 }
976 }
977 l.vmap[pc] = 0
978 return 0
979}
980
981// Verbose is a boolean type that implements Infof (like Printf) etc.
982// See the documentation of V for more information.
983type Verbose bool
984
985// V reports whether verbosity at the call site is at least the requested level.
986// The returned value is a boolean of type Verbose, which implements Info, Infoln
987// and Infof. These methods will write to the Info log if called.
988// Thus, one may write either
989// if glog.V(2) { glog.Info("log this") }
990// or
991// glog.V(2).Info("log this")
992// The second form is shorter but the first is cheaper if logging is off because it does
993// not evaluate its arguments.
994//
995// Whether an individual call to V generates a log record depends on the setting of
996// the -v and --vmodule flags; both are off by default. If the level in the call to
997// V is at least the value of -v, or of -vmodule for the source file containing the
998// call, the V call will log.
999func V(level Level) Verbose {
1000 // This function tries hard to be cheap unless there's work to do.
1001 // The fast path is two atomic loads and compares.
1002
1003 // Here is a cheap but safe test to see if V logging is enabled globally.
1004 if logging.verbosity.get() >= level {
1005 return Verbose(true)
1006 }
1007
1008 // It's off globally but it vmodule may still be set.
1009 // Here is another cheap but safe test to see if vmodule is enabled.
1010 if atomic.LoadInt32(&logging.filterLength) > 0 {
1011 // Now we need a proper lock to use the logging structure. The pcs field
1012 // is shared so we must lock before accessing it. This is fairly expensive,
1013 // but if V logging is enabled we're slow anyway.
1014 logging.mu.Lock()
1015 defer logging.mu.Unlock()
1016 if runtime.Callers(2, logging.pcs[:]) == 0 {
1017 return Verbose(false)
1018 }
1019 v, ok := logging.vmap[logging.pcs[0]]
1020 if !ok {
1021 v = logging.setV(logging.pcs[0])
1022 }
1023 return Verbose(v >= level)
1024 }
1025 return Verbose(false)
1026}
1027
1028// Info is equivalent to the global Info function, guarded by the value of v.
1029// See the documentation of V for usage.
1030func (v Verbose) Info(args ...interface{}) {
1031 if v {
1032 logging.print(infoLog, args...)
1033 }
1034}
1035
1036// Infoln is equivalent to the global Infoln function, guarded by the value of v.
1037// See the documentation of V for usage.
1038func (v Verbose) Infoln(args ...interface{}) {
1039 if v {
1040 logging.println(infoLog, args...)
1041 }
1042}
1043
1044// Infof is equivalent to the global Infof function, guarded by the value of v.
1045// See the documentation of V for usage.
1046func (v Verbose) Infof(format string, args ...interface{}) {
1047 if v {
1048 logging.printf(infoLog, format, args...)
1049 }
1050}
1051
1052// Info logs to the INFO log.
1053// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1054func Info(args ...interface{}) {
1055 logging.print(infoLog, args...)
1056}
1057
1058// InfoDepth acts as Info but uses depth to determine which call frame to log.
1059// InfoDepth(0, "msg") is the same as Info("msg").
1060func InfoDepth(depth int, args ...interface{}) {
1061 logging.printDepth(infoLog, depth, args...)
1062}
1063
1064// Infoln logs to the INFO log.
1065// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1066func Infoln(args ...interface{}) {
1067 logging.println(infoLog, args...)
1068}
1069
1070// Infof logs to the INFO log.
1071// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1072func Infof(format string, args ...interface{}) {
1073 logging.printf(infoLog, format, args...)
1074}
1075
1076// Warning logs to the WARNING and INFO logs.
1077// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1078func Warning(args ...interface{}) {
1079 logging.print(warningLog, args...)
1080}
1081
1082// WarningDepth acts as Warning but uses depth to determine which call frame to log.
1083// WarningDepth(0, "msg") is the same as Warning("msg").
1084func WarningDepth(depth int, args ...interface{}) {
1085 logging.printDepth(warningLog, depth, args...)
1086}
1087
1088// Warningln logs to the WARNING and INFO logs.
1089// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1090func Warningln(args ...interface{}) {
1091 logging.println(warningLog, args...)
1092}
1093
1094// Warningf logs to the WARNING and INFO logs.
1095// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1096func Warningf(format string, args ...interface{}) {
1097 logging.printf(warningLog, format, args...)
1098}
1099
1100// Error logs to the ERROR, WARNING, and INFO logs.
1101// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1102func Error(args ...interface{}) {
1103 logging.print(errorLog, args...)
1104}
1105
1106// ErrorDepth acts as Error but uses depth to determine which call frame to log.
1107// ErrorDepth(0, "msg") is the same as Error("msg").
1108func ErrorDepth(depth int, args ...interface{}) {
1109 logging.printDepth(errorLog, depth, args...)
1110}
1111
1112// Errorln logs to the ERROR, WARNING, and INFO logs.
1113// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1114func Errorln(args ...interface{}) {
1115 logging.println(errorLog, args...)
1116}
1117
1118// Errorf logs to the ERROR, WARNING, and INFO logs.
1119// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1120func Errorf(format string, args ...interface{}) {
1121 logging.printf(errorLog, format, args...)
1122}
1123
1124// Fatal logs to the FATAL, ERROR, WARNING, and INFO logs,
1125// including a stack trace of all running goroutines, then calls os.Exit(255).
1126// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1127func Fatal(args ...interface{}) {
1128 logging.print(fatalLog, args...)
1129}
1130
1131// FatalDepth acts as Fatal but uses depth to determine which call frame to log.
1132// FatalDepth(0, "msg") is the same as Fatal("msg").
1133func FatalDepth(depth int, args ...interface{}) {
1134 logging.printDepth(fatalLog, depth, args...)
1135}
1136
1137// Fatalln logs to the FATAL, ERROR, WARNING, and INFO logs,
1138// including a stack trace of all running goroutines, then calls os.Exit(255).
1139// Arguments are handled in the manner of fmt.Println; a newline is appended if missing.
1140func Fatalln(args ...interface{}) {
1141 logging.println(fatalLog, args...)
1142}
1143
1144// Fatalf logs to the FATAL, ERROR, WARNING, and INFO logs,
1145// including a stack trace of all running goroutines, then calls os.Exit(255).
1146// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1147func Fatalf(format string, args ...interface{}) {
1148 logging.printf(fatalLog, format, args...)
1149}
1150
1151// fatalNoStacks is non-zero if we are to exit without dumping goroutine stacks.
1152// It allows Exit and relatives to use the Fatal logs.
1153var fatalNoStacks uint32
1154
1155// Exit logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1156// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
1157func Exit(args ...interface{}) {
1158 atomic.StoreUint32(&fatalNoStacks, 1)
1159 logging.print(fatalLog, args...)
1160}
1161
1162// ExitDepth acts as Exit but uses depth to determine which call frame to log.
1163// ExitDepth(0, "msg") is the same as Exit("msg").
1164func ExitDepth(depth int, args ...interface{}) {
1165 atomic.StoreUint32(&fatalNoStacks, 1)
1166 logging.printDepth(fatalLog, depth, args...)
1167}
1168
1169// Exitln logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1170func Exitln(args ...interface{}) {
1171 atomic.StoreUint32(&fatalNoStacks, 1)
1172 logging.println(fatalLog, args...)
1173}
1174
1175// Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
1176// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
1177func Exitf(format string, args ...interface{}) {
1178 atomic.StoreUint32(&fatalNoStacks, 1)
1179 logging.printf(fatalLog, format, args...)
1180}