Ability to customize Logrus about iris HOT 24 CLOSED

Th 27 July 2017

golog is now three plus times faster than our previous logger: logrus

Feel free to send a PR of your own loger benchmark to put it here!

C:\mygopath\src\github.com\kataras\golog\_benchmarks>go test -v -bench=. -benchtime=20s
goos: windows
goarch: amd64
pkg: github.com/kataras/golog/_benchmarks
BenchmarkGologPrint-8           10000000              4032 ns/op            1082 B/op         32 allocs/op
BenchmarkLogrusPrint-8           3000000              9421 ns/op            1611 B/op         64 allocs/op
PASS
ok      github.com/kataras/golog/_benchmarks    82.141s

from iris.

@mattrmiller Thanks for your nice words, we really do our bests!

Sorry for being late, I was thinking the design the whole time, here is my result:

Application
	Logs LogService
	

// Implements the https://golang.org/pkg/io/#ReadWriteCloser.
struct LogService
        Read(p []byte) (n int, err error) // io.Reader | somehow
	Write(p []byte) (n int, err error) // io.Writer | somehow
	Close() error // io.Closer | somehow
        // the above, three will complete the interface of the: 
	// https://golang.org/pkg/io/#ReadWriteCloser
	// in order to make possible to use everything inside the `io` package.
	// i.e 
        // https://golang.org/pkg/io/#example_MultiWriter	
	// https://golang.org/pkg/io/#example_TeeReader (piping)
	
	// by default will be text (string to []byte), but can be 
	// changed to `JSON` by setting directly the `encoding/json#Marshal` func
	// in order to be able to
        // receive logs from any other tools (written by other languages?) 
	Marshal LoggerMarshalFunc
	
	// should returns false when the specific "log" should be skipped 
	// and not logged to the `writer` or to thePipe or the defined writer.
	CanHandle(log []byte) bool 
	CanHandleStr(log string) bool // Marshal -> result as bytes -> log = string(result)

	// Intercept logs, as their original form
	Handle(log []byte)
        HandleStr(log string) // Marshal -> result as bytes -> log = string(result)
	
	// Marshal(v) -> result as []byte -> CanHandle(result) -> true -> Write(result) -> Handle(result)
	Log(v interface{}) 
	
	// The `Pipe` is not a must-feature
	// because the standard library already provides a pipe function
	// which receives a compatible io.Writer.
	// See here: https://golang.org/pkg/io/#pkg-examples
	// Pipe(writers ...io.Writer)

	      
LoggerMarshalFunc func(v interface{}) ([]byte, error)

func main(){
	app := iris.New()
	app.Logs.Handle(func(log []byte) {
	    fmt.Printf("%s", log)
	})
}

I think we are in a good mood today, this way ensures "low-level" access of logging because we 're working with []byte( as we should if we want to be compatible with the rest of our cloud ecosystem).

Tell me your thoughts about this, please

from iris.

We're ending up to build our own logger service because the rest are not working as we wanted to, this logger service will have different kind of built'n printers, i.e colored printer, logrus (so at the end if you say that logrus do the job for you because of the rest of your structure, then your issue should be solved too). The goal is to be fully compatible with the rest of the existing loggers with an easy way of "binding".

from iris.

Logrus is a popular logging package. Some already use this in their projects, and set it up with Console in dev and JSON writers in production. It would be nice to add the ability to customize Logrus inside of Iris

Logrus is already used inside Iris and you can customize it, app.Logger() returns the logrus.Logger object.

Even better, would be nice to have it's own context.

Yes, in Iris logrus has its own context, it does not make use of the global-package level logger.

from iris.

I understand. Maybe I didn't explain correctly. We have access to the created Logger, but we do not have access to set the Logger defaults, or even better set the logger to the same logger my app uses elsewhere.

For example, here is what I set for Logger in dev, from the way I can see I am not able to do this currently:

		log.SetFormatter(&log.TextFormatter{
			ForceColors:   true,
			FullTimestamp: true,
		})
		log.SetLevel(log.DebugLevel)

from iris.

I did understand but I thought that you talk about its own context, logrus don't have Set functions to set variables to a logrus.Logrus object, so you have to do that with fields as shown below:

	app.Logger().Formatter = &log.TextFormatter{
			ForceColors:   true,
			FullTimestamp: true,
		}
	app.Logger().Level = log.DebugLevel

