go-pkgz / lgr Goto Github PK

The idea is to implement some kind of Filter/Mask option getting the list of sensitive elements, like tokens, passwords and so on and replacing them by "*****" in the output

My recent PR shows that I probably don't understand your intent. Correct me if I am wrong.

Logger usage:

• a package that needs logging must declare the interface:

type L interface {
	Logf(format string, args ...interface{})
}

• some code outside of the package creates and configures an instance of lgr.Logger (including ignored callers)
• the instance of lgr.Logger is passed to the package

Caller filtering:

• based on function level (we filter functions and not packages as it currently implied). Example setup code:

lgr.Setup(lgr.CallerIgnore("github.com/umputun/remark/backend/app/rest.errDetailsMsg", "github.com/umputun/remark/backend/app/rest.SendErrorJSON"))

• this filtering works irrespective of the logged caller info type (whether it CallerFile or CallerFunc or CallerPkg). Currently some "filtering" is done only if l.callerPkg && !l.callerFile && !l.callerFunc equals true.

Also in #2 you mention that below log record is incorrect (this record is generated by Remark42 if we execute command http :8080/auth having logger replaced to the new one from the master branch):

2019/03/08 04:58:17.446 [INFO]  {logger/logger.go:120} GET - /auth - 0c10a2713542 - 400 (36) - 93.542µs

It literally says that (*Logger).Logf() method is called from github.com/go-pkgz/rest/logger/logger.go:120 which is truth. Why do you think that this record is incorrect? What record would you prefer to see? Don't you mix up github.com/go-pkgz/lgr and github.com/go-pkgz/rest/logger packages?

The problem

There is a field ErrorLog *log.Logger in Go's http.Server. From docs: "ErrorLog specifies an optional logger for errors accepting connections, unexpected behavior from handlers, and underlying FileSystem errors. If nil, logging is done via the log package's standard logger."

Example code that triggers logging:

package main

import (
	"net/http"
)

func handler(w http.ResponseWriter, r *http.Request) {
	w.WriteHeader(200)
	w.WriteHeader(404)
}

func main() {
	http.ListenAndServe(":8080", http.HandlerFunc(handler))
}

If we run above server and issue this command:

$ http :8080

then the server prints this error message:

2019/03/21 14:30:40 http: superfluous response.WriteHeader call from main.handler (main.go:9)

Propose

Maybe it makes sense to implement lgr.Logger wrapping into the standard logger.

Thoughts about implementation

Basically the only thing we need to implement is a custom io.Writer. Then we can pass it to the log.Logger's constructor or set it up via SetOutput() function or method. But some problems arise if we do caller logging. Even if we skip all call frames related to log package then we still be somewhere inside net/http package. If we skip more frames then we may end up in our code (unexpected behavior from handlers, as in example) but may be not (errors accepting connections, FileSystem errors). So it may be worth to log only some generic caller info like {net/http}. This info may be passed as an argument to a method/function that wraps lgr.Logger.

Maybe smth based on templates, like {{.TS}} - {{.Level}} - {{.CallerFunc}} - {{.Msg}}.

Way to reproduce

package main

import (
	"github.com/go-pkgz/lgr"
)

func main() {
	const line = "https%3A%2F%2Ftest.test"
	lgr.Print(line)
}

Result

2020/10/06 22:06:37 INFO https%!A(MISSING)%!F(MISSING)%!F(MISSING)test.test

Expected result

2020/10/06 22:06:37 INFO https%3A%2F%2Ftest.test

Comparision with standard log package

This issue also affects lgr.ToStdLogger

More explained example

package main

import (
	"github.com/go-pkgz/lgr"
	"log"
	"os"
)

func main() {
	const line = "https%3A%2F%2Ftest.test"
	log.SetOutput(os.Stdout)

	lgr.Print(line)
	lgr.Printf(line)
	lgr.ToStdLogger(lgr.Default(), "").Print(line)

	log.Print(line)
	log.Printf(line)
	log.New(os.Stdout, "", 0).Print(line)
}

Results

2020/10/06 22:08:26 INFO  https%!A(MISSING)%!F(MISSING)%!F(MISSING)test.test
2020/10/06 22:08:26 INFO  https%!A(MISSING)%!F(MISSING)%!F(MISSING)test.test
2020/10/06 22:08:26 INFO  https%!A(MISSING)%!F(MISSING)%!F(MISSING)test.test
2020/10/06 22:08:26 https%3A%2F%2Ftest.test
2020/10/06 22:08:26 https%!A(MISSING)%!F(MISSING)%!F(MISSING)test.test
https%3A%2F%2Ftest.test

For some reason log.Printf("[ERROR] oh no!") puts error into stdout twice by default.

main.go

package main

import log "github.com/go-pkgz/lgr"

func main() {
	log.Printf("[ERROR] oh no!")
}

output

➜  _ git:(master) ✗ go run main.go
2021/01/28 12:11:29 ERROR oh no!
2021/01/28 12:11:29 ERROR oh no!

Maybe I am doing something wrong?

If I use the following construct
log.Printf("[DEBUG]%s = %s", k, v)
, the first character on the output is clipped.
`2019/06/15 20:53:33.451 [DEBUG] {go-krb-iis-history/main.go:116} -compress = null

2019/06/15 20:53:33.454 [DEBUG] {go-krb-iis-history/main.go:116} ontent-Type = application/json`

If I use the following construct
log.Printf("[DEBUG] %s = %s", k, v)
all ok
`2019/06/15 21:00:28.715 [DEBUG] {go-krb-iis-history/main.go:116} X-compress = null

2019/06/15 21:00:28.716 [DEBUG] {go-krb-iis-history/main.go:116} Content-Type = application/json`