[ANN] Lager - a new logging framework for Erlang/OTP

[Andrew Thompson-2]

As part of the work I've been doing at Basho on Riak, I was asked to
write a new logging framework that would allow us to improve the logging
experience for users. Lager is the result of that work and I'm glad to
announce it is available as open-source under the Apache 2.0 licence for
anyone to use.

I've written up a blog post over at the Basho blog going into more
details:

http://blog.basho.com/2011/07/20/Introducing-Lager-A-New-Logging-Framework-for-ErlangOTP/

You can also take a look at the code and the README over at the github
repo:

https://github.com/basho/lager

Please let me know what you think, I'm open to suggestions on improving
and enhancing it. Pull requests would be great too.

Andrew
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Max Lapshin-2]

I will not get tired to tell, that current erlang implementations of
logging are great OOM killers for cases, when you need
to store 20+ megabytes of data in process.

OTP guys have added good format_state method, but one bad place has
left: it is dumping reason.

And reason of crash may include whole process state. I have fixed
gen_server for this:

https://github.com/erlyvideo/erlyvideo/blob/master/apps/erlyvideo/src/core/gen_server_ems.erl#L747

and rewritten pretty_printer:

https://github.com/erlyvideo/erlyvideo/blob/master/apps/erlyvideo/src/core/io_lib_pretty_limited.erl

Without these changes small problem could bring down whole system,
making insolvent all claims for bullet-proof software.
The same situation is with message queue. If any streaming process in
erlyvideo blocks just for 5-20 seconds, its message queue
will grow to several megabytes of data. Dumping it via loggers will
finish erlang VM.

But good one-line loggers are ok, especially for startup. As here:

https://github.com/erlyvideo/erlyvideo/blob/master/apps/log4erl/src/error_logger_log4erl_h.erl#L72

I had to rewrite application startup handling so that it should be
more readable.

So, thanks for your code and I'm running fast to read and test it.
I'll be glad if some of my code would be usefull for you.
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Max Lapshin-2]

And, Andrew.
Log rotation is the _most_ important feature in any logger. In fact,
any logging system must be started from log rotator, because as a rule
of thumb, it should be considered, that nobody ever setups logrotate.

One of my famous tools is runit for its log rotation: it stores all
debug output to logs and you should never bother about space on disks.
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Tim Watson-5]

On 21 July 2011 06:53, Max Lapshin <[hidden email]> wrote:
> And, Andrew.
> Log rotation is the _most_ important feature in any logger. In fact,
> any logging system must be started from log rotator, because as a rule
> of thumb, it should be considered, that nobody ever setups logrotate.

Yes, that's why https://github.com/hyperthunk/fastlog uses
error_logger by default, which can benefit from sasl rolling log
configuration and riak_err to minimise memory usage.

Andrew - I find it interesting that you did the opposite, and
optionally redirected error_logger to Lager! :)

I like the way you check the levels though -
https://github.com/basho/lager/blob/master/src/lager_console_backend.erl#L42
- this is cleaner than the boilerplate I ended up with in fastlog,
which checks the atoms for all the possible levels. I might steal
that. :)

Do you support (or plan to support) named loggers? This is a useful
feature, as well as the ability to set different levels for different
(named) logger processes, which I use quite often.

I notice in your parse_transform that you log a bunch of useful stuff.
I did something similar (see
https://github.com/hyperthunk/fastlog/wiki/Parse-Transform-Support for
details) although I allow patterns to be defined (per logger) to
specify which bits actually appear in the logs - again something you
might like to think about.

Also in your parse_transform, you seem to log time information by
default - this can be quite expensive and it might be better to make
this optional!?

One final note - lager_mochiglobal appears to be doing some scary
things. Is this really the easiest way to check whether or not a log
level is set properly, and why do you need to check the level at the
call site if the logging process (i.e., the gen_event handler) is also
doing this? Maybe I've flicked thorugh the code too quickly and
misunderstood.

Anyway - hope these comments are helpful, and thanks for the
contribution to the community. We have at least 4 logging frameworks
to choose from now! :)
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Max Lapshin-2]

>
> I like the way you check the levels though -
> https://github.com/basho/lager/blob/master/src/lager_console_backend.erl#L42
> - this is cleaner than the boilerplate I ended up with in fastlog,
> which checks the atoms for all the possible levels. I might steal
> that. :)
>

I suppose it is a bad idea to filter logs in the single process. It
seems a very good idea like in log4erl to
compile module when reading configuration and filter messages _before_
sending them to error_logger.

It is better to filter with 24 cores, than with one =)
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Tim Watson-5]

On 21 July 2011 21:18, Max Lapshin <[hidden email]> wrote:

