inconshreveable / log15 Goto Github PK

This turns out to be more tricky than one would hope. Best options that I can think of are:

1. Change the Handler interface to pass calldepth through and require every implementing handler to appropriately increment it as it goes through the handler tree.
2. Add another implementation of the Logger interface which includes these parameters in the context. Basically adding a NewSourceInfoLogger call (or something similar).
3. Change the default logger implementation to always take the performance hit (I haven't measured this yet) of doing runtime.Callers and adding those values as fields in the log.Record. An optional handler could be used to inject them into the context.

Relevant thread on go-nuts:
https://groups.google.com/forum/#!topic/golang-nuts/_EdGGCwY1AI

I think it would be nice to have a convenience method that called log.Crit() followed by an implicit os.Exit(1). Most often, when I fire a Crit it is truly critical and I want to bail. Any chance of this?

Feedback from the mailing list:

A "stack trace" can be useful sometimes. What about adding a special "stack" key to the log functions (or better, a logger.XxxStack functions) which store the callers in the context.'

It's a difficult API design problem:

• Adding new XxxStack functions is too onerous on the API.
• A simple handler can't just add them because it would end up generating the stack from within the handler tree.
• Maybe a handler could add them but it would have to do something smart where it walks up the captured stack frames and removes each frame until it reaches the caller of a Logger interface method.

Most likely, the best option is that this should be a new top-level function that you would use as a context value that we would know how to format nicely for you:

logger.Error("something went horribly wrong", "stack", log.Stack())

Note that it wouldn't work well with log.Lazy though (you'd end up with frames from the handler tree in the traceback).

How is it formatted as output? Newline escaping will produce an unreadable mess when looking at log files or on the terminal. grohl does something interesting where it splits the
stack into multiple log messages which is interesting to consider:

t=12412323 lvl=error stack=First line of stack trace
t=12412323 lvl=error stack=Second line of stack trace
t=12412323 lvl=error stack=Third line of stack trace

Maybe this format could just be used for the TerminalFormat.

This issue originates from #44 where an external dependency (go-loggly) did buffering of log messages.

One of the key features of log15 is the way Handlers connect and create a handling tree. I think properties such as async, buffering (with max buffersize and flush interval) should be handled by a Handler, and the hook to a logging service shouldn't have to implement buffering itself and should just send logs to the logging service.

Now ofcourse the whole purpose of the buffering in go-loggly is so that can send multiple log entries in a single call to loggly. And this is actually very important, especially when working with huge amounts of logs. But buffering and bulk writes are also important in other handlers. For instance, a colleague of mine (@michaelvlaar) found that some of our application spend a huge amount of time in the kernel due to writes to files and os.Stdout. So a more generic approach to buffering and handling of bulk log records seems to be an interesting topic. We brainstormed a bit about it and came up with the following idea:

Add an extra interface type:

type BulkHandler interface{
    LogBulk([]*Record) error
}

Some Handlers such as the LogglyHandler and the FileHandler could implement this interface, taking a slice of logs and sending/writing them all at once, or at least as much as possible/efficient per call/write. For instance: Loggly's bulk endpoint states "You can send a maximum of 5MB per batch and up to 1MB per event", so the LogglyHandler will need to take care of that.

Then a new Handler would be added:

type bufferedBulkHandler struct {
    buffer []*Record
    handler Handler
    bufferSize int // buffer is this size large, and will be flushed when it's full
    flushInterval time.Duration
    forceFlushLevel Level // buffer is flushed directly (while blocking the logging call) after a message with this level (or higher) is added.
}

func BufferedBulkHander(size int, interval time.Duration, forceFlushLevel Level, handler Handler) Handler

The ForceFlushLevel is actually quite important, there's a good chance a program is crashing when a log with LvlCrit is added. And you wouldn't want that message to be stuck in the buffer when the program crashes. Normal flushing takes place asynchronously, not directly blocking a Log call.

Maybe in this case (because of the number of options) the BufferedBulkHandler should be an exported type with exported fields, and not a function.

