Built-in log Package

[dc0d]

Many packages use the built-in log package. It could log data with help from it's type. If we could set the output of the logger to something other than io.Writer, like:

type Output interface {
    Printf(format string, vset ...interface{})
    Flags() (flag int)
    Prefix() (prefix string)
    SetFlags(flag int)
    SetPrefix(prefix string)
}

Then, inside the output handler we could perform proper actions for logging the data. Usual informative data would just get logged, and error would get logged as error - as it should be. logger.Error(err) looks unnecessary redundant to me (as in leveled loggers). If it's an error, it's an error.

We could even have other types/interfaces that we could take proper action based on their type/interface much more flexible than just having 5 or 7 or 10 levels.

This package demonstrates this idea. All data gets logged as info and if it is/contains error, it gets logged as error (hence, two levels). Most functions from standard log package are implemented.

[Axel Wagner]

I'd consider it quite sensible to log an error *and* handle it (e.g. by retrying). In that case, I wouldn't want it to appear with error-severity in my log - it might be an error string, but it's not an error condition. Only after bailing on handling an error should it stand out in an error log. So I don't really agree with that approach, fine as it is.

Just my 2¢.

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[dc0d]

That may be (still IMH-Experience in the majority of cases, this is the proper default to go).

But the main concern to express here is, the default logger should accept an interface like Output instead of io.Writer. That way any necessary mechanism can be added without touching the log package, which is used in many packages.

Best would be if it could just accept the same logger interface as the destination.

And if the log package is going to change to support leveled logging (or another package is going to be added for this purpose), it's the best if the destination could accept object themselves, not a byte slice ([]byte).

To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.

[Peter Mogensen]

On 2017-08-14 11:04, dc0d wrote:
> That may be (still IMH-Experience in the majority of cases, this is the
> proper default to go).
>
> But the main concern to express here is, the default logger should

> accept an interface like /Output/ instead of /io.Writer/.

I would agree, if not for the fact that there seem to be very little
consensus on exactly what such an interface should look like.

systemd support a very simple (but useful) interface for leveled
logging. Just prefix what you write to stdout or stderr with "<X>" where
X is the syslog log-level. Systemd takes care of anything else.
Exactly this is pretty much impossible to do efficiently with many
log-packages, including the stdlib "log".

/Peter

[dc0d]

Some packages tried that approach, adding levels as prefixes (which I prefer to defining methods). But did not get enough attention.

Whatever approach that may get chosen for a logging package, the logger struct should implement some Logger interface and should accept an instance of another object which also implements the Logger interface.

This way it will be possible to not only handle the log entries at lower layers but also to have a hierarchy of loggers to the top (where logging is happening) which can behave differently based on the (conceptual) context - choosing the formatters, the destinations or notifying another system.

And levels could be expanded to tags. A tagged entry can be processed based on its tags (including a concept like level) - but it seems (sadly) that levels are more wide-spread than just being a tag.

That sort of interface, is what I would like to see. And you are right about that there is no conclusive agreement on what it should like.

Another question that I failed to answer properly (by myself) is: are metrics same as logs? Or they are a higher level concept (which also can be logged)? And should logging be in charge of delivering metrics (seems it can be)?

[Sam Vilain]

The main problem with the Printf-style interface is that it's not worth building real applications with.  For anything with non-trivial logging needs, you need:

* tagging of log lines with identifiers such as PID, host, request ID, etc

* structured for easier downstream analysis by tools like the ELK stack and common commercial systems like splunk

What I've had to do to achieve this is to pass an alternate writer to the "standard log" interface expected by various libraries (eg, Sarama) and add PID and host tagging to that.   Writing things in terms of "prefix" represents a very limited view of log correlation; it worked for syslog perhaps but the world has moved on.  Log levels are also mostly useless.

The right API to me is probably somewhere between logrus and Uber's zap.  These systems are in more widespread use with a different set of priorities, and it would be good to be able to plug into those (and see also my context suggestion which could let these libraries automatically connect with a configured logger)

Sam

--

You received this message because you are subscribed to the Google Groups "golang-nuts" group.

To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.

[Peter Mogensen]

On 2017-08-14 18:36, dc0d wrote:
> Another question that I failed to answer properly (by myself) is: are
> metrics same as logs? Or they are a higher level concept (which also can
> be logged)? And should logging be in charge of delivering metrics (seems
> it can be)?

