woodsman.go

// Basic examples:
//
//  woodsman.Info("Prepare to repel boarders")
//
//  woodsman.Fatalf("Initialization failed: %s", err)
//
// See the documentation for the V function for an explanation of these examples:
//
//  if woodsman.V(2) {
//      woodsman.Info("Starting transaction...")
//  }
//
//  woodsman.V(2).Infoln("Processed", nItems, "elements")
//
// Log output is buffered and written periodically using Flush. Programs
// should call Flush before exiting to guarantee all log output is written.
//
// By default, all log statements write to files in a temporary directory.
// This package provides several flags that modify this behavior.
// As a result, flag.Parse must be called before any logging is done.
//
//  -logtostderr=false
//      Logs are written to standard error.
//  -logtofile=false
//      Logs are written to file.
//  -logsyslog=false
//      Logs are written to syslog.
//  -stderrthreshold=ERROR
//      Log events at or above this severity are logged to standard
//      error as well as to files.
//  -log_dir=""
//      Log files will be written to this directory instead of the
//      default temporary directory.
//
//  Other flags provide aids to debugging.
//
//  -log_backtrace_at=""
//      When set to a file and line number holding a logging statement,
//      such as
//          -log_backtrace_at=gopherflakes.go:234
//      a stack trace will be written to the Info log whenever execution
//      hits that statement. (Unlike with -vmodule, the ".go" must be
//      present.)
//  -v=0
//      Enable V-leveled logging at the specified level.
//  -vmodule=""
//      The syntax of the argument is a comma-separated list of pattern=N,
//      where pattern is a literal file name (minus the ".go" suffix) or
//      "glob" pattern and N is a V level. For instance,
//          -vmodule=gopher*=3
//      sets the V level to 3 in all Go files whose names begin "gopher".
//
package woodsman

import (
    "bufio"
    "bytes"
    "errors"
    "fmt"
    "io"
    "os"
    "path/filepath"
    "runtime"
    "strconv"
    "strings"
    "sync/atomic"
    "time"

    "github.com/blackjack/syslog"
)

// severity identifies the sort of log: info, warning etc. It also implements
// the flag.Value interface. The -stderrthreshold flag is of type severity and
// should be modified only through the flag.Value interface. The values match
// the corresponding constants in C++.
type severity int32 // sync/atomic int32

const (
    infoLog severity = iota
    warningLog
    errorLog
    fatalLog
    numSeverity = 4
)

const severityChar = "IWEF"

var severityName = []string{
    infoLog:    "INFO",
    warningLog: "WARNING",
    errorLog:   "ERROR",
    fatalLog:   "FATAL",
}

// get returns the value of the severity.
func (s *severity) get() severity {
    return severity(atomic.LoadInt32((*int32)(s)))
}

// set sets the value of the severity.
func (s *severity) set(val severity) {
    atomic.StoreInt32((*int32)(s), int32(val))
}

// String is part of the flag.Value interface.
func (s *severity) String() string {
    return strconv.FormatInt(int64(*s), 10)
}

// Get is part of the flag.Value interface.
func (s *severity) Get() interface{} {
    return *s
}

// Set is part of the flag.Value interface.
func (s *severity) Set(value string) error {
    var threshold severity
    // Is it a known name?
    if v, ok := severityByName(value); ok {
        threshold = v
    } else {
        v, err := strconv.Atoi(value)
        if err != nil {
            return err
        }
        threshold = severity(v)
    }
    logging.stderrThreshold.set(threshold)
    return nil
}

func severityByName(s string) (severity, bool) {
    s = strings.ToUpper(s)
    for i, name := range severityName {
        if name == s {
            return severity(i), true
        }
    }
    return 0, false
}

// OutputStats tracks the number of output lines and bytes written.
type OutputStats struct {
    lines int64
    bytes int64
}

// Lines returns the number of lines written.
func (s *OutputStats) Lines() int64 {
    return atomic.LoadInt64(&s.lines)
}

// Bytes returns the number of bytes written.
func (s *OutputStats) Bytes() int64 {
    return atomic.LoadInt64(&s.bytes)
}

// Stats tracks the number of lines of output and number of bytes
// per severity level. Values must be read with atomic.LoadInt64.
var Stats struct {
    Info, Warning, Error OutputStats
}

var severityStats = [numSeverity]*OutputStats{
    infoLog:    &Stats.Info,
    warningLog: &Stats.Warning,
    errorLog:   &Stats.Error,
}