>>
>> I like the way you check the levels though -
>> https://github.com/basho/lager/blob/master/src/lager_console_backend.erl#L42
>> - this is cleaner than the boilerplate I ended up with in fastlog,
>> which checks the atoms for all the possible levels. I might steal
>> that. :)
>>
>
> I suppose it is a bad idea to filter logs in the single process. It
> seems a very good idea like in log4erl to
> compile module when reading configuration and filter messages _before_
> sending them to error_logger.
>
> It is better to filter with 24 cores, than with one =)
>

I don't agree that this is an either or thing. It is true that turning
on and off the levels at compilation time is clearly superior in terms
of performance, but it isn't much use when you're deployed in
production and wish to turn up (or down) the logging levels for a
temporary period. Filtering out certainly logging levels at compile
time is quite easy - tuning to get good performance at runtime without
sacrificing flexibility is harder. Besides, log4erl also supports
changing log levels on the appenders at runtime, so it is also doing
some work at runtime. Probably the most efficient way would be to
bucket the loggers according to all the levels they are enabled for,
which would carry a little time overhead in finding a logger (for a
given level) and a little space overhead in storing the buckets.

I do agree that doing as much work in the client as possible is good.
I would move the formatting work (which in fastlog is usually
undertaken by error_logger, although that can be overriden - to the
client process, but I have state associated with the individual
loggers. I've been thinking about having a single proc to hold all the
various states and having the parse_transform generate code that gets
the state back and doing the level checking and actually logging calls
in the client.

Currently fastlog attempts to do things in as light a fashion as
possible, as you can read about on the wiki:
https://github.com/hyperthunk/fastlog/wiki. I'm going to benchmark
before making any significant changes - perhaps the various authors of
logging frameworks could agree on a sensible set of benchmarks that we
could all aspire to?
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Max Lapshin-2]

On Fri, Jul 22, 2011 at 12:44 AM, Tim Watson <[hidden email]> wrote:
> temporary period. Filtering out certainly logging levels at compile
> time is quite easy - tuning to get good performance at runtime without
> sacrificing flexibility is harder. Besides, log4erl also supports
> changing log levels on the appenders at runtime, so it is also doing
> some work at runtime.

log4erl compiles filtering module in runtime. It really works.
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Andrew Thompson-2]

Trying to reply to several emails here, bear with me.

Lager actually filters in 2 places, at the logging callsite (via a
lookup in mochiglobal, which is *very* fast) and then each backend also
filters, because you may have different backends consuming different
levels. Lager calculates the minimum level in use and stores that in the
mochiglobal value.

The use of mochiglobal was something I kind of agonized over, but its
solid code (riak uses it heavily) and its the fastest option for this
kind of 'read often, write seldom' value.

For log rotation, I find the builtin rotation to be inadequate. Lager
will shortly have its own size and date based rotation (size is done,
but in a branch and I'm working on date right now) that should be more
consistant with what normal rotation tools do.

With regard to more configurable formatting, that's something I'd like
to work on, but I don't want it to be too expensive. Maybe I can do some
compile-time voodoo with like -DFORMAT_STRING="..." and use that to
optimize how values are captured and formatted at compile time.

Thanks for all the suggestions guys, I've certainly gotten some new
ideas from this thread.

Andrew
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Tim Watson-5]

> With regard to more configurable formatting, that's something I'd like
> to work on, but I don't want it to be too expensive. Maybe I can do some
> compile-time voodoo with like -DFORMAT_STRING="..." and use that to
> optimize how values are captured and formatted at compile time.

So fastlog_util compiles its logging patterns at runtime into a fun,
which does little more than extract certain record fields from the
logging record (which the parse_transform produces) - and replace
their values in the format string. That seemed fairly efficient to me.

I'll have a look at mochiglobal - sounds interesting.
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Tim Watson-5]

On 21 July 2011 21:54, Max Lapshin <[hidden email]> wrote:
> On Fri, Jul 22, 2011 at 12:44 AM, Tim Watson <[hidden email]> wrote:
>> temporary period. Filtering out certainly logging levels at compile
>> time is quite easy - tuning to get good performance at runtime without
>> sacrificing flexibility is harder. Besides, log4erl also supports
>> changing log levels on the appenders at runtime, so it is also doing
>> some work at runtime.
>
> log4erl compiles filtering module in runtime. It really works.
>

I'll take a closer look - sounds interesting. What put me off
originally is that there is a heck of a lot of code there, which tends
to mean there's a lot going on whereas I wanted minimal impact and
control over blocking the client (or better, making the work in the
client) or not. Fastlog is only 665 lines of code, as it does very
little work to get from the call site to the underlying logging module
(error_logger by default).
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Andrew Thompson-2]

On Thu, Jul 21, 2011 at 10:52:11PM +0100, Tim Watson wrote:
> I'll take a closer look - sounds interesting. What put me off
> originally is that there is a heck of a lot of code there, which tends
> to mean there's a lot going on whereas I wanted minimal impact and
> control over blocking the client (or better, making the work in the
> client) or not. Fastlog is only 665 lines of code, as it does very
> little work to get from the call site to the underlying logging module
> (error_logger by default).