Logrus can give you the package-level logger by log.StandardLogger() , which returns a logrus.Logger instance.

So you can also do that:

stdLogger := log.StandardLogger()
app.Logger().Formatter = stdLogger.Formatter
app.Logger().Formatter = stdLogger.Formatter

However, you can just set that to the Iris' logger if you want so:

app := iris.New()
app.Logger() = log.StandardLogger()
// rest of your code goes here...

Did these helped you or should we think another, more complicated, way of doing this?

from iris.

@mattrmiller Did the last of @hiveminded 's code snippet solved the issue or you're suggesting that we should change iris to make use of the "global" logrus?

from iris.

Neither of those snippets compile. If you look at the handle you get back from Logrus, and the options you have when you initialize Logrus. They are different.

from iris.

Also, while I love Logrus and have used it in all of my projects, it should be noted that the owner is looking for someone to maintain the package going forward as he has had less and less time: sirupsen/logrus#570 (comment)

This highlights my initial concern, which is that users of the library should be able to set the logging, at the very least customize the logging for Iris. Something as simple as a setter for the Logger object is appropriate. But per the code snippet above, you can not set a variable on a function like: Logger().

from iris.

while I love Logrus and have used it in all of my projects, it should be noted that the owner is looking for someone to maintain the package...

You propose to accept a generic way of logging like an interface, Iris had a simple io.Writer as its logger interface before V8, do you think that was the best solution if not could you please suggest something that will suite you for future use?

But per the code snippet above, you can not set a variable on a function like: Logger().

Yes, but app.Logger() returns a pointer, so you can try something like this:

l := app.Logger()
l = logrus.StandardLogger()

from iris.

You propose to accept a generic way of logging like an interface, Iris had a simple io.Writer as its logger interface before V8, do you think that was the best solution if not could you please suggest something that will suite you for future use?

You already have a Logger() function, just make a SetLogger(logger *log.Logger) function, that way, users who already use Logrus, and have it initialized inside their application can have Iris use the same logger, that is already configured.

Yes, but app.Logger() returns a pointer, so you can try something like this:

Yes, I can get an instance of Iris's logger, but that does not accomplish what I was proposing is a problem... that I have no way to setup Logrus inside of Iris. You do not expose it, and you give no way to set it.

from iris.

As for my first recommendations, you've right it doesn't compile in go 1.8 because we have vendored the logrus package, so ignore them.

Yes, I can get an instance of Iris's logger, but that does not accomplish what I was proposing is a problem...

It was a design decision: to reduce the exported functions that could do the job via geters, as they return a pointer to something.

Just make a SetLogger(logger *log.Logger) function

This sounds an easy task, if that was the case here I could just code it and resolve the issue but this will not work, because as I described on my first sentence, the *log.Logger of yours is different than Iris' when using go1.8: because of the vendor folder(it can be fixed in go1.9 but we want compatibility with previous go versions too).

Based on your comments I read about logrus I think that we should follow a different aspect here.

Ideas

1. no api or logger breaking changes: remove logrus from vendor folder, this will solve the issue with the above code-snippets we posted.
   1.1 add the SetLogger as you proposed, keep the rest of the logger API as remains.
   1.2 problems of this implementation is that iris will need to go get the logrus package and we should avoid these things(the whole framework is copy-paste-able today). As you informed me, the logrus package would be quite unstable, so the whole 1. chapter is not a solution that I want to proceed with.

2. accept a generic logger interface, similarly to logrus' provided functions, at a new SetLogger function
   2.2 and default it to the same logrus Logger we have today (this will cause the same problems described at 1.2)
   2.3 or default to a custom logger that will have the same defaulted output but this will cause a breaking change to apps that depends on that app.Logger or its default behaviour/output.

3. same as 2.0, accept a generic interface... but code some useful iris#Configurators that will set the logger to a specific logger (logrus, zap, standard log.Logger...)
   3.1 or a single Configuration that will receive a logger interface, and will set that to the app's logger
   3.1 problem of 3.0: if these Configurations are not receiving a generic interface then they should be on a different repository (in order to not cause the same problems we talked about)
   3.2 problems of 3.0 and 3.1 API change, the end-developers will have to import a package based on the logger they want to use and pass to the app.Configure(loggerConfiguration) or app.Run(..., loggerConfiguration) or app.SetLogger.