// Level is exported because it appears in the arguments to V and is
// the type of the v flag, which can be set programmatically.
// It's a distinct type because we want to discriminate it from logType.
// Variables of type level are only changed under logging.mu.
// The -v flag is read only with atomic ops, so the state of the logging
// module is consistent.

// Level is treated as a sync/atomic int32.

// Level specifies a level of verbosity for V logs. *Level implements
// flag.Value; the -v flag is of type Level and should be modified
// only through the flag.Value interface.
type Level int32

// get returns the value of the Level.
func (l *Level) get() Level {
    return Level(atomic.LoadInt32((*int32)(l)))
}

// set sets the value of the Level.
func (l *Level) set(val Level) {
    atomic.StoreInt32((*int32)(l), int32(val))
}

// String is part of the flag.Value interface.
func (l *Level) String() string {
    return strconv.FormatInt(int64(*l), 10)
}

// Get is part of the flag.Value interface.
func (l *Level) Get() interface{} {
    return *l
}

// Set is part of the flag.Value interface.
func (l *Level) Set(value string) error {
    v, err := strconv.Atoi(value)
    if err != nil {
        return err
    }
    logging.mu.Lock()
    defer logging.mu.Unlock()
    logging.setVState(Level(v), logging.vmodule.filter, false)
    return nil
}

// moduleSpec represents the setting of the -vmodule flag.
type moduleSpec struct {
    filter []modulePat
}

// modulePat contains a filter for the -vmodule flag.
// It holds a verbosity level and a file pattern to match.
type modulePat struct {
    pattern string
    literal bool // The pattern is a literal string
    level   Level
}

// match reports whether the file matches the pattern. It uses a string
// comparison if the pattern contains no metacharacters.
func (m *modulePat) match(file string) bool {
    if m.literal {
        return file == m.pattern
    }
    match, _ := filepath.Match(m.pattern, file)
    return match
}

func (m *moduleSpec) String() string {
    // Lock because the type is not atomic.
    logging.mu.Lock()
    defer logging.mu.Unlock()
    var b bytes.Buffer
    for i, f := range m.filter {
        if i > 0 {
            b.WriteRune(',')
        }
        fmt.Fprintf(&b, "%s=%d", f.pattern, f.level)
    }
    return b.String()
}

// Get is part of the (Go 1.2)  flag.Getter interface. It always returns nil for this flag type since the
// struct is not exported.
func (m *moduleSpec) Get() interface{} {
    return nil
}

var errVmoduleSyntax = errors.New("syntax error: expect comma-separated list of filename=N")

// Syntax: -vmodule=recordio=2,file=1,gfs*=3
func (m *moduleSpec) Set(value string) error {
    var filter []modulePat
    for _, pat := range strings.Split(value, ",") {
        if len(pat) == 0 {
            // Empty strings such as from a trailing comma can be ignored.
            continue
        }
        patLev := strings.Split(pat, "=")
        if len(patLev) != 2 || len(patLev[0]) == 0 || len(patLev[1]) == 0 {
            return errVmoduleSyntax
        }
        pattern := patLev[0]
        v, err := strconv.Atoi(patLev[1])
        if err != nil {
            return errors.New("syntax error: expect comma-separated list of filename=N")
        }
        if v < 0 {
            return errors.New("negative value for vmodule level")
        }
        if v == 0 {
            continue // Ignore. It's harmless but no point in paying the overhead.
        }

        filter = append(filter, modulePat{pattern, isLiteral(pattern), Level(v)})
    }
    logging.mu.Lock()
    defer logging.mu.Unlock()
    logging.setVState(logging.verbosity, filter, true)
    return nil
}