Unfortunately, error_logger has a lot of flaws, which is why lager has
so much code to replace error_logger in it.

Andrew
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Tim Watson-5]

On 22 July 2011 02:41, Andrew Thompson <[hidden email]> wrote:

> On Thu, Jul 21, 2011 at 10:52:11PM +0100, Tim Watson wrote:
>> I'll take a closer look - sounds interesting. What put me off
>> originally is that there is a heck of a lot of code there, which tends
>> to mean there's a lot going on whereas I wanted minimal impact and
>> control over blocking the client (or better, making the work in the
>> client) or not. Fastlog is only 665 lines of code, as it does very
>> little work to get from the call site to the underlying logging module
>> (error_logger by default).
>
> Unfortunately, error_logger has a lot of flaws, which is why lager has
> so much code to replace error_logger in it.
>
> Andrew

You're not the first person to mention this, so clearly there are
compelling reasons to do so. My motivation for sticking with
error_logger was that it has been battle tested for a very long time,
and is therefore reliable. Clearly there are times when it doesn't do
what you want (hence the appearance of riak_err and other
customisations) so a replacement is a good idea. If Lager is going to
be what riak uses for its error logging, I suspect that'll persuade a
lot of people that it's a worthwhile alternative.

My primary motivation for building fastlog was to get control over the
logging levels (at runtime), which is does fine for now. I will be
keeping an eye on Lager though - as it does sound very capable. Good
luck with it!
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Max Lapshin-2]

> You're not the first person to mention this, so clearly there are
> compelling reasons to do so. My motivation for sticking with
> error_logger was that it has been battle tested for a very long time,
> and is therefore reliable.

It has been tested for several times and considered a VM OOM killer,
when you have to deal more than
with 1 MB of state.

This is why it is one of the first things, done in erlyvideo: turn off
error_logger

Erlang is a platform is excelent. erlyvideo can crush down only
because of error_logger and it happened earlier.
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Tim Watson-5]

> It has been tested for several times and considered a VM OOM killer,
> when you have to deal more than
> with 1 MB of state.

I believe this is why riak_err was created - to limit the amount of
memory being consumed.

>
> This is why it is one of the first things, done in erlyvideo: turn off
> error_logger
>

Or don't log massive terms - we've use error_logger in production
without any issues, but large terms went to a disk_log backed thing. I
do seem to remember that we found making the client (i.e., the process
in which the call site appears) do the work and block seemed to offer
better throughput under load.

Anyway these issues about error_logger are an interesting point -
perhaps Lager will be a better option. I wrote fastlog mainly for my
open source projects, so it should be easy to swap out and experiment.
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Tim Watson-5]

On 22 July 2011 10:42, Tim Watson <[hidden email]> wrote:

>> It has been tested for several times and considered a VM OOM killer,
>> when you have to deal more than
>> with 1 MB of state.
>
> I believe this is why riak_err was created - to limit the amount of
> memory being consumed.
>
>>
>> This is why it is one of the first things, done in erlyvideo: turn off
>> error_logger
>>

So looking at erlyvideo, I notice that you're using log4erl - I take
it that you've tested this and are satisfied with its performance? How
did you benchmark it?
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Max Lapshin-2]

On Friday, July 22, 2011, Tim Watson <[hidden email]> wrote:

> On 22 July 2011 10:42, Tim Watson <[hidden email]> wrote:
>>> It has been tested for several times and considered a VM OOM killer,
>>> when you have to deal more than
>>> with 1 MB of state.
>>
>> I believe this is why riak_err was created - to limit the amount of
>> memory being consumed.
>>
>>>
>>> This is why it is one of the first things, done in erlyvideo: turn off
>>> error_logger
>>>
>
> So looking at erlyvideo, I notice that you're using log4erl - I take
> it that you've tested this and are satisfied with its performance? How
> did you benchmark it?
>

It just works because erlyvideo serves 300-4000 simultaneous clients.
They provide not too much logging events.


When error_logger brings down erlang vm, it happens because of wrong
matching with large state, or dumping message queue or last message.

That is why gen_server also need fix
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions

[Tim Watson-5]

>
> It just works because erlyvideo serves 300-4000 simultaneous clients.
> They provide not too much logging events.
>

Cool - I'm quite interested in comparing the three (mentioned) so
maybe instead of taking my logging framework beyond its current (very
early) stage, I will write a little library to provide a logging API
and swap out at compile and/or runtime the actual logging framework
being used. That might be more useful in general than yet another
logging library.

>
> When error_logger brings down erlang vm, it happens because of wrong
> matching with large state, or dumping message queue or last message.
>
> That is why gen_server also need fix
>

Ok that's good to know - thanks for pointing this out.
_______________________________________________
erlang-questions mailing list
[hidden email]
http://erlang.org/mailman/listinfo/erlang-questions