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