The only thing that we know now is that we have to remove the dependency of logrus.Logger at any case, as I did before v8 (we had a simple io.Writer as the logger interface) but I need your point of view, what do you suggest to do now?

from iris.

I agree. 1, seems unsuitable as we dig in more.

2 & 3) I like, use an internal logging mechanism or library, but have the ability to customize it and/or shut it off. It should not be assumed that the end user will use this logger as theirs. Example) the reason I always establish my logger myself in my package, is that my projects run inside of docker, and follow 12 factor; where by they are configured by env variables, and in production my logs are JSON payloads. I run a cron library along side my Api, so my Api/Iris is not just Iris.. it is a working, living application.

One thing that always comes to mind when continuing to find the perfect Api http router, is maybe treating logging inside Iris, like middleware/callbacks/error codes. Have an OnLogError method along with Info/Warn/etc... that Iris uses internally, whatever logging they want. But the user has the ability to intercept these and pipe them to their normal logging output. If you did this along side the ability to customize the logger, then it would accommodate both sides of the fence: 1) I want to use and customize the logger inside of Iris 2) I want to shut off the logger inside of Iris 3) I want to intercept logging inside of Iris, and pipe them to my own logging framework.

On a final note, TJ Holowaychuk has a nice library that is pretty much drop in for logrus, and knowing TJ it will be well maintained. It also is a lot more performant than logrus. https://medium.com/@tjholowaychuk/apex-log-e8d9627f4a9a#.rav8yhkud

from iris.

We agree, that's nice. Your whole suggestion was already implemented on iris.v6 via the old adaptors feature/logger policy but this design had some issues because go developers didn't seem to be ready to use so generic things, they did ask questions like 'how to I map the logger with a file', 'why logger is an io.Writer' (keep note that the logger policy was just an io.Writer which had shortcuts like log := NewDefaultLogger() which returned a func(string) [the pipe you described] and others methods like .ToStdLogger() which converted the io.Writer logger to a standard log.Logger package) , general: they found this implementation hard-to-use, so we've changed it to a simply logrus.Logger` instance (the mistake we pay now).

I've seen the TJ's logger implementation, it looks promising but think of the possibility that two years from now, we will discuss the same problems as we do for logrus now...

We need something that will be familiar with the majority of the end-developers but in the same time can be useful for cloud providers(input/output pipe) and any other customization

• Iris is using the logger to log the startup information
• Iris never panics, at serve-time the logger is used only to log critical errors, with that in mind: do we really need logger levels? or we should create a function that will accept int type of a level that the end-developers can work with the rest of the application(we had this on iris v6 too)?
• Do we need a logger at all? Yes: All iris' functions return an error too but then the problem from end-developers' perspective is that an error maybe caused but not being logged because they forgot/or don't know that they had to check the returning error. This caused unnecessary code written by users, so a logger was a must-feature.

from iris.

All fair points, I definitely think a logger is necessary inside of Iris. I just want to be able to match the logging I use, but I know this is difficult as the many flavors of loggers out there. You guys do a nice job with template engines, but I am in no way suggesting doing the same for loggers.

I think you are correct, really, if anything Iris needs to log some sort of Panic, and may not need levels at all. While I understand end-users complaints that they have to handle errors and logging themselves... that is really the standard in Go, and the "Go way" so I am disappointed to see excellent libraries, like Iris, get down a path because engineers are coming over to Go, and Go takes some liberties in stating how things will be done that do not match the languages and way they are used to developing... errors being one of them. That soapbox aside, I know you have an obligation to end users. I agree with your statement:

We need something that will be familiar with the majority of the end-developers but in the same time can be useful for cloud providers(input/output pipe) and any other customization

I like logrus, and even though the maintainer is looking to offshore it to someone, I think it has a long life ahead of it... as I said I am still using it in all my projects. For me, unless I can match Iris's logging to the rest of my application, I will miss out on some crucial logging, and in production I will be blind to them because they will not be in JSON payloads that my docker cluster understands and can parse and aggregate.

