Cleanup log package, remove dependency on taskmanager package

This commit is contained in:
Daniel 2019-09-06 22:45:49 +02:00
parent 0b6582dd15
commit c1cc409558
9 changed files with 255 additions and 210 deletions

View file

@ -9,5 +9,5 @@ var (
func init() {
flag.StringVar(&logLevelFlag, "log", "info", "set log level to [trace|debug|info|warning|error|critical]")
flag.StringVar(&pkgLogLevelsFlag, "plog", "", "set log level of packages: database=trace,firewall=debug")
flag.StringVar(&pkgLogLevelsFlag, "plog", "", "set log level of packages: database=trace,notifications=debug")
}

View file

@ -9,7 +9,7 @@ var counter uint16
const maxCount uint16 = 999
func (s severity) String() string {
func (s Severity) String() string {
switch s {
case TraceLevel:
return "TRAC"
@ -51,15 +51,15 @@ func formatLine(line *logLine, duplicates uint64, useColor bool) string {
fLine = fmt.Sprintf("%s%s %s:%03d %s %s %03d%s%s %s", colorStart, line.timestamp.Format("060102 15:04:05.000"), line.file[fPartStart:], line.line, rightArrow, line.level.String(), counter, formatDuplicates(duplicates), colorEnd, line.msg)
}
if line.trace != nil {
if line.tracer != nil {
// append full trace time
if len(line.trace.actions) > 0 {
fLine += fmt.Sprintf(" Σ=%s", line.timestamp.Sub(line.trace.actions[0].timestamp))
if len(line.tracer.logs) > 0 {
fLine += fmt.Sprintf(" Σ=%s", line.timestamp.Sub(line.tracer.logs[0].timestamp))
}
// append all trace actions
var d time.Duration
for i, action := range line.trace.actions {
for i, action := range line.tracer.logs {
// set color
if useColor {
colorStart = action.level.color()
@ -71,10 +71,10 @@ func formatLine(line *logLine, duplicates uint64, useColor bool) string {
fPartStart = 0
}
// format
if i == len(line.trace.actions)-1 { // last
if i == len(line.tracer.logs)-1 { // last
d = line.timestamp.Sub(action.timestamp)
} else {
d = line.trace.actions[i+1].timestamp.Sub(action.timestamp)
d = line.tracer.logs[i+1].timestamp.Sub(action.timestamp)
}
fLine += fmt.Sprintf("\n%s%19s %s:%03d %s %s%s %s", colorStart, d, action.file[fPartStart:], action.line, rightArrow, action.level.String(), colorEnd, action.msg)
}

View file

@ -16,7 +16,7 @@ const (
// colorWhite = "\033[37m"
)
func (s severity) color() string {
func (s Severity) color() string {
switch s {
case DebugLevel:
return colorCyan

View file

@ -28,7 +28,7 @@ func init() {
colorsSupported = osdetail.EnableColorSupport()
}
func (s severity) color() string {
func (s Severity) color() string {
if colorsSupported {
switch s {
case DebugLevel:

View file

@ -8,24 +8,14 @@ import (
"time"
)
func fastcheck(level severity) bool {
if pkgLevelsActive.IsSet() {
return true
}
if uint32(level) < atomic.LoadUint32(logLevel) {
return false
}
return true
}
func log(level severity, msg string, trace *ContextTracer) {
func log(level Severity, msg string, tracer *ContextTracer) {
if !started.IsSet() {
// a bit resouce intense, but keeps logs before logging started.
// FIXME: create option to disable logging
go func() {
<-startedSignal
log(level, msg, trace)
log(level, msg, tracer)
}()
return
}
@ -72,7 +62,7 @@ func log(level severity, msg string, trace *ContextTracer) {
// create log object
log := &logLine{
msg: msg,
trace: trace,
tracer: tracer,
level: level,
timestamp: now,
file: file,
@ -94,82 +84,96 @@ func log(level severity, msg string, trace *ContextTracer) {
}
func Tracef(things ...interface{}) {
if fastcheck(TraceLevel) {
log(TraceLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
func fastcheck(level Severity) bool {
if pkgLevelsActive.IsSet() {
return true
}
if uint32(level) >= atomic.LoadUint32(logLevel) {
return true
}
return false
}
// Trace is used to log tiny steps. Log traces to context if you can!
func Trace(msg string) {
if fastcheck(TraceLevel) {
log(TraceLevel, msg, nil)
}
}
func Debugf(things ...interface{}) {
if fastcheck(DebugLevel) {
log(DebugLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
// Tracef is used to log tiny steps. Log traces to context if you can!
func Tracef(format string, things ...interface{}) {
if fastcheck(TraceLevel) {
log(TraceLevel, fmt.Sprintf(format, things...), nil)
}
}
// Debug is used to log minor errors or unexpected events. These occurences are usually not worth mentioning in itself, but they might hint at a bigger problem.
func Debug(msg string) {
if fastcheck(DebugLevel) {
log(DebugLevel, msg, nil)
}
}
func Infof(things ...interface{}) {
if fastcheck(InfoLevel) {
log(InfoLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
// Debugf is used to log minor errors or unexpected events. These occurences are usually not worth mentioning in itself, but they might hint at a bigger problem.
func Debugf(format string, things ...interface{}) {
if fastcheck(DebugLevel) {
log(DebugLevel, fmt.Sprintf(format, things...), nil)
}
}
// Info is used to log mildly significant events. Should be used to inform about somewhat bigger or user affecting events that happen.
func Info(msg string) {
if fastcheck(InfoLevel) {
log(InfoLevel, msg, nil)
}
}
func Warningf(things ...interface{}) {
if fastcheck(WarningLevel) {
log(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
// Infof is used to log mildly significant events. Should be used to inform about somewhat bigger or user affecting events that happen.
func Infof(format string, things ...interface{}) {
if fastcheck(InfoLevel) {
log(InfoLevel, fmt.Sprintf(format, things...), nil)
}
}
// Warning is used to log (potentially) bad events, but nothing broke (even a little) and there is no need to panic yet.
func Warning(msg string) {
if fastcheck(WarningLevel) {
log(WarningLevel, msg, nil)
}
}
func Errorf(things ...interface{}) {
if fastcheck(ErrorLevel) {
log(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
// Warningf is used to log (potentially) bad events, but nothing broke (even a little) and there is no need to panic yet.
func Warningf(format string, things ...interface{}) {
if fastcheck(WarningLevel) {
log(WarningLevel, fmt.Sprintf(format, things...), nil)
}
}
// Error is used to log errors that break or impair functionality. The task/process may have to be aborted and tried again later. The system is still operational. Maybe User/Admin should be informed.
func Error(msg string) {
if fastcheck(ErrorLevel) {
log(ErrorLevel, msg, nil)
}
}
func Criticalf(things ...interface{}) {
if fastcheck(CriticalLevel) {
log(CriticalLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
// Errorf is used to log errors that break or impair functionality. The task/process may have to be aborted and tried again later. The system is still operational.
func Errorf(format string, things ...interface{}) {
if fastcheck(ErrorLevel) {
log(ErrorLevel, fmt.Sprintf(format, things...), nil)
}
}
// Critical is used to log events that completely break the system. Operation connot continue. User/Admin must be informed.
func Critical(msg string) {
if fastcheck(CriticalLevel) {
log(CriticalLevel, msg, nil)
}
}
func Testf(things ...interface{}) {
fmt.Printf(things[0].(string), things[1:]...)
}
func Test(msg string) {
fmt.Println(msg)
// Criticalf is used to log events that completely break the system. Operation connot continue. User/Admin must be informed.
func Criticalf(format string, things ...interface{}) {
if fastcheck(CriticalLevel) {
log(CriticalLevel, fmt.Sprintf(format, things...), nil)
}
}

View file

@ -30,12 +30,13 @@ import (
- logging is configured by main module and is supplied access to configuration and taskmanager
*/
type severity uint32
// Severity describes a log level.
type Severity uint32
type logLine struct {
msg string
trace *ContextTracer
level severity
tracer *ContextTracer
level Severity
timestamp time.Time
file string
line int
@ -45,7 +46,7 @@ func (ll *logLine) Equal(ol *logLine) bool {
switch {
case ll.msg != ol.msg:
return false
case ll.trace != nil || ol.trace != nil:
case ll.tracer != nil || ol.tracer != nil:
return false
case ll.file != ol.file:
return false
@ -57,13 +58,14 @@ func (ll *logLine) Equal(ol *logLine) bool {
return true
}
// Log Levels
const (
TraceLevel severity = 1
DebugLevel severity = 2
InfoLevel severity = 3
WarningLevel severity = 4
ErrorLevel severity = 5
CriticalLevel severity = 6
TraceLevel Severity = 1
DebugLevel Severity = 2
InfoLevel Severity = 3
WarningLevel Severity = 4
ErrorLevel Severity = 5
CriticalLevel Severity = 6
)
var (
@ -74,7 +76,7 @@ var (
logLevel = &logLevelInt
pkgLevelsActive = abool.NewBool(false)
pkgLevels = make(map[string]severity)
pkgLevels = make(map[string]Severity)
pkgLevelsLock sync.Mutex
logsWaiting = make(chan bool, 1)
@ -90,22 +92,26 @@ var (
testErrors = abool.NewBool(false)
)
func SetPkgLevels(levels map[string]severity) {
// SetPkgLevels sets individual log levels for packages.
func SetPkgLevels(levels map[string]Severity) {
pkgLevelsLock.Lock()
pkgLevels = levels
pkgLevelsLock.Unlock()
pkgLevelsActive.Set()
}
// UnSetPkgLevels removes all individual log levels for packages.
func UnSetPkgLevels() {
pkgLevelsActive.UnSet()
}
func SetLogLevel(level severity) {
// SetLogLevel sets a new log level.
func SetLogLevel(level Severity) {
atomic.StoreUint32(logLevel, uint32(level))
}
func ParseLevel(level string) severity {
// ParseLevel returns the level severity of a log level name.
func ParseLevel(level string) Severity {
switch strings.ToLower(level) {
case "trace":
return 1
@ -123,6 +129,7 @@ func ParseLevel(level string) severity {
return 0
}
// Start starts the logging system. Must be called in order to see logs.
func Start() (err error) {
if !initializing.SetToIf(false, true) {
@ -143,7 +150,7 @@ func Start() (err error) {
// get and set file loglevels
pkgLogLevels := pkgLogLevelsFlag
if len(pkgLogLevels) > 0 {
newPkgLevels := make(map[string]severity)
newPkgLevels := make(map[string]Severity)
for _, pair := range strings.Split(pkgLogLevels, ",") {
splitted := strings.Split(pair, "=")
if len(splitted) != 2 {
@ -170,7 +177,7 @@ func Start() (err error) {
return err
}
// Shutdown writes remaining log lines and then stops the logger.
// Shutdown writes remaining log lines and then stops the log system.
func Shutdown() {
close(shutdownSignal)
shutdownWaitGroup.Wait()

View file

@ -3,10 +3,29 @@ package log
import (
"fmt"
"time"
"github.com/safing/portbase/taskmanager"
)
var (
schedulingEnabled = false
writeTrigger = make(chan struct{})
)
// EnableScheduling enables external scheduling of the logger. This will require to manually trigger writes via TriggerWrite whenevery logs should be written. Please note that full buffers will also trigger writing. Must be called before Start() to have an effect.
func EnableScheduling() {
if !initializing.IsSet() {
schedulingEnabled = true
}
}
// TriggerWriter triggers log output writing.
func TriggerWriter() {
if started.IsSet() && schedulingEnabled {
select {
case writeTrigger <- struct{}{}:
}
}
}
func writeLine(line *logLine, duplicates uint64) {
fmt.Println(formatLine(line, duplicates, true))
// TODO: implement file logging and setting console/file logging
@ -23,7 +42,6 @@ func writer() {
var line *logLine
var lastLine *logLine
var duplicates uint64
startedTask := false
defer shutdownWaitGroup.Done()
for {
@ -41,8 +59,7 @@ func writer() {
// wait for timeslot to log, or when buffer is full
select {
case <-taskmanager.StartVeryLowPriorityMicroTask():
startedTask = true
case <-writeTrigger:
case <-forceEmptyingOfBuffer:
case <-shutdownSignal:
for {
@ -89,10 +106,6 @@ func writer() {
writeLine(line, duplicates)
duplicates = 0
default:
if startedTask {
taskmanager.EndMicroTask()
startedTask = false
}
break writeLoop
}
}

View file

@ -5,41 +5,35 @@ import (
"fmt"
"runtime"
"sync"
"sync/atomic"
"time"
)
// Key for context value
// ContextTracerKey is the key used for the context key/value storage.
type ContextTracerKey struct{}
// ContextTracer is attached to a context in order bind logs to a context.
type ContextTracer struct {
sync.Mutex
actions []*Action
}
type Action struct {
timestamp time.Time
level severity
msg string
file string
line int
logs []*logLine
}
var (
key = ContextTracerKey{}
nilTracer *ContextTracer
key = ContextTracerKey{}
)
func AddTracer(ctx context.Context) context.Context {
if ctx != nil && fastcheckLevel(TraceLevel) {
// AddTracer adds a ContextTracer to the returned Context. Will return a nil ContextTracer if one already exists. Will return a nil context if nil.
func AddTracer(ctx context.Context) (context.Context, *ContextTracer) {
if ctx != nil && fastcheck(TraceLevel) {
_, ok := ctx.Value(key).(*ContextTracer)
if !ok {
return context.WithValue(ctx, key, &ContextTracer{})
tracer := &ContextTracer{}
return context.WithValue(ctx, key, tracer), tracer
}
}
return ctx
return ctx, nil
}
// Tracer returns the ContextTracer previously added to the given Context.
func Tracer(ctx context.Context) *ContextTracer {
if ctx != nil {
tracer, ok := ctx.Value(key).(*ContextTracer)
@ -47,10 +41,59 @@ func Tracer(ctx context.Context) *ContextTracer {
return tracer
}
}
return nilTracer
return nil
}
func (ct *ContextTracer) logTrace(level severity, msg string) {
// Submit collected logs on the context for further processing/outputting. Does nothing if called on a nil ContextTracer.
func (tracer *ContextTracer) Submit() {
if tracer != nil {
return
}
if !started.IsSet() {
// a bit resouce intense, but keeps logs before logging started.
// FIXME: create option to disable logging
go func() {
<-startedSignal
tracer.Submit()
}()
return
}
if len(tracer.logs) == 0 {
return
}
// extract last line as main line
mainLine := tracer.logs[len(tracer.logs)-1]
tracer.logs = tracer.logs[:len(tracer.logs)-1]
// create log object
log := &logLine{
msg: mainLine.msg,
tracer: tracer,
level: mainLine.level,
timestamp: mainLine.timestamp,
file: mainLine.file,
line: mainLine.line,
}
// send log to processing
select {
case logBuffer <- log:
default:
forceEmptyingOfBuffer <- true
logBuffer <- log
}
// wake up writer if necessary
if logsWaitingFlag.SetToIf(false, true) {
logsWaiting <- true
}
}
func (tracer *ContextTracer) log(level Severity, msg string) {
// get file and line
_, file, line, ok := runtime.Caller(2)
if !ok {
@ -64,9 +107,9 @@ func (ct *ContextTracer) logTrace(level severity, msg string) {
}
}
ct.Lock()
defer ct.Unlock()
ct.actions = append(ct.actions, &Action{
tracer.Lock()
defer tracer.Unlock()
tracer.logs = append(tracer.logs, &logLine{
timestamp: time.Now(),
level: level,
msg: msg,
@ -75,146 +118,122 @@ func (ct *ContextTracer) logTrace(level severity, msg string) {
})
}
func (ct *ContextTracer) Tracef(things ...interface{}) (ok bool) {
if ct != nil {
if fastcheckLevel(TraceLevel) {
ct.logTrace(TraceLevel, fmt.Sprintf(things[0].(string), things[1:]...))
}
return true
// Trace is used to log tiny steps. Log traces to context if you can!
func (tracer *ContextTracer) Trace(msg string) {
switch {
case tracer != nil:
tracer.log(TraceLevel, msg)
case fastcheck(TraceLevel):
log(TraceLevel, msg, nil)
}
return false
}
func (ct *ContextTracer) Trace(msg string) (ok bool) {
if ct != nil {
if fastcheckLevel(TraceLevel) {
ct.logTrace(TraceLevel, msg)
}
return true
// Tracef is used to log tiny steps. Log traces to context if you can!
func (tracer *ContextTracer) Tracef(format string, things ...interface{}) {
switch {
case tracer != nil:
tracer.log(TraceLevel, fmt.Sprintf(format, things...))
case fastcheck(TraceLevel):
log(TraceLevel, fmt.Sprintf(format, things...), nil)
}
return false
}
func (ct *ContextTracer) Warningf(things ...interface{}) (ok bool) {
if ct != nil {
if fastcheckLevel(TraceLevel) {
ct.logTrace(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...))
}
return true
// Debug is used to log minor errors or unexpected events. These occurences are usually not worth mentioning in itself, but they might hint at a bigger problem.
func (tracer *ContextTracer) Debug(msg string) {
switch {
case tracer != nil:
tracer.log(DebugLevel, msg)
case fastcheck(DebugLevel):
log(DebugLevel, msg, nil)
}
return false
}
func (ct *ContextTracer) Warning(msg string) (ok bool) {
if ct != nil {
if fastcheckLevel(TraceLevel) {
ct.logTrace(WarningLevel, msg)
}
return true
// Debugf is used to log minor errors or unexpected events. These occurences are usually not worth mentioning in itself, but they might hint at a bigger problem.
func (tracer *ContextTracer) Debugf(format string, things ...interface{}) {
switch {
case tracer != nil:
tracer.log(DebugLevel, fmt.Sprintf(format, things...))
case fastcheck(DebugLevel):
log(DebugLevel, fmt.Sprintf(format, things...), nil)
}
return false
}
func (ct *ContextTracer) Errorf(things ...interface{}) (ok bool) {
if ct != nil {
if fastcheckLevel(TraceLevel) {
ct.logTrace(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...))
}
return true
// Info is used to log mildly significant events. Should be used to inform about somewhat bigger or user affecting events that happen.
func (tracer *ContextTracer) Info(msg string) {
switch {
case tracer != nil:
tracer.log(InfoLevel, msg)
case fastcheck(InfoLevel):
log(InfoLevel, msg, nil)
}
return false
}
func (ct *ContextTracer) Error(msg string) (ok bool) {
if ct != nil {
if fastcheckLevel(TraceLevel) {
ct.logTrace(ErrorLevel, msg)
}
return true
// Infof is used to log mildly significant events. Should be used to inform about somewhat bigger or user affecting events that happen.
func (tracer *ContextTracer) Infof(format string, things ...interface{}) {
switch {
case tracer != nil:
tracer.log(InfoLevel, fmt.Sprintf(format, things...))
case fastcheck(InfoLevel):
log(InfoLevel, fmt.Sprintf(format, things...), nil)
}
return false
}
func DebugTrace(ctx context.Context, msg string) (ok bool) {
tracer, ok := ctx.Value(key).(*ContextTracer)
if ok && fastcheckLevel(TraceLevel) {
log(DebugLevel, msg, tracer)
return true
// Warning is used to log (potentially) bad events, but nothing broke (even a little) and there is no need to panic yet.
func (tracer *ContextTracer) Warning(msg string) {
switch {
case tracer != nil:
tracer.log(WarningLevel, msg)
case fastcheck(WarningLevel):
log(WarningLevel, msg, nil)
}
log(DebugLevel, msg, nil)
return false
}
func DebugTracef(ctx context.Context, things ...interface{}) (ok bool) {
tracer, ok := ctx.Value(key).(*ContextTracer)
if ok && fastcheckLevel(TraceLevel) {
log(DebugLevel, fmt.Sprintf(things[0].(string), things[1:]...), tracer)
return true
// Warningf is used to log (potentially) bad events, but nothing broke (even a little) and there is no need to panic yet.
func (tracer *ContextTracer) Warningf(format string, things ...interface{}) {
switch {
case tracer != nil:
tracer.log(WarningLevel, fmt.Sprintf(format, things...))
case fastcheck(WarningLevel):
log(WarningLevel, fmt.Sprintf(format, things...), nil)
}
log(DebugLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
return false
}
func InfoTrace(ctx context.Context, msg string) (ok bool) {
tracer, ok := ctx.Value(key).(*ContextTracer)
if ok && fastcheckLevel(TraceLevel) {
log(InfoLevel, msg, tracer)
return true
// Error is used to log errors that break or impair functionality. The task/process may have to be aborted and tried again later. The system is still operational. Maybe User/Admin should be informed.
func (tracer *ContextTracer) Error(msg string) {
switch {
case tracer != nil:
tracer.log(ErrorLevel, msg)
case fastcheck(ErrorLevel):
log(ErrorLevel, msg, nil)
}
log(InfoLevel, msg, nil)
return false
}
func InfoTracef(ctx context.Context, things ...interface{}) (ok bool) {
tracer, ok := ctx.Value(key).(*ContextTracer)
if ok && fastcheckLevel(TraceLevel) {
log(InfoLevel, fmt.Sprintf(things[0].(string), things[1:]...), tracer)
return true
// Errorf is used to log errors that break or impair functionality. The task/process may have to be aborted and tried again later. The system is still operational.
func (tracer *ContextTracer) Errorf(format string, things ...interface{}) {
switch {
case tracer != nil:
tracer.log(ErrorLevel, fmt.Sprintf(format, things...))
case fastcheck(ErrorLevel):
log(ErrorLevel, fmt.Sprintf(format, things...), nil)
}
log(InfoLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
return false
}
func WarningTrace(ctx context.Context, msg string) (ok bool) {
tracer, ok := ctx.Value(key).(*ContextTracer)
if ok && fastcheckLevel(TraceLevel) {
log(WarningLevel, msg, tracer)
return true
// Critical is used to log events that completely break the system. Operation connot continue. User/Admin must be informed.
func (tracer *ContextTracer) Critical(msg string) {
switch {
case tracer != nil:
tracer.log(CriticalLevel, msg)
case fastcheck(CriticalLevel):
log(CriticalLevel, msg, nil)
}
log(WarningLevel, msg, nil)
return false
}
func WarningTracef(ctx context.Context, things ...interface{}) (ok bool) {
tracer, ok := ctx.Value(key).(*ContextTracer)
if ok && fastcheckLevel(TraceLevel) {
log(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...), tracer)
return true
// Criticalf is used to log events that completely break the system. Operation connot continue. User/Admin must be informed.
func (tracer *ContextTracer) Criticalf(format string, things ...interface{}) {
switch {
case tracer != nil:
tracer.log(CriticalLevel, fmt.Sprintf(format, things...))
case fastcheck(CriticalLevel):
log(CriticalLevel, fmt.Sprintf(format, things...), nil)
}
log(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
return false
}
func ErrorTrace(ctx context.Context, msg string) (ok bool) {
tracer, ok := ctx.Value(key).(*ContextTracer)
if ok && fastcheckLevel(TraceLevel) {
log(ErrorLevel, msg, tracer)
return true
}
log(ErrorLevel, msg, nil)
return false
}
func ErrorTracef(ctx context.Context, things ...interface{}) (ok bool) {
tracer, ok := ctx.Value(key).(*ContextTracer)
if ok && fastcheckLevel(TraceLevel) {
log(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...), tracer)
return true
}
log(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil)
return false
}
func fastcheckLevel(level severity) bool {
return uint32(level) >= atomic.LoadUint32(logLevel)
}

View file

@ -12,20 +12,22 @@ func TestContextTracer(t *testing.T) {
t.Skip()
}
ctx := AddTracer(context.Background())
ctx, tracer := AddTracer(context.Background())
_ = Tracer(ctx)
Tracer(ctx).Trace("api: request received, checking security")
tracer.Trace("api: request received, checking security")
time.Sleep(1 * time.Millisecond)
Tracer(ctx).Trace("login: logging in user")
tracer.Trace("login: logging in user")
time.Sleep(1 * time.Millisecond)
Tracer(ctx).Trace("database: fetching requested resources")
tracer.Trace("database: fetching requested resources")
time.Sleep(10 * time.Millisecond)
Tracer(ctx).Warning("database: partial failure")
tracer.Warning("database: partial failure")
time.Sleep(10 * time.Microsecond)
Tracer(ctx).Trace("renderer: rendering output")
tracer.Trace("renderer: rendering output")
time.Sleep(1 * time.Millisecond)
Tracer(ctx).Trace("api: returning request")
tracer.Trace("api: returning request")
DebugTrace(ctx, "api: completed request")
tracer.Trace("api: completed request")
tracer.Submit()
time.Sleep(100 * time.Millisecond)
}