Depends... I guess.
I implemented both (in https://github.com/One-com/gone/) and the
strategies are somewhat different. Mostly due to performance requirements.
For instance.. metrics are often something you would be more likely to
call in a hot path than logging (which is mostly errors). And I think
it's sad to have a fine metrics library which you tend to not use in the
places which could be really interesting only because it's too expensive.
For error-logging you are mostly not concerned with performance,
however, debug-logging is somewhat like metrics in that regard. You
don't want to discourage it because your debug-log call is really
expensive. For debug-logging that could however be solved with a compile
time switch as many logging libraries do.

/Peter

[Chris Hines]

I would be curious what you think of github.com/go-kit/kit/log (and related "sub"-packages). See my talk about it's design here:

Video: https://youtu.be/ojhFQNgyZO4?list=FLcxNiie7-UD8znndwDn7PFw

Slides: https://speakerdeck.com/chrishines/go-kit-log-package

Chris

To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.

[Sam Vilain]

On 8/15/17 7:14 AM, Chris Hines wrote:

I would be curious what you think of github.com/go-kit/kit/log (and related "sub"-packages). See my talk about it's design here:

Video: https://youtu.be/ojhFQNgyZO4?list=FLcxNiie7-UD8znndwDn7PFw

Slides: https://speakerdeck.com/chrishines/go-kit-log-package

I can see what you're going for with that, and in a way it's demonstrating some sugar issues in go.  For some reason, folk expect to be able to write logging statements without an awful lot of unsightly brackets and constructors :-).

To quickly round them up, this module uses what I consider to be Perl 5-esque "slurpy hashes":

// Unstructured
log.Printf("HTTP server listening on %s", addr)

// Structured
logger.Log("transport", "HTTP", "addr", addr, "msg", "listening")

Whereas logrus steers you towards a map[string]interface{}:

func main() {
  log.WithFields(log.Fields{
    "animal": "walrus",
  }).Info("A walrus appears")
}

And zap uses type-safe individual field constructors:

logger.Info("failed to fetch URL",
  // Structured context as strongly typed Field values.
  zap.String("url", url),
  zap.Int("attempt", 3),
  zap.Duration("backoff", time.Second),
)

Of these, I lean towards the zap style because it's not significantly more verbose (IMHO), it's more type safe, and faster.

However, the syntax sugar issue has meant that zap now also have a similar interface to kit:

sugar := logger.Sugar()
sugar.Infow("failed to fetch URL",
  // Structured context as loosely typed key-value pairs.
  "url", url,
  "attempt", 3,
  "backoff", time.Second,
)

One common element is the ability to create a logger with tags pre-built:

// kit	
logger = log.With(logger, "instance_id", 123)

// logrus
logger = logrus.WithFields(logrus.Fields{"instance_id": 123})

// zap
logger = logger.With(zap.Int("instance_id", 123))

IMHO appropriate use of this feature is critical to sane log analysis as soon as your app gets non-trivial: distributed, sharded, microservices, async, etc - non-linear, multiuser and multicore: it can simply save you down the track if you tag the request ID, customer ID, and particularly the value of a loop variable for log statements inside inner loops.

So I guess, what I found was that once I did that using zap, I really don't care that much about the syntax sugar.  I would write things like:

for i, v := range arr {
   logger := logger.With(zap.Int("itemIdx", i))

   if err := v.Process(); err != nil {
       logger.Error("failed to process", zap.Object("error", err))
   }
}

And so the individual log statements don't go over the magic length at which blub programmers scoff, turn up their noses and say, "see, this is why go is so much worse than blub".  It's also a good abstraction.  And did I mention it's fast?  I really like the way that it never combines the log line into something heavy like a map[string]interface{}, and that it just logs its fields in the order they were passed - so it's more like a traditional log line, just with JSON boundaries.

So anyway, yeah that's where I stand on that API - I can see how you got there, and I watched a structured logging talk at GopherCon 2016 which set me down this path, but after investigation I just couldn't trade performance, memory efficiency and a good abstraction for a little syntax sugar.

I'm not quite sure what the language or stdlib could do to make this better, other than shipping something like zap in stdlib.  It's never really appropriate to use anything other than stdlib logging to log with in a library, and that's the nub of the problem: it means libraries will pretty much always have unstructured logging.  The best you can do is to log each "printf" argument to its own field, but that's not a very good answer especially with the "message" is "%s: %s %s" or something.

