New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

miniTS in TextFormatter is inaccurate when hook takes a long time #457

Closed
at15 opened this Issue Dec 18, 2016 · 2 comments

Comments

Projects
None yet
2 participants
@at15
Copy link
Contributor

at15 commented Dec 18, 2016

Problem

When using elapsed time instead of full time, it is calculated using the miniTS function

func miniTS() int {
	return int(time.Since(baseTimestamp) / time.Second)
}

and time.Since is a shortcut for time.Now().Sub(t), if there is no hook executed, this function is correct, since entry.Time would be the same as time.Now(). However, the formatter is called after all the hooks are executed, thus if the hooks took a long time to finish, it would formatter would output a wrong elapsed time.

Replay

i.e. the following code use a dummy hook that do nothing but sleep for 1 second when it is called

package main

import (
	"time"

	"fmt"

	log "github.com/Sirupsen/logrus"
)

type DelayHook struct {
}

func (h *DelayHook) Levels() []log.Level {
	return []log.Level{log.InfoLevel}
}

func (h *DelayHook) Fire(entry *log.Entry) error {
	time.Sleep(1 * time.Second)
	return nil
}

func init() {
	h := &DelayHook{}
	log.AddHook(h)
}

func main() {
	fmt.Println("start")
	log.Info("1")
	log.Info("2")
	fmt.Println("end")
}

the output is

start
INFO[0001] 1                                            
INFO[0002] 2                                            
end

but it should be

start
INFO[0000] 1                                            
INFO[0001] 2                                            
end

Solution

A possible solution is to replace mintTS with int(entry.Time.Sub(baseTimestamp)/time.Second), change https://github.com/sirupsen/logrus/blob/master/text_formatter.go#L119

fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, miniTS(), entry.Message)

to

fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimeStamp)/time.Second), entry.Message)

Also as mentioned by #435, maybe enable non-blocking execution of hook is a better way, also adding Flush may improve performance by batching when the Writer is a remote service that takes long round trip time, but this may require a lot of change in the code

btw: the travis badge in README have broken link due to case sensitive problem

@at15 at15 referenced this issue Dec 18, 2016

Closed

[Refactor] Log filter #59

6 of 7 tasks complete

@at15 at15 changed the title miniTs in TextFormatter is inaccurate when hook takes a long time miniTS in TextFormatter is inaccurate when hook takes a long time Dec 18, 2016

@stevvooe

This comment has been minimized.

Copy link
Collaborator

stevvooe commented Jan 10, 2017

@at15 Please submit a PR.

at15 added a commit to at15/logrus that referenced this issue Jan 11, 2017

Remove miniTS in TextFormatter
- Related issues: sirupsen#457
- miniTS use current time instead of time the log function is called,
which is inaccurate when hook takes a long time
- `miniTS` is removed and replaced by
`int(entry.Time.Sub(baseTimestamp)/time.Second)` in `printColored`
which is the only usage of `miniTS`
@at15

This comment has been minimized.

Copy link
Contributor Author

at15 commented Jan 11, 2017

@stevvooe PR submitted

Paddy-Truck added a commit to Paddy-Truck/logrus that referenced this issue Sep 8, 2017

Remove miniTS in TextFormatter
- Related issues: sirupsen#457
- miniTS use current time instead of time the log function is called,
which is inaccurate when hook takes a long time
- `miniTS` is removed and replaced by
`int(entry.Time.Sub(baseTimestamp)/time.Second)` in `printColored`
which is the only usage of `miniTS`
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment