gopkg.in/dedis/onet.v2@v2.0.0-20181115163211-c8f3724038a7/log/lvl.go (about) 1 package log 2 3 import ( 4 "errors" 5 "flag" 6 "fmt" 7 "os" 8 "regexp" 9 "runtime" 10 "runtime/pprof" 11 "strconv" 12 "sync" 13 "testing" 14 "time" 15 ) 16 17 const ( 18 lvlWarning = iota - 20 19 lvlError 20 lvlFatal 21 lvlPanic 22 lvlInfo 23 lvlPrint 24 ) 25 26 // These formats can be used in place of the debugVisible 27 const ( 28 // FormatPython uses [x] and others to indicate what is shown 29 FormatPython = -1 30 // FormatNone is just pure print 31 FormatNone = 0 32 ) 33 34 // defaultMainTest indicates what debug-level should be used when `go test -v` 35 // is called. 36 const defaultMainTest = 2 37 38 // MainTestWait is the maximum time the MainTest-method waits before aborting 39 // and printing a stack-trace of all functions. 40 // This is deprecated and should not be used anymore. 41 var MainTestWait = 0 * time.Minute 42 43 // NamePadding - the padding of functions to make a nice debug-output - this is automatically updated 44 // whenever there are longer functions and kept at that new maximum. If you prefer 45 // to have a fixed output and don't remember oversized names, put a negative value 46 // in here. 47 var NamePadding = 40 48 49 // LinePadding of line-numbers for a nice debug-output - used in the same way as 50 // NamePadding. 51 var LinePadding = 3 52 53 // StaticMsg - if this variable is set, it will be outputted between the 54 // position and the message. 55 var StaticMsg = "" 56 57 // outputLines can be false to suppress outputting of lines in tests. 58 var outputLines = true 59 60 var debugMut sync.RWMutex 61 62 var regexpPaths, _ = regexp.Compile(".*/") 63 64 func init() { 65 stdLogger, err := newStdLogger() 66 if err != nil { 67 panic(err) 68 } 69 stdKey := RegisterLogger(stdLogger) 70 if stdKey != 0 { 71 panic(errors.New("Cannot add a logger before the standard logger")) 72 } 73 ParseEnv() 74 } 75 76 func lvl(lvl, skip int, args ...interface{}) { 77 debugMut.Lock() 78 defer debugMut.Unlock() 79 for _, l := range loggers { 80 // Get the *LoggerInfo that contains how should the formatting go. 81 lInfo := l.GetLoggerInfo() 82 83 if lvl > lInfo.DebugLvl { 84 continue 85 } 86 87 pc, _, line, _ := runtime.Caller(skip) 88 name := regexpPaths.ReplaceAllString(runtime.FuncForPC(pc).Name(), "") 89 lineStr := fmt.Sprintf("%d", line) 90 91 // For the testing-framework, we check the resulting string. So as not to 92 // have the tests fail every time somebody moves the functions, we put 93 // the line-# to 0 94 if !outputLines { 95 line = 0 96 } 97 98 if lInfo.UseColors { 99 // Only adjust the name and line padding if we also have color. 100 if len(name) > NamePadding && NamePadding > 0 { 101 NamePadding = len(name) 102 } 103 if len(lineStr) > LinePadding && LinePadding > 0 { 104 LinePadding = len(lineStr) 105 } 106 } 107 108 namePadding := 0 109 linePadding := 0 110 if lInfo.Padding { 111 namePadding = NamePadding 112 linePadding = LinePadding 113 } 114 fmtstr := fmt.Sprintf("%%%ds: %%%dd", namePadding, linePadding) 115 caller := fmt.Sprintf(fmtstr, name, line) 116 if StaticMsg != "" { 117 caller += "@" + StaticMsg 118 } 119 message := fmt.Sprintln(args...) 120 121 lvlAbs := lvl 122 if lvl < 0 { 123 lvlAbs *= -1 124 } 125 lvlStr := strconv.Itoa(lvlAbs) 126 if lvl < 0 { 127 lvlStr += "!" 128 } 129 switch lvl { 130 case lvlPrint: 131 lvlStr = "I" 132 case lvlInfo: 133 lvlStr = "I" 134 case lvlWarning: 135 lvlStr = "W" 136 case lvlError: 137 lvlStr = "E" 138 case lvlFatal: 139 lvlStr = "F" 140 case lvlPanic: 141 lvlStr = "P" 142 } 143 str := fmt.Sprintf(": (%s) - %s", caller, message) 144 if lInfo.ShowTime { 145 ti := time.Now() 146 str = fmt.Sprintf("%s.%09d%s", ti.Format("06/02/01 15:04:05"), ti.Nanosecond(), str) 147 } 148 str = fmt.Sprintf("%-2s%s", lvlStr, str) 149 150 l.Log(lvl, str) 151 } 152 } 153 154 // Needs two functions to keep the caller-depth the same and find who calls us 155 // Lvlf1 -> Lvlf -> lvl 156 // or 157 // Lvl1 -> lvld -> lvl 158 func lvlf(l int, f string, args ...interface{}) { 159 if l > DebugVisible() { 160 return 161 } 162 lvl(l, 3, fmt.Sprintf(f, args...)) 163 } 164 func lvld(l int, args ...interface{}) { 165 lvl(l, 3, args...) 166 } 167 168 // Lvl1 debug output is informational and always displayed 169 func Lvl1(args ...interface{}) { 170 lvld(1, args...) 171 } 172 173 // Lvl2 is more verbose but doesn't spam the stdout in case 174 // there is a big simulation 175 func Lvl2(args ...interface{}) { 176 lvld(2, args...) 177 } 178 179 // Lvl3 gives debug-output that can make it difficult to read 180 // for big simulations with more than 100 hosts 181 func Lvl3(args ...interface{}) { 182 lvld(3, args...) 183 } 184 185 // Lvl4 is only good for test-runs with very limited output 186 func Lvl4(args ...interface{}) { 187 lvld(4, args...) 188 } 189 190 // Lvl5 is for big data 191 func Lvl5(args ...interface{}) { 192 lvld(5, args...) 193 } 194 195 // Lvlf1 is like Lvl1 but with a format-string 196 func Lvlf1(f string, args ...interface{}) { 197 lvlf(1, f, args...) 198 } 199 200 // Lvlf2 is like Lvl2 but with a format-string 201 func Lvlf2(f string, args ...interface{}) { 202 lvlf(2, f, args...) 203 } 204 205 // Lvlf3 is like Lvl3 but with a format-string 206 func Lvlf3(f string, args ...interface{}) { 207 lvlf(3, f, args...) 208 } 209 210 // Lvlf4 is like Lvl4 but with a format-string 211 func Lvlf4(f string, args ...interface{}) { 212 lvlf(4, f, args...) 213 } 214 215 // Lvlf5 is like Lvl5 but with a format-string 216 func Lvlf5(f string, args ...interface{}) { 217 lvlf(5, f, args...) 218 } 219 220 // LLvl1 *always* prints 221 func LLvl1(args ...interface{}) { lvld(-1, args...) } 222 223 // LLvl2 *always* prints 224 func LLvl2(args ...interface{}) { lvld(-2, args...) } 225 226 // LLvl3 *always* prints 227 func LLvl3(args ...interface{}) { lvld(-3, args...) } 228 229 // LLvl4 *always* prints 230 func LLvl4(args ...interface{}) { lvld(-4, args...) } 231 232 // LLvl5 *always* prints 233 func LLvl5(args ...interface{}) { lvld(-5, args...) } 234 235 // LLvlf1 *always* prints 236 func LLvlf1(f string, args ...interface{}) { lvlf(-1, f, args...) } 237 238 // LLvlf2 *always* prints 239 func LLvlf2(f string, args ...interface{}) { lvlf(-2, f, args...) } 240 241 // LLvlf3 *always* prints 242 func LLvlf3(f string, args ...interface{}) { lvlf(-3, f, args...) } 243 244 // LLvlf4 *always* prints 245 func LLvlf4(f string, args ...interface{}) { lvlf(-4, f, args...) } 246 247 // LLvlf5 *always* prints 248 func LLvlf5(f string, args ...interface{}) { lvlf(-5, f, args...) } 249 250 // TestOutput sets the DebugVisible to 0 if 'show' 251 // is false, else it will set DebugVisible to 'level' 252 // 253 // Usage: TestOutput( test.Verbose(), 2 ) 254 func TestOutput(show bool, level int) { 255 debugMut.Lock() 256 defer debugMut.Unlock() 257 258 if show { 259 loggers[0].GetLoggerInfo().DebugLvl = level 260 } else { 261 loggers[0].GetLoggerInfo().DebugLvl = 0 262 } 263 } 264 265 // SetDebugVisible set the global debug output level in a go-rountine-safe way 266 func SetDebugVisible(lvl int) { 267 debugMut.Lock() 268 defer debugMut.Unlock() 269 loggers[0].GetLoggerInfo().DebugLvl = lvl 270 } 271 272 // DebugVisible returns the actual visible debug-level 273 func DebugVisible() int { 274 debugMut.RLock() 275 defer debugMut.RUnlock() 276 return loggers[0].GetLoggerInfo().DebugLvl 277 } 278 279 // SetShowTime allows for turning on the flag that adds the current 280 // time to the debug-output 281 func SetShowTime(show bool) { 282 debugMut.Lock() 283 defer debugMut.Unlock() 284 loggers[0].GetLoggerInfo().ShowTime = show 285 } 286 287 // ShowTime returns the current setting for showing the time in the debug 288 // output 289 func ShowTime() bool { 290 debugMut.Lock() 291 defer debugMut.Unlock() 292 return loggers[0].GetLoggerInfo().ShowTime 293 } 294 295 // SetUseColors can turn off or turn on the use of colors in the debug-output 296 func SetUseColors(useColors bool) { 297 debugMut.Lock() 298 defer debugMut.Unlock() 299 loggers[0].GetLoggerInfo().UseColors = useColors 300 } 301 302 // UseColors returns the actual setting of the color-usage in log 303 func UseColors() bool { 304 debugMut.Lock() 305 defer debugMut.Unlock() 306 return loggers[0].GetLoggerInfo().UseColors 307 } 308 309 // SetPadding can turn off or turn on the use of padding in log 310 func SetPadding(padding bool) { 311 debugMut.Lock() 312 defer debugMut.Unlock() 313 loggers[0].GetLoggerInfo().Padding = padding 314 } 315 316 // Padding returns the actual setting of the padding in log 317 func Padding() bool { 318 debugMut.Lock() 319 defer debugMut.Unlock() 320 return loggers[0].GetLoggerInfo().Padding 321 } 322 323 // MainTest can be called from TestMain. It will parse the flags and 324 // set the DebugVisible to defaultMainTest, then run the tests and check for 325 // remaining go-routines. 326 // If you give it an integer as optional parameter, it will set the 327 // debig-lvl to that integer. As `go test` will only output whenever 328 // `-v` is given, this gives no disadvantage over setting the default 329 // output-level. 330 func MainTest(m *testing.M, ls ...int) { 331 flag.Parse() 332 l := defaultMainTest 333 if len(ls) > 0 { 334 l = ls[0] 335 } 336 TestOutput(testing.Verbose(), l) 337 done := make(chan int) 338 go func() { 339 code := m.Run() 340 done <- code 341 }() 342 select { 343 case code := <-done: 344 if code == 0 { 345 AfterTest(nil) 346 } 347 os.Exit(code) 348 case <-time.After(interpretWait()): 349 Error("Didn't finish in time") 350 pprof.Lookup("goroutine").WriteTo(os.Stdout, 1) 351 os.Exit(1) 352 } 353 } 354 355 // ParseEnv looks at the following environment-variables: 356 // DEBUG_LVL - for the actual debug-lvl - default is 1 357 // DEBUG_TIME - whether to show the timestamp - default is false 358 // DEBUG_COLOR - whether to color the output - default is false 359 // DEBUG_PADDING - whether to pad the output nicely - default is true 360 func ParseEnv() { 361 dv := os.Getenv("DEBUG_LVL") 362 if dv != "" { 363 dvInt, err := strconv.Atoi(dv) 364 Lvl3("Setting level to", dv, dvInt, err) 365 SetDebugVisible(dvInt) 366 if err != nil { 367 Error("Couldn't convert", dv, "to debug-level") 368 } 369 } 370 dt := os.Getenv("DEBUG_TIME") 371 if dt != "" { 372 dtInt, err := strconv.ParseBool(dt) 373 Lvl3("Setting showTime to", dt, dtInt, err) 374 SetShowTime(dtInt) 375 if err != nil { 376 Error("Couldn't convert", dt, "to boolean") 377 } 378 } 379 dc := os.Getenv("DEBUG_COLOR") 380 if dc != "" { 381 ucInt, err := strconv.ParseBool(dc) 382 Lvl3("Setting useColor to", dc, ucInt, err) 383 SetUseColors(ucInt) 384 if err != nil { 385 Error("Couldn't convert", dc, "to boolean") 386 } 387 } 388 dp := os.Getenv("DEBUG_PADDING") 389 if dp != "" { 390 dpBool, err := strconv.ParseBool(dp) 391 Lvl3("Setting padding to", dp, dpBool, err) 392 SetPadding(dpBool) 393 if err != nil { 394 Error("Couldn't convert", dp, "to boolean") 395 } 396 } 397 } 398 399 // RegisterFlags adds the flags and the variables for the debug-control 400 // (standard logger) using the standard flag-package. 401 func RegisterFlags() { 402 ParseEnv() 403 defaultDebugLvl := DebugVisible() 404 defaultShowTime := ShowTime() 405 defaultUseColors := UseColors() 406 defaultPadding := Padding() 407 debugMut.Lock() 408 defer debugMut.Unlock() 409 flag.IntVar(&loggers[0].GetLoggerInfo().DebugLvl, "debug", defaultDebugLvl, "Change debug level (0-5)") 410 flag.BoolVar(&loggers[0].GetLoggerInfo().ShowTime, "debug-time", defaultShowTime, "Shows the time of each message") 411 flag.BoolVar(&loggers[0].GetLoggerInfo().UseColors, "debug-color", defaultUseColors, "Colors each message") 412 flag.BoolVar(&loggers[0].GetLoggerInfo().Padding, "debug-padding", defaultPadding, "Pads each message nicely") 413 } 414 415 var timeoutFlagMutex sync.Mutex 416 417 // interpretWait will use the test.timeout flag and MainTestWait to get 418 // the time to wait. From highest preference to lowest preference: 419 // 1. "-timeout 1m" 420 // 2. MainTestWait = 2*time.Minute 421 // 3. 10*time.Minute 422 // interpretWait will throw a warning if MainTestWait has been set. 423 func interpretWait() time.Duration { 424 timeoutFlagMutex.Lock() 425 defer timeoutFlagMutex.Unlock() 426 toFlag := flag.Lookup("test.timeout") 427 if toFlag == nil { 428 Fatal("MainTest should not be called outside of tests") 429 } 430 dur := MainTestWait 431 var err error 432 if dur != 0*time.Second { 433 Warn("Usage of MainTestWait is deprecated!") 434 } else { 435 dur = 10 * time.Minute 436 } 437 if toStr := toFlag.Value.String(); toStr != "0s" { 438 dur, err = time.ParseDuration(toStr) 439 ErrFatal(err, "couldn't parse passed timeout value") 440 } 441 return dur 442 }