// isLiteral reports whether the pattern is a literal string, that is, has no metacharacters
// that require filepath.Match to be called to match the pattern.
func isLiteral(pattern string) bool {
    return !strings.ContainsAny(pattern, `*?[]\`)
}

// traceLocation represents the setting of the -log_backtrace_at flag.
type traceLocation struct {
    file string
    line int
}

// isSet reports whether the trace location has been specified.
// logging.mu is held.
func (t *traceLocation) isSet() bool {
    return t.line > 0
}

// match reports whether the specified file and line matches the trace location.
// The argument file name is the full path, not the basename specified in the flag.
// logging.mu is held.
func (t *traceLocation) match(file string, line int) bool {
    if t.line != line {
        return false
    }
    if i := strings.LastIndex(file, "/"); i >= 0 {
        file = file[i+1:]
    }
    return t.file == file
}

func (t *traceLocation) String() string {
    // Lock because the type is not atomic.
    logging.mu.Lock()
    defer logging.mu.Unlock()
    return fmt.Sprintf("%s:%d", t.file, t.line)
}

// Get is part of the (Go 1.2) flag.Getter interface. It always returns nil for this flag type since the
// struct is not exported
func (t *traceLocation) Get() interface{} {
    return nil
}

var errTraceSyntax = errors.New("syntax error: expect file.go:234")

// Syntax: -log_backtrace_at=gopherflakes.go:234
// Note that unlike vmodule the file extension is included here.
func (t *traceLocation) Set(value string) error {
    if value == "" {
        // Unset.
        t.line = 0
        t.file = ""
    }
    fields := strings.Split(value, ":")
    if len(fields) != 2 {
        return errTraceSyntax
    }
    file, line := fields[0], fields[1]
    if !strings.Contains(file, ".") {
        return errTraceSyntax
    }
    v, err := strconv.Atoi(line)
    if err != nil {
        return errTraceSyntax
    }
    if v <= 0 {
        return errors.New("negative or zero value for level")
    }
    logging.mu.Lock()
    defer logging.mu.Unlock()
    t.line = v
    t.file = file
    return nil
}

// flushSyncWriter is the interface satisfied by logging destinations.
type flushSyncWriter interface {
    Flush() error
    Sync() error
    io.Writer
}

// Flush flushes all pending log I/O.
func Flush() {
    logging.lockAndFlushAll()
}

func init() {
    initExternalVars()

    // Default stderrThreshold is ERROR.
    logging.stderrThreshold = errorLog

    logging.setVState(0, nil, false)
    go logging.flushDaemon()
}

// buffer holds a byte Buffer for reuse. The zero value is ready for use.
type buffer struct {
    bytes.Buffer
    tmp  [64]byte // temporary byte array for creating headers.
    next *buffer
}

// setVState sets a consistent state for V logging.
// l.mu is held.
func (l *loggingT) setVState(verbosity Level, filter []modulePat, setFilter bool) {
    // Turn verbosity off so V will not fire while we are in transition.
    logging.verbosity.set(0)
    // Ditto for filter length.
    logging.filterLength = 0

    // Set the new filters and wipe the pc->Level map if the filter has changed.
    if setFilter {
        logging.vmodule.filter = filter
        logging.vmap = make(map[uintptr]Level)
    }

    // Things are consistent now, so enable filtering and verbosity.
    // They are enabled in order opposite to that in V.
    atomic.StoreInt32(&logging.filterLength, int32(len(filter)))
    logging.verbosity.set(verbosity)
}

// getBuffer returns a new, ready-to-use buffer.
func (l *loggingT) getBuffer() *buffer {
    l.freeListMu.Lock()
    b := l.freeList
    if b != nil {
        l.freeList = b.next
    }
    l.freeListMu.Unlock()
    if b == nil {
        b = new(buffer)
    } else {
        b.next = nil
        b.Reset()
    }
    return b
}

// putBuffer returns a buffer to the free list.
func (l *loggingT) putBuffer(b *buffer) {
    if b.Len() >= 256 {
        // Let big buffers die a natural death.
        return
    }
    l.freeListMu.Lock()
    b.next = l.freeList
    l.freeList = b
    l.freeListMu.Unlock()
}

var timeNow = time.Now // Stubbed out for testing.

/*
header formats a log header as defined by the C++ implementation.
It returns a buffer containing the formatted header.

Log lines have this form:
    Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg...
where the fields are defined as follows:
    L                A single character, representing the log level (eg 'I' for INFO)
    mm               The month (zero padded; ie May is '05')
    dd               The day (zero padded)
    hh:mm:ss.uuuuuu  Time in hours, minutes and fractional seconds
    threadid         The space-padded thread ID as returned by GetTID()
    file             The file name
    line             The line number
    msg              The user-supplied message
*/
func (l *loggingT) header(s severity) *buffer {
    // Lmmdd hh:mm:ss.uuuuuu threadid file:line]
    now := timeNow()
    _, file, line, ok := runtime.Caller(3) // It's always the same number of frames to the user's call.
    if !ok {
        file = "???"
        line = 1
    } else {
        slash := strings.LastIndex(file, "/")
        if slash >= 0 {
            file = file[slash+1:]
        }
    }
    if line < 0 {
        line = 0 // not a real line number, but acceptable to someDigits
    }
    if s > fatalLog {
        s = infoLog // for safety.
    }
    buf := l.getBuffer()

    // Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
    // It's worth about 3X. Fprintf is hard.
    _, month, day := now.Date()
    hour, minute, second := now.Clock()
    buf.tmp[0] = severityChar[s]
    buf.twoDigits(1, int(month))
    buf.twoDigits(3, day)
    buf.tmp[5] = ' '
    buf.twoDigits(6, hour)
    buf.tmp[8] = ':'
    buf.twoDigits(9, minute)
    buf.tmp[11] = ':'
    buf.twoDigits(12, second)
    buf.tmp[14] = '.'
    buf.nDigits(6, 15, now.Nanosecond()/1000)
    buf.tmp[21] = ' '
    buf.nDigits(5, 22, pid)
    buf.tmp[27] = ' '
    buf.Write(buf.tmp[:28])
    buf.WriteString(file)
    buf.tmp[0] = ':'
    n := buf.someDigits(1, line)
    buf.tmp[n+1] = ']'
    buf.tmp[n+2] = ' '
    buf.Write(buf.tmp[:n+3])
    return buf
}

// Some custom tiny helper functions to print the log header efficiently.

const digits = "0123456789"

// twoDigits formats a zero-prefixed two-digit integer at buf.tmp[i].
func (buf *buffer) twoDigits(i, d int) {
    buf.tmp[i+1] = digits[d%10]
    d /= 10
    buf.tmp[i] = digits[d%10]
}

// nDigits formats a zero-prefixed n-digit integer at buf.tmp[i].
func (buf *buffer) nDigits(n, i, d int) {
    for j := n - 1; j >= 0; j-- {
        buf.tmp[i+j] = digits[d%10]
        d /= 10
    }
}

// someDigits formats a zero-prefixed variable-width integer at buf.tmp[i].
func (buf *buffer) someDigits(i, d int) int {
    // Print into the top, then copy down. We know there's space for at least
    // a 10-digit number.
    j := len(buf.tmp)
    for {
        j--
        buf.tmp[j] = digits[d%10]
        d /= 10
        if d == 0 {
            break
        }
    }
    return copy(buf.tmp[i:], buf.tmp[j:])
}

func (l *loggingT) println(s severity, args ...interface{}) {
    buf := l.header(s)
    fmt.Fprintln(buf, args...)
    l.output(s, buf)
}

func (l *loggingT) print(s severity, args ...interface{}) {
    buf := l.header(s)
    fmt.Fprint(buf, args...)
    if buf.Bytes()[buf.Len()-1] != '\n' {
        buf.WriteByte('\n')
    }
    l.output(s, buf)
}

func (l *loggingT) printf(s severity, format string, args ...interface{}) {
    buf := l.header(s)
    fmt.Fprintf(buf, format, args...)
    if buf.Bytes()[buf.Len()-1] != '\n' {
        buf.WriteByte('\n')
    }
    l.output(s, buf)
}

// output writes the data to the log files and releases the buffer.
func (l *loggingT) output(s severity, buf *buffer) {
    l.mu.Lock()
    if l.traceLocation.isSet() {
        _, file, line, ok := runtime.Caller(3) // It's always the same number of frames to the user's call (same as header).
        if ok && l.traceLocation.match(file, line) {
            buf.Write(stacks(false))
        }
    }
    data := buf.Bytes()

    if l.toStderr {
        os.Stderr.Write(data)
    }

    if l.toSyslog {
        switch s {
        case fatalLog:
            syslog.Emerg(string(data))
        case errorLog:
            syslog.Err(string(data))
        case warningLog:
            syslog.Warning(string(data))
        case infoLog:
            syslog.Info(string(data))
        }
    }

    if l.toFile {
        // JTODO: CONVERT TO JUST MIN THRESHOLD, NOT STDERR THRESHOLD
        // if s >= l.stderrThreshold.get() {
        //     os.Stderr.Write(data)
        // }

        if l.file[s] == nil {
            if err := l.createFiles(s); err != nil {
                os.Stderr.Write(data) // Make sure the message appears somewhere.
                l.exit(err)
            }
        }

        switch s {
        case fatalLog:
            l.file[fatalLog].Write(data)
        case errorLog:
            l.file[errorLog].Write(data)
        case warningLog:
            l.file[warningLog].Write(data)
        case infoLog:
            l.file[infoLog].Write(data)
        }
    }

    if s == fatalLog {
        // Make sure we see the trace for the current goroutine on standard error.
        if !l.toStderr {
            os.Stderr.Write(stacks(false))
        }
        // Write the stack trace for all goroutines to the files.
        trace := stacks(true)
        logExitFunc = func(error) {} // If we get a write error, we'll still exit below.
        for log := fatalLog; log >= infoLog; log-- {
            if f := l.file[log]; f != nil { // Can be nil if -logtostderr is set.
                f.Write(trace)
            }
        }
        l.mu.Unlock()
        timeoutFlush(10 * time.Second)
        os.Exit(255) // C++ uses -1, which is silly because it's anded with 255 anyway.
    }
    l.putBuffer(buf)
    l.mu.Unlock()
    if stats := severityStats[s]; stats != nil {
        atomic.AddInt64(&stats.lines, 1)
        atomic.AddInt64(&stats.bytes, int64(len(data)))
    }
}

// timeoutFlush calls Flush and returns when it completes or after timeout
// elapses, whichever happens first.  This is needed because the hooks invoked
// by Flush may deadlock when woodsman.Fatal is called from a hook that holds
// a lock.
func timeoutFlush(timeout time.Duration) {
    done := make(chan bool, 1)
    go func() {
        Flush() // calls logging.lockAndFlushAll()
        done <- true
    }()
    select {
    case <-done:
    case <-time.After(timeout):
        fmt.Fprintln(os.Stderr, "woodsman: Flush took longer than", timeout)
    }
}

// stacks is a wrapper for runtime.Stack that attempts to recover the data for all goroutines.
func stacks(all bool) []byte {
    // We don't know how big the traces are, so grow a few times if they don't fit. Start large, though.
    n := 10000
    if all {
        n = 100000
    }
    var trace []byte
    for i := 0; i < 5; i++ {
        trace = make([]byte, n)
        nbytes := runtime.Stack(trace, all)
        if nbytes < len(trace) {
            return trace[:nbytes]
        }
        n *= 2
    }
    return trace
}

// logExitFunc provides a simple mechanism to override the default behavior
// of exiting on error. Used in testing and to guarantee we reach a required exit
// for fatal logs. Instead, exit could be a function rather than a method but that
// would make its use clumsier.
var logExitFunc func(error)

// exit is called if there is trouble creating or writing log files.
// It flushes the logs and exits the program; there's no point in hanging around.
// l.mu is held.
func (l *loggingT) exit(err error) {
    fmt.Fprintf(os.Stderr, "log: exiting because of error: %s\n", err)
    // If logExitFunc is set, we do that instead of exiting.
    if logExitFunc != nil {
        logExitFunc(err)
        return
    }
    l.flushAll()
    os.Exit(2)
}

// syncBuffer joins a bufio.Writer to its underlying file, providing access to the
// file's Sync method and providing a wrapper for the Write method that provides log
// file rotation. There are conflicting methods, so the file cannot be embedded.
// l.mu is held for all its methods.
type syncBuffer struct {
    logger *loggingT
    *bufio.Writer
    file   *os.File
    sev    severity
    nbytes uint64 // The number of bytes written to this file
}

func (sb *syncBuffer) Sync() error {
    return sb.file.Sync()
}

func (sb *syncBuffer) Write(p []byte) (n int, err error) {
    if sb.nbytes+uint64(len(p)) >= MaxSize {
        if err := sb.rotateFile(time.Now()); err != nil {
            sb.logger.exit(err)
        }
    }
    n, err = sb.Writer.Write(p)
    sb.nbytes += uint64(n)
    if err != nil {
        sb.logger.exit(err)
    }
    return
}

// rotateFile closes the syncBuffer's file and starts a new one.
func (sb *syncBuffer) rotateFile(now time.Time) error {
    if sb.file != nil {
        sb.Flush()
        sb.file.Close()
    }
    var err error
    sb.file, _, err = create(severityName[sb.sev], now)
    sb.nbytes = 0
    if err != nil {
        return err
    }

    sb.Writer = bufio.NewWriterSize(sb.file, bufferSize)

    // Write header.
    var buf bytes.Buffer
    fmt.Fprintf(&buf, "Log file created at: %s\n", now.Format("2006/01/02 15:04:05"))
    fmt.Fprintf(&buf, "Running on machine: %s\n", host)
    fmt.Fprintf(&buf, "Binary: Built with %s %s for %s/%s\n", runtime.Compiler, runtime.Version(), runtime.GOOS, runtime.GOARCH)
    fmt.Fprintf(&buf, "Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg\n")
    n, err := sb.file.Write(buf.Bytes())
    sb.nbytes += uint64(n)
    return err
}

// bufferSize sizes the buffer associated with each log file. It's large
// so that log records can accumulate without the logging thread blocking
// on disk I/O. The flushDaemon will block instead.
const bufferSize = 256 * 1024

// createFiles creates all the log files for severity from sev down to infoLog.
// l.mu is held.
func (l *loggingT) createFiles(sev severity) error {
    now := time.Now()
    // Files are created in decreasing severity order, so as soon as we find one
    // has already been created, we can stop.
    for s := sev; s >= infoLog && l.file[s] == nil; s-- {
        sb := &syncBuffer{
            logger: l,
            sev:    s,
        }
        if err := sb.rotateFile(now); err != nil {
            return err
        }
        l.file[s] = sb
    }
    return nil
}

const flushInterval = 30 * time.Second

// flushDaemon periodically flushes the log file buffers.
func (l *loggingT) flushDaemon() {
    for _ = range time.NewTicker(flushInterval).C {
        l.lockAndFlushAll()
    }
}

// lockAndFlushAll is like flushAll but locks l.mu first.
func (l *loggingT) lockAndFlushAll() {
    l.mu.Lock()
    l.flushAll()
    l.mu.Unlock()
}

// flushAll flushes all the logs and attempts to "sync" their data to disk.
// l.mu is held.
func (l *loggingT) flushAll() {
    // Flush from fatal down, in case there's trouble flushing.
    for s := fatalLog; s >= infoLog; s-- {
        file := l.file[s]
        if file != nil {
            file.Flush() // ignore error
            file.Sync()  // ignore error
        }
    }
}

// setV computes and remembers the V level for a given PC
// when vmodule is enabled.
// File pattern matching takes the basename of the file, stripped
// of its .go suffix, and uses filepath.Match, which is a little more
// general than the *? matching used in C++.
// l.mu is held.
func (l *loggingT) setV(pc uintptr) Level {
    fn := runtime.FuncForPC(pc)
    file, _ := fn.FileLine(pc)
    // The file is something like /a/b/c/d.go. We want just the d.
    if strings.HasSuffix(file, ".go") {
        file = file[:len(file)-3]
    }
    if slash := strings.LastIndex(file, "/"); slash >= 0 {
        file = file[slash+1:]
    }
    for _, filter := range l.vmodule.filter {
        if filter.match(file) {
            l.vmap[pc] = filter.level
            return filter.level
        }
    }
    l.vmap[pc] = 0
    return 0
}

// Verbose is a boolean type that implements Infof (like Printf) etc.
// See the documentation of V for more information.
type Verbose bool

// V reports whether verbosity at the call site is at least the requested level.
// The returned value is a boolean of type Verbose, which implements Info, Infoln
// and Infof. These methods will write to the Info log if called.
// Thus, one may write either
//  if woodsman.V(2) { woodsman.Info("log this") }
// or
//  woodsman.V(2).Info("log this")
// The second form is shorter but the first is cheaper if logging is off because it does
// not evaluate its arguments.
//
// Whether an individual call to V generates a log record depends on the setting of
// the -v and --vmodule flags; both are off by default. If the level in the call to
// V is at least the value of -v, or of -vmodule for the source file containing the
// call, the V call will log.
func V(level Level) Verbose {
    // This function tries hard to be cheap unless there's work to do.
    // The fast path is two atomic loads and compares.

    // Here is a cheap but safe test to see if V logging is enabled globally.
    if logging.verbosity.get() >= level {
        return Verbose(true)
    }

    // It's off globally but it vmodule may still be set.
    // Here is another cheap but safe test to see if vmodule is enabled.
    if atomic.LoadInt32(&logging.filterLength) > 0 {
        // Now we need a proper lock to use the logging structure. The pcs field
        // is shared so we must lock before accessing it. This is fairly expensive,
        // but if V logging is enabled we're slow anyway.
        logging.mu.Lock()
        defer logging.mu.Unlock()
        if runtime.Callers(2, logging.pcs[:]) == 0 {
            return Verbose(false)
        }
        v, ok := logging.vmap[logging.pcs[0]]
        if !ok {
            v = logging.setV(logging.pcs[0])
        }
        return Verbose(v >= level)
    }
    return Verbose(false)
}