Rails - Jul 2006 - REPOST: Musings on Rails and logging philosophies

[OK, since I stupidly posted this over the July 4th week[end] and got no
responses, let''s try it again...]

As a perpetual Rails dabbler, I make an awful lot of typical beginner 
mistakes.  And the logs are always either too verbose or too sparse to help 
me.  And it started me thinking.

I came from one of the largest production OLTP systems in the world, and 
the one thing that helped us manage troubleshooting in both development and 
production was extensive, obsessive, flexible logging.  Every operation was 
logged.  Every OS call was followed by an error check and a log message - 
and I mean EVERY call.  On Stratus computers, s$sleep returns an error 
code.  In ten years, I never saw it return anything but zero, but you''d
better believe that every single s$sleep call was accompanied by a 
conditional call to our log system.

Now, with Ruby''s support for exceptions, such paranoia may not seem 
warranted.  After all, if something wild happens, a subroutine can raise an 
exception, and it will get propagated back to something that logs it.  And 
it''s true; the need for logging errors is strongly satisfied by
exceptions.

But errors are only one category of log messages.  Warnings are an 
excellent way to troubleshoot.  For any error, I''d usually find four or
five related warnings that told me why the error occurred.  And for 
"stepping through" code after the fact, info and debug messages are 
invaluable.  Exceptions can''t help you here.

Obviously, you don''t want to pollute the log files with hundreds of 
messages per second.  So following such a "log everything" philosophy 
requires a powerful log filtering system.  It needs to handle multiple 
source categories - exceptions, debug statements, database queries, 
controller/action invocation.  It needs to understand severity levels.  It 
needs to allow flexible, conditional routing of these messages to a 
database, log file, live output, or simply its own circular buffer.  And it 
needs a good interface to manage that routing.

I think Rick Olsen''s ExceptionLogger is a great step toward such a 
filtering system, and I''ve volunteered to contribute.  But I realized
that
such an "ActiveLogging" engine would only solve part of the problem. 
The
bigger problem, if you see it as a problem, is that Rails and its 
applications would need to start logging many more operations.  And that 
would create a dependency on a plugin that''s not likely to become part
of
core, at least in its current database-dependent state.

I think it''s worth the time to create a core ActiveLogger plugin that
will
handle the message routing, with the defaults set to the existing log files 
at first. Then plugins, generators or engines could handle things like 
database output (Rick''s plugin), e-mail notifications
(Jamis''s), etc.  A
bunch of non-invasive, logging-only patches could add the desired logging 
points to the Rails core.  

I''d be willing to put in a few hours a day on this.  As a Rails novice,
I
actually have a better feel for what log messages are missing from Rails, 
because at least once an hour I''m running into something that could use
them!

But maybe I''m thinking too hard.  I have yet to run a true Rails
production
application, so I don''t know the true needs there.  Maybe logging is 
old-school, and YAGNI.  I''ll post this on rails-core if
there''s a
consensus, but I wanted to get some input first before I start tilting at, 
well, logging mills.

What do folks think?

Jay Levitt

Like you, I''m a rails dabbler with large systems experience.

You have my support on this.  I find rails current logging to be
generally unhelpful.  Better logging with plain language messages would
be nice.  A good logging engine like you suggest is a good start.

