Java-like logging package: elog

[Kyle Lemons]

Hello Go nuts,

I've been doing a good amount of development in Go since I discovered it.  I very quickly found the standard logging package to be lacking, so I have put together a logging package that I want to share.

The short version:

I have pasted the main file on pastie to get some feedback before I decide if I want to make it a third party library or submit it to the Go core:

http://pastie.org/private/rhzmgijimi0xp8wra8jdg

Some example code is at the top.  I also have a fairly extensive elog_test.go to go with it, but making that available doesn't seem as important until I either post it on google code or submit it for code review and inclusion into the main tree.

Motivation:

I have also heard some complaints on #go-nuts about adding and removing the import when you move debug messages around.  Having designed large applications in Java, I have gotten used to its logging support by which one can set up a variety of loggers to a variety of sources and independently filter them... so, as a developer, you can put in whatever debug messages you want and assign them a debug level and have that message automatically sent to all of the various logger sources: tracing (and higher) messages via UDP on the network, standard informational (and higher) messages to standard output, and all fine and debugging messages to a log file that can be examined should the application crash.

My Go solution:

I have written a package that I will loosely call "inspired by" the Java version.  It doesn't (yet?) have network broadcast or XML log writing, but it has served the same purpose of making my debugging life easier.  To address the issue of having too many messages printed to the console, when I am running my application in a production mode I turn the filter on the standard output down to elog.INFO or elog.WARNING, so that I can get a good idea of how things are going at a glance.  While I am debugging, however, I have the console output turned up to elog.FINE or elog.DEBUG, so that I can get a better idea of what the application is actually doing.  If something goes wrong or I notice errant behavior while the program is running in production, I can check the log file that I have set up; I can do the same if I want more precise insight into what's going on in debugging as well (as there are certainly some things that are way too verbose to ever go to the console).

To implement this, there is a standard *Logger that is passed around (or made global) through which all logging is done.  When the *Logger is set up, anything implementing the LogWriter interface can be added to it to handle log messages.  I have written two such interfaces, which should be sufficient for basic use: one that prints to the console and one that prints to file.  The console writer prints the time, the log level, and the message while the file writer also prints out the source.  There are a few fine-grained methods that allow you to control the exact log message that is submitted as well as some really simple wrappers that use printf-style interpolation and automatically fill in the source, time, and log level for you.

My question(s) to you:

There is already logging functionality in the standard library, but it is fairly basic.

First off, what do you think of the code?  I haven't been using this language for long enough to be confident that I'm approaching everything in a Go-like way.

Do you guys like this sort of logging?  Have you used it in Java and (dis)liked it?  I'm sure other similar libraries exist as well.

Should I see about merging (what I hesitantly call) my improvements into the standard log package?  As a subpackage of log?  Should I submit this for inclusion as a separate package to log?

Should I maintain this as a third party package?  Do you think enough people would actually use it to make maintaining it as a third party package worthwhile?  Logging doesn't exactly seem like something people look around for in the external package list.

Thanks for taking the time to read through my long-winded email.  If you read this far and want to check out the code, here's the link again:

http://pastie.org/private/rhzmgijimi0xp8wra8jdg

~Kyle Lemons

P.S. If you're interested in the java.util.logging package that inspired this, here's the API:

http://java.sun.com/j2se/1.4.2/docs/api/java/util/logging/Logger.html

[Kees]

I like it. I wrote my own logging package as well: http://mroffice.org/log.go
. A bit more basic than yours, but it has rotating log file handling.

I like rotating logfiles, so that I have one file per run of my app.
Perhaps you can build this into your logging package as well. From the
mature logging packages I like log4j and friends from
logging.apache.org . Something like that (log4go) would definitely be
welcome...

Cheers,

Kees

[Kyle Lemons]

Kees,
Thanks for your reply. I have never used log4j, but read a bit
about it. I do, being a fan of configuration files in general, like
the idea of not requiring a recompile of the program in order to
change the logging settings (and the ability to have my production and
debug versions using different settings). I will definitely consider
adding similar functionality here; probably provided as a utility func
elog.ReadConfiguration(file string) *Logger, or similar. Also, log
rotation is definitely a possibility that I had not considered. I
will definitely add it to my list of things to add as well. Are there
any other features of log4j that you like particularly? Have you ever
used the socket or XML appenders? Any thoughts about if this is
appropriate as a standard package or should be distributed
independently?

~Kyle

[Jim Robinson]

I think it's always useful to have remote log servers which are able to auto rotate logs.  So a system where one could configure the client to dial and connect to a remote log server on startup (soft failing if the log server is unavailable), logging messages over the network (again, soft failing if the server were unavailable).

We've been looking at using things like log4j + spray in our Java based systems.

[Rob 'Commander' Pike]

That's a nice package. I worry though about the cost of each logging operation. When I was designing package "log", I deliberately did not include a logging level or flag as part of the interface to logging operations because their implementation requires evaluating the arguments even if the logging statement will not execute. That is, if log.Stderr took a level argument,

log.Stderr(2, f(), g())

then f and g would be called even if the logging level was only 1. For many cases that's not important, but I've seen cases in other languages where similar issues have dominated performance in some applications.

As a result, the log package is less nice to use - you must say

if logLevel >= 2 {
log.Stderr(f(), g())
}

which is indeed less convenient but will only call f and g when their values are needed.

