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