I appreciate the history, I will continue to think of solutions; personally, my 2 cents it sounds like you had it right on v6... that would be ideal for any real world usage I have seen, running this in production and having worked with a lot of Go Api's. You guys have a great library here, and I plan to pitch in where I can.

from iris.

note 1 :

CanHandle(log []byte) true can be changed to CanHandle(v interface{}) bool which can run even before the Marshal, to save time if the end-developer's needs don't need to marshal a log at all

from iris.

I like this approach, I feel it handles the 3 cases stated above very well; and provides the flexibility stated in all discussions here today.

from iris.

@mattrmiller See the first pure implementation (without reader, writer and closer yet) but I am thinking if that we can make it to "adapt" a second service inside an existing logger service to, for example, handle a specific log which (this adapted logger service) will have the same behavior with events and able to interrupt logs.

package main

import (
	"io"
)

type (
	CanMarshalFunc func(interface{}) bool
	MarshalFunc    func(v interface{}) ([]byte, error)
        //can handle callers can change the result of the log or return a nil to cancel the logging
        // or just return the same "log", true
	CanHandleFunc  func(log []byte) (modifiedOrNil []byte)
	Handler        func(log []byte)
)

type Service struct {
	// these three will complete the interface of the:
	// https://golang.org/pkg/io/#ReadWriteCloser
	// in order to make possible to use everything inside the `io` package.
	// i.e
	// https://golang.org/pkg/io/#example_MultiWriter
	// https://golang.org/pkg/io/#example_TeeReader (piping)
	io.Reader // exported, can be used by end-developer
	io.Writer // >> >>
	io.Closer // >> >>

	canMarshal CanMarshalFunc // multi by wrapping
	canHandle  CanHandleFunc  // multi by wrapping
	handlers   []Handler      // but slice here

	Marshal MarshalFunc // exported, can be used or changed by end-developer
	// NOTE:
	// we could omit that and use a new function to marshal, i.e
	// Marshal(marshalFunc func(v interface{}) (log []byte, this_Marshaler_worked_or_continue_to_the_next_marshaller bool))
/* but this will cause the marshalers to not be compatible with std, i.e the `encoding/json`  */
}

func (s *Service) Read(p []byte) (n int, err error) {
	return
}

func (s *Service) Write(p []byte) (n int, err error) {
	return
}

func (s *Service) Close() error {
	return nil
}

func (s *Service) CanMarshal(cb CanMarshalFunc) {
	if s.canMarshal == nil {
		s.canMarshal = cb
		return
	}

	oldCb := s.canMarshal
	newCb := cb

	// false on first failure
	s.canMarshal = func(v interface{}) bool {
		can := oldCb(v)
		if can {
			return newCb(v)
		}

		return can
	}
}

func (s *Service) CanHandle(cb CanHandleFunc) {
	if s.canHandle == nil {
		s.canHandle = cb
		return
	}

	oldCanHandle := s.canHandle
	newCanHandle := cb

	// return the first failure
	s.canHandle = func(log []byte) []byte {
		newLog := oldCanHandle(log)
		if newLog != nil {
			return newCanHandle(newLog)
		}
		return newLog
	}
}

func (s *Service) Handle(h Handler) {
	s.handlers = append(s.handlers, h)
}

// Log -> CanMarshal(v) -> true -> Marshal -> result -> CanHandle(result) -> Write(result) -> Handle(result)
// Handle in the end in order to be able to start go routines to use this log else where.
func (s *Service) Log(v interface{}) {
	if s.canMarshal(v) {
		log, err := s.Marshal(v)
		if err != nil {
			return // we'll see what we can do with this error
		}
		if newLog := s.canHandle(log); len(newLog) > 0 {
			for _, h := range s.handlers {
				h(newLog)
			}
		}
	}
}

Or it's too much for these type of logging services we're talking about?

Update: I'll be AFK for the next hours, please write your ideas, implementations, end-developer API code-snippets that you would like to use with iris'logger and any type of comments below, I'll read them carefully later on and I'll respond, thank you for your interest and your time!

from iris.

My implementation so far:

package main

import (
	"bytes"
	"errors"
	"io"
	"io/ioutil"
	"sync"
)

type (
	MarshalFunc  func(v interface{}) ([]byte, error)
	HijackerFunc func(log []byte) (modifiedOrNil []byte)
	HandlerFunc  func(log []byte)
)