In summary, what I propose is:

• Define the BulkHandler interface
• Add the BufferedBulkHandler (either as func or exported struct)
• Implement LogBulk([] *log15.Record) error for the FileHandler and LogglyHandler, and possibly more.

What I'm not sure about is whether BufferedBulkHandler should accept a Handler as argument, and check with a type assertion if the Handler also happens to implement BulkHandler. Or maybe it should just accept BulkHandler's (it doesn't really make sense to first buffer messages, and then handle them one by one through a normal Handler, or does it?).

Hello,
I didn't find any examples into godoc of log15 for set time with millisecond precision.

Is it possible? if yes, how I can enabled it?

Many thx

I recommend log15 for pgx, a database driver for PostgreSQL. I'm doing only a small amount of logging now. There is a small but measurable performance impact when enabling logging. A 63000ns query becomes 66000ns even when the log is filtered. Some of that is preparing the parameters to be logged, but at least 1000ns is just overhead for the log call. pgx is very focused on performance, so losing 5% even when logging is disabled is unfortunate. I work around it by checking if no logger is provided and skipping the logging call altogether.

Overall though, the performance is acceptable for my current uses. But I'd like to add some low-level, high-volume debug logging. The problem is when the logger is set to filter debug messages even the no-op calls would seriously degrade performance. So I can't add the debug logging because it would negatively impact people who only have logging set to error.

I know it kind of goes against the leveled logger interface, but is there any way to quickly determine if a given level will be discarded? I really need to skip the log call entirely to have acceptable performance. Otherwise, I probably will need to have an extra debug flag in pgx that turns on and off the extra logging.

If that's the solution, that's fine, just thought I'd see if there is a better built-in way.

Hello,
It seems travis-ci is not tracking this repository would it be possible to activate this and add the build status to the readme?

It would be nice if I could specify a series of keys into TerminalFormat so that I could layout the key values in a specific named order like

func TerminalFormat(contextKeys []string, "[%s] [%s] %s %s %-40s %s") log.Format { 

Missing context keys would be passed empty strings, unused context items would be added to the end

BTW noticed the following in format

    // try to justify the log output for short messages
    if len(r.Ctx) > 0 && len(r.Msg) < termMsgJust {
        b.Write(bytes.Repeat([]byte{' '}, termMsgJust-len(r.Msg)))
    }

That could be removed by changing the above format statements to

    if color > 0 {
        fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %-40s ", color, lvl, r.Time.Format(termTimeFormat), r.Msg)
    } else {
        fmt.Fprintf(b, "[%s] [%s] %-40s ", lvl, r.Time.Format(termTimeFormat), r.Msg)
    }

The "%-40s" provides the right pad

This is a great package, the value of the MatchFilterHandler is underated and makes this the perfect tool for module logs. thanks !

I'd like to use epoch time in my log files since I happen to be using epoch time within the server. Is it possible to have this natively supported as opposed to having to make a specific formatter for this? It seems useful in the sense of being able to reuse the existing formatter code versus adding a new formatter to modify only one field.

The stack trimming logic only works correctly when the stack contains the main function.

godoc then shows:

package log15
import "github.com/inconshreveable/log15"

which I believe is incorrect

Currently it's not possible to configure which syslog facility the syslog handler will log from. This means that all logs will be logged from the "kern" facility, since this is the default within the stdlib syslog package. This is confusing, because "kern" should be used for kernel logging only.

I noticed that syslog priority configuration used to be supported in this library, but it was removed in commit 54d74c8. Could you maybe reintroduce this? If not, it might be a good idea to pick a better default.

Here is a rolling file log handler I put together, feel free to use it. The only enhancement you may want to add is the option to delete files after x days or only have so many days of logs, and maybe choose your own format of the date. I can make a PR if you would think its useful

func RollingFile(path,filePrefix,fileSuffix string, fmtr log.Format) (log.Handler) {
    handler := &RollingFileHandler{FilePrefix:filePrefix,FileSuffix:fileSuffix,Path:path,Format:fmtr}
    e:= handler.Create()
    if e!=nil {
        panic("Unable to create logger for " + path +"/"+ filePrefix + fileSuffix)
    }
    return handler
}
type RollingFileHandler struct {
    Stream io.WriteCloser
    FormattedDay string
    Handler log.Handler
    Path,FilePrefix, FileSuffix string
    Format log.Format

}
func (h *RollingFileHandler) Close () error {
    if h.Stream!=nil {
        stream := h.Stream
        h.Stream=nil
        return stream.Close()
    }
    return nil
}
func (h *RollingFileHandler) Create () error {
    h.Close()
    formattedDay :=h.FilePrefix + time.Now().Format("2006-01-02") + h.FileSuffix
    h.FormattedDay = formattedDay
    path:=filepath.Join(h.Path,h.FormattedDay)
    f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
    if err != nil {
        return err
    }
    h.Stream = f
    h.Handler = log.StreamHandler(h.Stream,h.Format)
    return nil
}

func (h *RollingFileHandler) Log (r *log.Record) error {
    // Check the current day to see if the log should be closed
    formattedDay :=h.FilePrefix + time.Now().Format("2006-01-02") + h.FileSuffix
    if formattedDay!=h.FormattedDay || h.Stream==nil{
        err := h.Create()
        if err!=nil {
            return err
        }

    }
    h.Handler.Log(r)
    return nil
}

In a relatively short period of time (may 2014) and only 87 comits, log15 is at v2 already.
In #34 it's mentioned that when it is merged, the version should be bumped to v3.

Maybe it's good to keep a document (e.g.: CHANGELOG.md) that contains the important changes and provides help with migration for breaking changes.

Could we have an ability where we can change the context of a logger? I'm marking a type's attribute on the log, but it can be changed. Rather than recreating the logger every time, I'd like the ability to change a key/value pair on the context.

One thing I miss in log15 is a good way to redact/censor information from the logs.

From https://godoc.org/github.com/op/go-logging#Redactor

type Redactor interface {
    Redacted() interface{}
}

"Redactor is an interface for types that may contain sensitive information (like passwords), which shouldn't be printed to the log. The idea was found in relog as part of the vitness project. "

What are your thoughts about this?
I could implement and PR.

If a package importing "gopkg.in/inconshreveable/log15.v2" imports another package which also uses "gopkg.in/inconshreveable/log15.v2", then any calls to l.SetHandler(...) for any logger will overwrite the handler in all loggers across both of those packages.

The reason is that there's a shared root in the package which always references the same underlying log.Handler even after calling l.New() on it.

Your documentation suggests initializing logging like this:

package yourlib

import "gopkg.in/inconshreveable/log15.v2"

var Log = log.New()

func init() {
    Log.SetHandler(log.DiscardHandler())
}

I tried this method and got burned because both my main package and my library imported "gopkg.in/inconshreveable/log15.v2". Suddenly my logs were gone because the library changed the singular root logger's handler to log.DiscardHandler.

I recommend changing the semantics of log15.New() to do a completely new object without a shared Root at the bottom, while allowing Logger.New() to perform shared state chaining.

Got bit by #16 today. Spent some extra head scratching figuring out why a fixed bug was biting me. gopkg.in/inconshreveable/log15.v2 is checking out the greatest v2 tag or branch. The fix is on branch v2. But there is a v2.2 tag that does not include the fix. So the default import does not include the fix.

Please tag a new version.

Thanks!

We're using log15 behind a wrapper, which means I'd like runtime.Callers to say 4, instead of 3:
https://github.com/inconshreveable/log15/blob/master/logger.go#L110

Is there a way around this?

If not, would this be ok?

 log.Root().SetStackDepth(4)

It's a small change, but it adds a method to the Logger interface, which is a very nice clean interface.

If you pass a typed nil pointer to the context,

Example:

if player is nil

    log.Warn("Remove issue", log.Ctx{"tier": tier, "player": player, "reason": "player does not exist in cache"})

You will get a panic when the struct's auto generated .String is called using a nil pointer.

This will happen here:

format.go:178

func formatShared(value interface{}) interface{} {
        switch v := value.(type) {
    case time.Time:
        return v.Format(timeFormat)

    case error:
        return v.Error()

    case fmt.Stringer:
        return v.String()

    default:
        return v
    }
}

This may be a known issue, but I could see accidentally having nil's sent in. From what I have read, to address this, reflect may be needed which would incur an overhead and may not be desired. I thought I'd open this issue to find out if this is deemed an issue. If not, what the best practices are to work around this.

The log15 docs recommend that library writers expose a Log variable that can be set to a logger. https://godoc.org/gopkg.in/inconshreveable/log15.v2#hdr-Library_Use
I think this is pretty poor practice, actually, because it defeats context loggers which is one of the features of log15 I really like. The recommendation made is better than nothing but there should also be a proper recommendation, which is to embed a logger into the appropriate objects exported by the library so the client can set a logger on a per-request or per-thread of execution basis.

I've been reading the section about error handling and tried to play with some mistyped keys (to see LOG15_ERROR reports), but it didn't work very well.

Here is the code and corresponding output:

log15.Info("one empty error", 1)
// Output:
// t=2015-11-27T19:57:07+0100 lvl=info msg="one empty error" LOG15_ERROR= LOG15_ERROR="Normalized odd number of arguments by adding nil"

log15.Info("empty error", 1, 2)
// Output:  
// t=2015-11-27T19:57:07+0100 lvl=info msg="empty error" LOG15_ERROR=

log15.Info("two empty errors", 1, 2, 3, 4)
// Output:  
// t=2015-11-27T19:57:07+0100 lvl=info msg="two empty errors" LOG15_ERROR= LOG15_ERROR=

First off, great stuff. I'm glad you put the time in to build such a great log library.

I was wondering, though, would it be possible to make the time, level, and message keys configurable? Does that seem reasonable?

https://github.com/inconshreveable/log15/blob/master/format.go#L77
https://github.com/inconshreveable/log15/blob/master/format.go#L121

I think that would allow for better integration into systems that are expecting different keys for those values.

Thanks!

In #43 @inconshreveable wrote:

A separate conversation should probably go into whether the ext package even makes sense and should continue to exist in v3.

Until recently I thought ext was just a folder containing packages for external logging systems, as that is mentioned in #5. I think that does make sense to avoid an eventually huge number of logging-service related packages in the project root.

However, for extra handlers such as the ext.EscalateErrHandler and ext.HotSwapHandler, I think normal sub-packages would be better. And I think extra Handlers are only required to be in a sub-package when one or more of the following is true:

• depends on a third-party package
• compiles with cgo
• imports unsafe (?)
• a large amounts of background work being started on init()

Otherwise, they might just as well be part of log15 itself, right?

As an example; the HotSwapHandler could go into gopkg.in/inconshreveable/log15.v2/hotswap. According to http://blog.golang.org/package-names that could look something like this:

type HotSwapHandler struct {
    h log15.Handler
}

func New(h log15.Handler) *HotSwapHandler { … }
func (h *HotSwapHandler) Log(r *log15.Record) error { … }
func (h *HotSwapHandler) Swap(h log15.Handler) { … }

And usage:

import "gopkg.in/inconshreveable/log15.v2/hotswap"

hotswapHandler := hotswap.New(fooHandler)
// etc

// later
hotswapHandler.Swap(barHandler)

So yes, I think ext should continue to exist, but only as folder for logging to external services. As described in #5.

First of all, thanks for creating this great logging package. I've looked at all the popular packages out there and I definitly like this one best!

I've created a very simple Handler/hook that sends logs to loggly. It depends on github.com/segmentio/go-loggly. Do you think handlers like these should just have their own repository, or could we include them in this repository?

I think the package should at least have its own package to avoid downloading the go-loggly dependency when go get-ing log15. Maybe it could be something like github.com/inconshreveable/log15/hooks/logglyhook. Name it logglyhook to avoid naming conflict because the user also needs to be importing go-loggly to create the hook.

Here's a gist of how the code looks right now: https://gist.github.com/GeertJohan/6214d2e04957610235ad

Cheers!

How can I tweak things so this kind of thing:

var body, err := ioutil.ReadAll(resp.Body) // http 
var bodyStr = string(body) // JSON posted back

log.Info("response", "body", bodtStr)

output:

INFO[03-11:12:16:26] response            body="{\r\n   \n"foo\": \"bar\" \r\n}"

I don't want all the escaping -- do I need to write my own formatter that bypasses this escaping?

What if I want conditional escaping -- escaping on some fields but not others ...is there a path to achieve that?

Currently compilation fails on app engine due to a missing term.IsTty method, since all term files have specific build tags that exclude appengine.

If the underlying connection of a nethandler breaks, all future records will fail to log. It should probably auto reconnect /w exponential backoff in a separate goroutine if the connection drops.

log15's handler interface is likely too flexible for configuration files to ever fully capture the all of the ways you could build a handler tree. That being said, it's entirely possible to define a simple configuration file format that could at least cover a large swath of the most common cases.

Context

We have noted the overlap of the Handler and Format APIs (see #8). Specifically they both specify a single function that takes a single *Record argument. This overlap makes the division of labor between Handlers and Formats murky.

We have also noted that writing a well behaved Format is non-trivial and the existing Formats are difficult or impossible to customize without copying (see #10 and #35).

Proposal

Change the Format interface to

// A Formatter formats log contexts as a sequence of bytes.
type Formatter interface {
    // Format formats alternating pairs of string keys and values in ctx and
    // returns the result. Implementations are encouraged to handle values
    // that implement the encoding.TextMarshaler interface by calling their
    // MarshalText method.
    Format(ctx []interface{}) []byte
}

Rationale

• Passing a log context to the Format method instead of a *Record forces all decisions about the key/value pairs into the Handler chain and Formatters to focus on a single job—formatting output.
• Encouraging use of the encoding.TextMarshaller interface provides an avenue for applications or Handlers to control the output format of individual values without interfering with the surrounding record encoding. Using a standard interface whenever appropriate is better than defining our own.

https://raw.githubusercontent.com/inconshreveable/log15/master/.travis.yml

This one is invalid. I have a yaml validator as a git hook in my project (which uses log15) and it complains after saving log15 with godep :). Can you please remove the tabs?

In

I propose the support of an implicit "err" argument:

log.Error("woah something happened", err)

would see that err is of type error, and "prefix" it with the "err" key.

Something like:

if _, ok := args[0].(error); ok {
    args = prepend(args, "err")
}

(first ensuring there is at least 1 argument)

This would avoid those things I see often:

log.Error("there was an error", "err", err)

that's 4 times the word "err" in there!

Hello,

It possible I'm missing something but is there a way to set one more custom log level?

I would like to have one log level lover than Debug (Trace).

I'd like to create a context handler in or for a library (or sub-module) that filters out debug messages. Something like:

func NewFoo() *Foo {
    // create context logger
    foo := &Foo{ Logger: Log.New("obj", "foo") }
    // restrict context logger to Info and higher
    foo.SetHandler(log15.LvlFilterHandler(log15.LvlInfo, ???))
    return foo
}

the problem I'm running into is what to pass for the ???. The library would have to be told about the next outer handler. If I do this outside of the library I still have the problem that a I need some global variable floating around to keep track of the root handler, and this defeats nesting. It would be nice to have a InsertHandler() that inserts a handler in front of the existing one. Or am I over-complicating?

It would be nice if writes were done on worker threads. While it does mean that log entries may be "out of order", it would help out in the cases where one logs a lot (I tend to utilize logging quite a bit) and it would also mitigate some of the impact of things done with Lazy.

Note that I am using lumberjack for rolling logs. So it would be nice if this did get added to place nice with any form of custom handlers.

I've just ran some code based on log15 under Windows and saw that the output is quite chaotic due to windows not recognizing the color defs and hence dumping a lot of extra characters all over the logs. At least this is my hunch, didn't really have time to track it down. Maybe you could add a build flag to disable colors if running on windows?

My applications require the fix in #37 however the current v2 branch does not contain it which means I can't use the gopkg.in based import path. It would be asesome if that fix made it to the v2 branch but I understand the concern with breaking existing code in which case a v3 branch would be great too.

kafka, sentry, logstash, flume, scribe, splunk, airbrake, etc.

i dont see any mention of it in doc.go

Go Issue: https://code.google.com/p/go/issues/detail?id=7690

Relevant Go CL: https://codereview.appspot.com/163550043/

Hi. Are there any plans for providing a shortcut for printf, style formatting or is it idiomatic to write:

log.Info(fmt.Sprintf("some text: %d > %d", max, min), "someCtx", 42)

It seems sort of verbose, but I could live with it.

Then another thing, which I tried to look up in the README and the docs but couldn't find. I assume logging error (the Go error type) values happens quite a lot. What is the usual way to deal with this? I have two options, both of which don't really feel that good:

// #1
log.Info(err.Error())

// #2
log.Info("while processing XXX", "error", err)

The first probably doesn't give enough information. The second one feels a bit better but I'm not sure about the key. Should I use "error"?

In #51 @ChrisHines wrote:

[..] It is mildly annoying that one must import log15.v2 in order to implement a Handler (because of the *log15.Record argument). So Handlers are always coupled to log15.v2. This may cause problems down the road for people that implement custom handlers in a library. Consumers of such Handlers will have a harder time upgrading to a putative log15.v3 because I'm pretty sure that all the Handlers in an application must have the same import path for *Record. I'm not sure what to do about that yet.

Excelent point! Even though the Record structure stays the same, the types will be incompatible because the qualified identifier is different.

inconshreveable/log15.v2/record
One solution would be moving Record to it's own package log15.v2/record.
Then log15.v3 will still import log15.v2/record, as will everyone that writes a custom handler.
If at v6 we want to make a breaking change the Record type, then log15.v6 will import log15.v6/record, and everyone will have to update their Handlers to work with v6.

inconshreveable/log15record.v1
The strange thing about the above log15.v2/record subpackage is that if you modify the Record in a non-breaking way (add a field at the bottom of the struct), then those changes must be made in log15.v2, even if the most recent log15 version is actually at v4. And it's also a bit strange that log15.v{3,4,5}/record are never used..
So another solution might be to create a new repo inconshreveable/log15record (package record) that starts at v1, and when breaking changes are made moves to v2..

In both cases, Lvl and RecordKeyNames must also move to the new package. Ctx doesn't necessarily have to move because on the record the field type for the context is []interface{}, but if log15.Ctx is used by third-party projects (I don't know if that's the case), it might move to record.Ctx as well to solve the same incompatibility problem.

I'm trying to add HTTP logging to my application. The format I want is all keys and values, no Msg component.

The terminal format adds 40 chars of padding, regardless of whether a Msg is specified. It would be nice if you could omit this padding without having to reimplement a lot of the terminal display code.

Hi,

Do you intend to release a new tag v2.xx soon ? The last one came in september, and there are some pretty feature that have been implemented since.

This should probably be mentioned in the Docs. This might also affect users who run on Google App Engine, which AFAIK still runs on Go 1.2.

Alternatively we could add a build tag to the go files. Speaking of which, I will create a PR ;)

The log15/stack package is moving to it's own repository as gopkg.in/stack.v?. This issue is here to remind us to use it when ready.

Also, I'm not sure how to interpret the API compatibility rules for gopkg.in as they relate to nested packages. Clearly log15 does not expose any types from log15/stack, so the main package is free to change its dependency without impacting clients. But what do we do with log15/stack then? I suppose we must keep it available at gopkg.in/inconshreveable/log15.v2/stack in case anyone has used it as a stand alone package. A v3 of log15 could then drop the stack folder going forward.

Thoughts?