Sam

[Chris Hines]

Thanks for your thoughtful response. I agree with many of your points, especially the benefits of structured logging, both on the usefulness of the logs and the flow of the code as it builds the logging context. I have a few comments on some of your points:

> Of these, I lean towards the zap style because it's not significantly more verbose (IMHO), it's more type safe, and faster.

The price of the zap API is that any package that doesn't use the sugared API becomes coupled to the zap and zapcore packages. The closest thing it provides to a fundamental interface is zapcore.Encoder which requires arguments of their concrete types `zapcore.Entry` and `zapcore.Field`. Another strike against zap, IMHO, is the sheer size of it's API. It also seems to me that customizing it's behavior would be a non-trivial exercise.

> I really like the way that it [zap] never combines the log line into something heavy like a map[string]interface{}, and that it just logs its fields in the order they were passed - so it's more like a traditional log line, just with JSON boundaries.

I agree and go-kit/log is the same as zap in this regard. It is true that go-kit/log currently implements JSON logging by converting to a map and using enconding/json to serialize the result. That is the simplest implementation, but it is not required by the go-kit/log.Logger interface and I am currently working on a new implementation that serializes to JSON directly from a keyvals slice. When complete, this will provide a significant performance improvement, bringing the speed of JSON output on par with the speed of logfmt output.

> It's never really appropriate to use anything other than stdlib logging to log with in a library, and that's the nub of the problem: it means libraries will pretty much always have unstructured logging.

As I explained at the end of my talk, I don't think it is appropriate for public libraries to log at all. My rationale is much broader than simply structured vs. unstructured, or stdlib vs. pick your logger. My rationale is that once a library chooses to log it has taken that choice away from the application it is eventually used by and public libraries harm their reusability by doing so. Logging is an application concern.

If a public library does choose to log, it should do so by a simple interface that isn't coupled to anything outside the package itself, the language, or the standard library; preferably a locally defined interface. Note that the go-kit/log.Logger interface meets this goal. Any package can copy that interface into its API and be compatible with go-kit/log style loggers without any external dependencies.

Non-public libraries have more leeway because, presumably, the library is closely related to a small set of applications that have common logging needs or the library is owned by an organization that has dictated a standard logging package. That said, designing private libraries as if they were public libraries could be a good idea in the long run.

Chris

[Tamás Gulácsi]

Even better: my libraries expose only the LogFunc: i.e.
var Log = func(keyvals ...interface{}) error { return nil}

Which is easy to override with any logger, is not tied to go-kit/log, but provides structured logging!

[dc0d]

Even better: my libraries expose only the LogFunc: i.e.

I am currently doing something similar; exposing an interface with four methods Error, Info, Errorf, Infof with a default logger that uses the built-in log, setup at init.

Yet IMHO there is a need for a built-in package that allows to change the source and works with objects, instead of byte slices.

[Peter Mogensen]

... or exposing some lib.SetLogger(...) function.

But preferably, one should try not to log from libraries and return
errors instead and leave logging to the application - if possible.

There's few things more annoying than libraries spitting something out
where you least need it.

/Peter

[dc0d]

As they say global variables/things are bad. But I even use a global Context and WaitGroup for signaling the termination of the whole program. On exit the context will get canceled and the program waits for the WaitGroup with a timeout. I would like to have those inside another built-in package.

There are many cases (/packages) that one can not pass the Context (and the WaitGroup) to each and every goroutine. It's possible to define a struct and use it as a closure for those functions(now methods). But one has to rewrite the whole interface to a package.

Forcing the function signature everywhere is not a practice/pattern anymore (hint: if it was not forced to be everywhere, it was a pattern). It's something else.

[Henrik Johansson]

Sorry to but in but what happened to the whole logging initiative that was on going?

Did I miss something about that? It seems very related to this.

--

[dc0d]

Logging from a specific place in code helps with finding out where the error happened. And doing that manually is cumbersome. I for one can not give-up on this because it makes fixing things super fast.

Fortunately current logging packages (like zap) take care of that case by providing the option to register them as the output for the standard log package - all at info level.

[dc0d]

Henrik,

Here I've tried to put a sample (other than the built-in log package) for cases that global stuff makes things more clear and pragmatic (IMHO).

[Peter Mogensen]