type Service struct {
	// these three will complete the interface of the:
	// https://golang.org/pkg/io/#ReadWriteCloser
	// in order to make possible to use everything inside the `io` package.
	// i.e
	// https://golang.org/pkg/io/#example_MultiWriter
	// https://golang.org/pkg/io/#example_TeeReader (piping)
	io.Reader // exported, can be used by end-developer for the above or to change the default buffer.
	io.Writer // >> >>
	io.Closer // >> >>

	hijack   HijackerFunc  // multi by wrapping
	handlers []HandlerFunc // slice here
	marshal  MarshalFunc
	// can change via `SetPrinter` or `AddPrinter` with mutex.
	// whenever a tool needs an `io.Writer` to do something
	// end-developers can pass this `Printer`.
	Printer io.Writer
	mu      sync.Mutex
}

var ErrMarshalNotResponsible = errors.New("this marshaler is not responsible for this type of data")
var ErrMarshalNotFound = errors.New("no marshaler found for this type of data, marshal failed")
var ErrSkipped = errors.New("skipped")

func textMarshal() MarshalFunc {
	return func(v interface{}) ([]byte, error) {
		if s, ok := v.(string); ok {
			return []byte(s), nil
		}
		return nil, ErrMarshalNotResponsible
	}

}

type noOp struct{}

func (w *noOp) Write(b []byte) (n int, err error) {
	// return the actual length in order to `AddPrinter(...)` to be work with io.MultiWriter
	return len(b), nil
}

func NoOp() io.Writer {
	return &noOp{}
}

type noOpCloser struct{}

func (c *noOpCloser) Close() error {
	return nil
}

func NoOpCloser() io.Closer {
	return &noOpCloser{}
}

func NewService(printer io.Writer) *Service {
	if printer == nil {
		printer = NoOp()
	}

	buf := &bytes.Buffer{}

	s := &Service{
		Printer: printer,
		Reader:  buf,
		Writer:  buf,
		Closer:  NoOpCloser(),
		marshal: textMarshal(),
	}
	s.Closer = s
	return s
}

func (s *Service) Marshal(marshaler func(v interface{}) ([]byte, error)) {
	s.mu.Lock()
	defer s.mu.Unlock()

	if s.marshal == nil {
		s.marshal = marshaler
		return
	}

	oldM := s.marshal
	newM := marshaler

	// false on first failure
	s.marshal = func(v interface{}) ([]byte, error) {
		b, err := oldM(v)

		// check if we can continue to the next marshal func
		if err != nil && err.Error() == ErrMarshalNotResponsible.Error() {
			return newM(v)
		}

		// if no data return but err is nil, then something went wrong
		if len(b) <= 0 && err == nil {
			return b, ErrMarshalNotFound
		}

		return b, err
	}
}

func (s *Service) Hijack(cb func(log []byte) []byte) {
	s.mu.Lock()
	defer s.mu.Unlock()

	if s.hijack == nil {
		s.hijack = cb
		return
	}

	oldCb := s.hijack
	newCb := cb

	// return the first failure
	s.hijack = func(log []byte) []byte {
		newLog := oldCb(log)
		if newLog != nil {
			return newCb(newLog)
		}
		return newLog
	}
}

func (s *Service) AddPrinter(writers ...io.Writer) {
	l := []io.Writer{s.Printer}
	w := io.MultiWriter(append(l, writers...)...)

	s.mu.Lock()
	s.Printer = w
	s.mu.Unlock()
}

func (s *Service) SetPrinter(writers ...io.Writer) {
	var w io.Writer
	if l := len(writers); l == 0 {
		return
	} else if l == 1 {
		w = writers[0]
	} else {
		w = io.MultiWriter(writers...)
	}

	s.mu.Lock()
	s.Printer = w
	s.mu.Unlock()
}

// Print -> Store[Marshal -> err != nil && result -> Hijack(result) -> Write(result)] -> Flush[Printer.Write(buf) and Handle(buf)]
func (s *Service) Print(v interface{}) {
	n, err := s.Store(v)
	if err != nil || n <= 0 {
		return
	}
	s.Flush()
}