On Thu, 2006-07-06 at 08:13 -0400, Jay Levitt wrote:
> [OK, since I stupidly posted this over the July 4th week[end] and got no
> responses, let''s try it again...]
> 
> As a perpetual Rails dabbler, I make an awful lot of typical beginner 
> mistakes.  And the logs are always either too verbose or too sparse to help
> me.  And it started me thinking.
> 
> I came from one of the largest production OLTP systems in the world, and 
> the one thing that helped us manage troubleshooting in both development and
> production was extensive, obsessive, flexible logging.  Every operation was
> logged.  Every OS call was followed by an error check and a log message - 
> and I mean EVERY call.  On Stratus computers, s$sleep returns an error 
> code.  In ten years, I never saw it return anything but zero, but
you''d
> better believe that every single s$sleep call was accompanied by a 
> conditional call to our log system.
> 
> Now, with Ruby''s support for exceptions, such paranoia may not
seem
> warranted.  After all, if something wild happens, a subroutine can raise an
> exception, and it will get propagated back to something that logs it.  And 
> it''s true; the need for logging errors is strongly satisfied by
exceptions.
> 
> But errors are only one category of log messages.  Warnings are an 
> excellent way to troubleshoot.  For any error, I''d usually find
four or
> five related warnings that told me why the error occurred.  And for 
> "stepping through" code after the fact, info and debug messages
are
> invaluable.  Exceptions can''t help you here.
> 
> Obviously, you don''t want to pollute the log files with hundreds
of
> messages per second.  So following such a "log everything"
philosophy
> requires a powerful log filtering system.  It needs to handle multiple 
> source categories - exceptions, debug statements, database queries, 
> controller/action invocation.  It needs to understand severity levels.  It 
> needs to allow flexible, conditional routing of these messages to a 
> database, log file, live output, or simply its own circular buffer.  And it
> needs a good interface to manage that routing.
> 
> I think Rick Olsen''s ExceptionLogger is a great step toward such a
> filtering system, and I''ve volunteered to contribute.  But I
realized that
> such an "ActiveLogging" engine would only solve part of the
problem.  The
> bigger problem, if you see it as a problem, is that Rails and its 
> applications would need to start logging many more operations.  And that 
> would create a dependency on a plugin that''s not likely to become
part of
> core, at least in its current database-dependent state.
> 
> I think it''s worth the time to create a core ActiveLogger plugin
that will
> handle the message routing, with the defaults set to the existing log files
> at first. Then plugins, generators or engines could handle things like 
> database output (Rick''s plugin), e-mail notifications
(Jamis''s), etc.  A
> bunch of non-invasive, logging-only patches could add the desired logging 
> points to the Rails core.  
> 
> I''d be willing to put in a few hours a day on this.  As a Rails
novice, I
> actually have a better feel for what log messages are missing from Rails, 
> because at least once an hour I''m running into something that
could use
> them!
> 
> But maybe I''m thinking too hard.  I have yet to run a true Rails
production
> application, so I don''t know the true needs there.  Maybe logging
is
> old-school, and YAGNI.  I''ll post this on rails-core if
there''s a
> consensus, but I wanted to get some input first before I start tilting at, 
> well, logging mills.
> 
> What do folks think?
> 
> Jay Levitt
> 
> _______________________________________________
> Rails mailing list
> Rails@lists.rubyonrails.org
> http://lists.rubyonrails.org/mailman/listinfo/rails

I agree.  Rails logging is very basic.  It would be nice to have a  
better system.


Richard
RogueWaveMarine.com

-- 
Posted with http://DevLists.com.  Sign up and save your mailbox.

> But maybe I''m thinking too hard.  I have yet to run a true Rails
production
> application, so I don''t know the true needs there.  Maybe logging
is
> old-school, and YAGNI.  I''ll post this on rails-core if
there''s a
> consensus, but I wanted to get some input first before I start tilting at,
> well, logging mills.
>
> What do folks think?
>
> Jay Levitt
+1

But if you do need it, by all means work on it.  For what it''s worth,
you might look at the syslog logger that robot coop did.  It may give
you some ideas on how to provide extended logging capabilities as an
addon:  http://dev.robotcoop.com/Tools/

-- 
Rick Olson
http://techno-weenie.net

On Fri, 7 Jul 2006 22:01:13 -0500, Rick Olson wrote:
> But if you do need it, by all means work on it.  For what it''s
worth,
> you might look at the syslog logger that robot coop did.  It may give
> you some ideas on how to provide extended logging capabilities as an
> addon:  http://dev.robotcoop.com/Tools/
Rick,

Thanks for the semi-encouragement :) The big problem, I think, is that for
such an extension to be useful and widely used, Rails itself needs a lot
more logging.  I could do a proof-of-concept version that overrides some
key Rails routines to wrap them in log messages, but this doesn''t start
to
get really interesting until it''s actually into core, which is why I
was
sending up a trial balloon.  

I''m actually more interested to hear your (and similar) viewpoints than
those who agree with me - what facets of Rails do you feel have eliminated
the need for such verbose logging?  

Jay

What about log4r?  It seems to be a framework ready to solve all of the 
problems you mentioned...

-- 
Posted via http://www.ruby-forum.com/.

Yes, if log4r is half as flexible as log4j, it should be flexible enough 
for what the OP is describing.

Ken

Robert James wrote:
> What about log4r?  It seems to be a framework ready to solve all of the 
> problems you mentioned...
>
>

On Wed, 12 Jul 2006 10:03:39 +0200, Kenneth Liu wrote:
> Yes, if log4r is half as flexible as log4j, it should be flexible enough 
> for what the OP is describing.
> 
> Ken
> 
> Robert James wrote:
>> What about log4r?  It seems to be a framework ready to solve all of the
>> problems you mentioned...
>>
logr4 is wonderful!  I don''t know how I missed it.

I think my ideal solution would be to:

- Redirect Rails Logger into log4r
- Create a web admin page for log4r like Rick''s exception logger
- Wrap it all up into a plugin or engine.

Once I do that, then I will come back and take up the cause of how to get
better logging rolled into the core itself - I don''t feel that this
should
stay in a plugin forever, for both technical and, er, "moral" reasons,
but
I realize that creating even an optional dependency on log4r could be
problematic for Rails.

If anyone''s interested in collaborating with me, drop me a line at
"jay at
jay dot eff-emm".

Jay Levitt