On 2017-08-17 09:24, dc0d wrote:
> Logging from a specific place in code helps with finding out /where/ the

> error happened. And doing that manually is cumbersome. I for one can not
> give-up on this because it makes fixing things super fast.

github.com/pkg/errors

...solves many of those problems w/o logging inside the libray.
That's not to say that there are not situations were you really really
want to log a message inside a library, but it can be kept to a minimum.

/Peter

[dc0d]

That's a nice package with good design (and I've used it for a while). But I loose the info about where the error is happening.

[Christian Joergensen]

On Thursday, August 17, 2017 at 11:40:08 AM UTC+2, dc0d wrote:

That's a nice package with good design (and I've used it for a while). But I loose the info about where the error is happening.

What do you mean by where the error is happening?

Have you checked out http://godoc.org/github.com/pkg/errors#hdr-Retrieving_the_stack_trace_of_an_error_or_wrapper 

Cheers,

Christian

[dc0d]

Christian,

By where I mean package/file.go:lineNumber which I have a helper method for that:

//-----------------------------------------------------------------------------

var (
    errNotAvailable = errors.New("N/A")
)

// Here .
func Here(skip ...int) (funcName, fileName string, fileLine int, callerErr error) {
    sk := 1
    if len(skip) > 0 && skip[0] > 1 {
        sk = skip[0]
    }
    var pc uintptr
    var ok bool
    pc, fileName, fileLine, ok = runtime.Caller(sk)
    if !ok {
        callerErr = errNotAvailable
        return
    }
    fn := runtime.FuncForPC(pc)
    name := fn.Name()
    ix := strings.LastIndex(name, ".")
    if ix > 0 && (ix+1) < len(name) {
        name = name[ix+1:]
    }
    funcName = name
    nd, nf := filepath.Split(fileName)
    fileName = filepath.Join(filepath.Base(nd), nf)
    return
}

//-----------------------------------------------------------------------------

I do not know if it's the best in the class though!

I like the approach that package took to keep track of the source error. But never have take a look to those interfaces. And that's my point. There is something wrong with being forced to adapt every single package to your underlying logger, just to provide logging.

And going back to the my initial concern: There is a need for an interface for a logger (whatever it should look like) and the standard log package should be able to consume that interface (instead of io.Writer).

[Chris Hines]

On Thursday, August 17, 2017 at 3:14:09 AM UTC-4, Henrik Johansson wrote:

Sorry to but in but what happened to the whole logging initiative that was on going?

Did I miss something about that? It seems very related to this.

That discussion took place in this thread: https://groups.google.com/forum/#!topic/golang-dev/F3l9Iz1JX4g

Some proposals were drafted (links to them are in the above thread). Proposal authors also had two conference calls to discuss and share ideas and opinions. Notes from those meetings were recorded in these two documents:

https://docs.google.com/document/d/1hovWbs19GvzfYDd-2RSYw4GN3h4vkbPUj_qO5cZa1uU/edit?usp=sharing

https://docs.google.com/document/d/1IOaEPwmVZrvlCg5anWI0UC9yaZmihSiMvu6-471f8KY/edit?usp=sharing

I don't know if the last two links will work for everyone because of permissions on the docs. I don't own the docs, so I cannot change the permissions. I will try to get the owner to open the permissions for viewing.

The general consensus (as I perceived it) was that logging use cases are too diverse to make a standard interface that satisfies a wide enough range. The group felt that persuading the community to treat logging as an application concern and that libraries should return errors or provide hooks rather than log directly. The last several slides of my talk (linked to earlier in the thread) was my attempt to persuade/educate along those lines.

Chris

[Henrik Johansson]

Thx Chris, that's unfortunate it was many years until the Java world settled on something that worked in spite of having a built-in  log package.

This is truly an area where we seem to repeat the mistakes of the past.

--

[Bret Jordan]

I know this thread is old... But for people that are looking for some simple logging by level functionality I have added basic logging levels to the default Go log package.  You can find my changes here:

https://github.com/gologme/log

In addition to adding Info, Warn, and Debug, users can also define their own arbitrary logging levels.  Also, logging levels are enabled or disabled individually.   So you can enable just Debug logs without getting Info and Warn.  The enabling only impacts the new added logging levels, not the traditional Print and Fatal loggers. 

All of the original functionality still exists and is unchanged. Though, I did enable the ability for users to define the calldepth.