func (s *Service) Store(v interface{}) (int, error) {
	// no locks here, will reduce performance
	// when we supposed to be in a state that all fields are passed to the logger.
	if s.marshal == nil {
		return -1, ErrMarshalNotFound
	}

	b, err := s.marshal(v)
	if err != nil {
		return -1, err
	}

	if hijack := s.hijack; hijack != nil {
		b = hijack(b)
		if len(b) == 0 {
			return -1, ErrSkipped
		}
	}

	return s.Write(b)
}

func (s *Service) Handle(h func(log []byte)) {
	s.mu.Lock()
	defer s.mu.Unlock()
	s.handlers = append(s.handlers, h)
}

func (s *Service) Flush() error {
	b, err := ioutil.ReadAll(s.Reader) // will consume the contents too
	if err != nil {
		return err
	}

	_, err = s.Printer.Write(b)
	// we don't care if printer has errors, handlers should be executed
	for _, h := range s.handlers {
		h(b)
	}

	return err
}

and a program for showcase:

package main

import (
	"encoding/json"
	"fmt"
	"os"
	"time"
)

const delay time.Duration = 1 * time.Second
const times = 3

func main() {
	s := NewService(NoOp())
	// the NoOp we gave
	// will print nothing.
	// so it will print once at the console(os.Stdout)
	s.AddPrinter(os.Stdout)

	s.Handle(func(l []byte) {
		fmt.Printf("this should be called AFTER print:\n%s\n", l)
	})

	// s := NewService(os.Stdout)
	// will log two times, one on the default os.Stdout and secondly to the os.Stderr given here
	// s.AddPrinter(os.Stderr)

	print(s, true)

	fmt.Printf("testing store and flush after %.2f seconds\n", delay.Seconds()*times)
	print(s, false)
	s.Flush()

	fmt.Println("testing json")
	// add the standard json marshaler
	s.Marshal(json.Marshal)

	// add a hijacker to add a new line after the json struct printed
	newLine := []byte("\n")
	s.Hijack(func(log []byte) []byte {
		return append(log, newLine...)
	})

	printJSON(s, true)

	fmt.Printf("testing store and flush json struct contents after %.2f seconds\n", delay.Seconds()*times)
	printJSON(s, false)
	s.Flush()
}

func print(s *Service, flush bool) {
	i := 1
	for range time.Tick(delay) {
		msg := fmt.Sprintf("[%d] We've logged: %d\n", i, time.Now().Second())
		if flush {
			s.Print(msg)
		} else {
			s.Store(msg)
		}

		if i == times {
			break
		}
		i++
	}
}

func printJSON(s *Service, flush bool) {
	var msg = struct {
		Order int `json:"order"`
		// remember: should be exported
		Time    string `json:"time"`
		Message string `json:"message"`
	}{}

	i := 1
	for range time.Tick(delay) {

		msg.Order = i
		msg.Time = time.Now().Format("2006/01/02 - 15:04:05")
		msg.Message = fmt.Sprintf("[%d] We've logged: %d", i, time.Now().Second())

		if flush {
			s.Print(msg)
		} else {
			s.Store(msg)
		}

		if i == times {
			break
		}
		i++
	}
}

from iris.

This looks good, excited to see how it get's integrated in.

from iris.

@mattrmiller we can also make use of the build tags i.e go build -tags=logrus and your program will run the default logrus logger you may define somewhere in your app, do you like that idea or this kind of behavior should be controlled by the end-developer's manual calls to iris logger service?

from iris.

I would leave it to the developer to over-ride what he/she wants, and pipe it to wherever they want. The alternative would be opening the flood gates for "please support 'X' logger".

from iris.

@kataras the preview you provided looks good to me, but this will take some time to be adapted here.

As I was the person who added the logrus to the vendor(the mistake that produces the issue title) I'm taking the opportunity to remove this vendored dependency so @mattrmiller can upgrade and attach his logrus instance with the iris' one (as a temporary solution)

from iris.

OK folks,

I did create two packages to solve this issue, one is pio and the other is the golog.

golog is being used inside Iris now, pio is the low-level printer of the golog's Logger, which can be used anywhere else too.

The new app.Logger() *golog.Logger can be compatible with external loggers too, i.e for Logrus app.Logger().Install(logrus.StandardLogger())

Read the HISTORY.md entry for more: https://github.com/kataras/iris/blob/master/HISTORY.md#we-26-july-2017--v810

from iris.