(This is one area where macros would actually help, by hiding the if statement for you but I'd still rather not have macros.)

I'm happy to see your package available but I would prefer that the standard library not provide a level feature.

-rob

[Kyle Lemons]

Rob,
That is a very good point. After reading about the log4j package
mentioned by an earlier poster, I had already started working on some
performance improvements to my package as well. Based on your
motivation, it sounds like keeping elog separate from the standard
logging package (in the standard library or as a third party package)
is most appropriate.
For my edification, however, I wrote some benchmarks to see what
the performance was like under certain circumstances, included below
and at the bottom of the pastie. These do not include the time
incurred in generating the parameters of the log message, of course.
If the program uses the elog.Log() function (which does not have the
overhead of Sprintf), it can determine that no logging is necessary
and return to execution in under a microsecond. Using one of the
utility functions has slightly more overhead (because of the nested
function calls, I would presume) such that the overhead winds up just
over a microsecond. Maybe it's only by comparison to the no-op
condition that its runtime seems exorbitant, but I would be interested
in any suggestions you have for improving the efficiency of the cases
in which it does log.

elog.BenchmarkStdoutLog 100000 22666 ns/op
elog.BenchmarkStdoutNotLogged 2000000 841 ns/op
elog.BenchmarkStdoutUtilLog 100000 29403 ns/op
elog.BenchmarkStdoutUtilNotLog 1000000 1283 ns/op
elog.BenchmarkFileLog 100000 23795 ns/op
elog.BenchmarkFileNotLogged 2000000 768 ns/op
elog.BenchmarkFileUtilLog 50000 31275 ns/op
elog.BenchmarkFileUtilNotLog 1000000 1176 ns/op

[Kees]

> will definitely add it to my list of things to add as well.  Are there
> any other features of log4j that you like particularly?  Have you ever
> used the socket or XML appenders?  Any thoughts about if this is
> appropriate as a standard package or should be distributed
> independently?

- i like the configurable output (thread, file, function, line, date,
time, etc.)
- havent really used any other output formats
- I think a slightly better log package (log levels for starters)
would be useful in the standard library, despite the potential
performance hit. But I can live without it too.

[Gustavo Hexsel]

  I suppose you could include one signature that receives a closure, for the cases where you would not want the  eval when it's not needed.

  then the call would be something along the lines

  elog.DebugBind(new func() string { return a() + b; })

[Kyle Lemons]

Thanks everyone for your input... I've been tinkering with this for
most of my free time today and just finished verifying the log
rotation behavior. I am somewhat fuzzy on how I can test some of it
(especially the rotating at midnight...) with gotest, but I verified
the behavior myself so I think that'll do for now.

Significant changes:
- Optimizations for speed when no logging is to be done
- Networking logging (JSON) via TCP and UDP
- File Log format strings (%T etc)
- XML configuration file for no-compile reconfiguration of logging
- XML supports console, file, and network log writers
- File log rotation based number of lines, number of bytes, and/or at
midnight

The suggestion to allow closures to defer intensive logging operations
is also an interesting one that I did not have time to play with yet.
I will definitely add that when I get the chance (though it will
probably not have all of the "easy" .DebugBind, .InfoBind, etc I do
plan to make a LogBind(level int, func() string) version).

It is now too big to pastie, and has lots of files... so, if you want
to peruse the source or play with it, I have posted it online:
http://www.prism.gatech.edu/~klemons3/eLog-v2.0.0.tbz2

From the comments, I haven't heard any objections to submitting this
for inclusion as a separate package from log in the standard
distribution, so I will do this sometime tomorrow. Hopefully by then
someone else will have tried it out and agreed that it looks nifty and
useful =).

Thanks again for all of your comments and ideas!
~Kyle

[Andrew Gerrand]

On 29 May 2010 01:42, Kyle Lemons <ky...@kylelemons.net> wrote:
> First off, what do you think of the code?  I haven't been using this
> language for long enough to be confident that I'm approaching everything in
> a Go-like way.

You could create an init function in the package that sets up a global
logger instance, rather than (or as another option to) passing a
*Logger around.

From a cursory glance at the code, it looks like you have various data
structures (maps, vectors) that might be updated simultaneously if a
message is logged from two goroutines at once. This will cause data
corruption and other weirdness.

One approach to solving this problem would be to create a buffered
channel of LogRecords as part of your Logger structure, and have a
call to Log simply perform a message send to that channel. Then you
can have a goroutine (launched upon calling NewLogger) that reads from
that channel and writes out log messages (and whatever else is
currently in Log).

> Do you guys like this sort of logging?  Have you used it in Java and
> (dis)liked it?  I'm sure other similar libraries exist as well.

I've used logging a bit like this with Python's logger package. I
never found it as useful as it appeared to be. It must suit some
people's programming style, though, as I believe libraries like this
are quite popular.

> Should I see about merging (what I hesitantly call) my improvements into the
> standard log package?  As a subpackage of log?  Should I submit this for
> inclusion as a separate package to log?

This package doesn't seem to offer improvements over the standard log
package that justify its complexity. We're trying to keep the standard
library as simple and universal as possible.

> Should I maintain this as a third party package?  Do you think enough people
> would actually use it to make maintaining it as a third party package
> worthwhile?  Logging doesn't exactly seem like something people look around
> for in the external package list.

Definitely maintain this as a third-party package! Push it to a
repository at github/bitbucket/googlecode, and then people can easily
install it with goinstall:
http://golang.org/cmd/goinstall

If people have a use for it, they will find it. As our user-base
grows, we hope the external library ecosystem will become more visible
and accessible. (We also have some plans to improve the godashboard
package list.)

Cheers,
Andrew