Weird [?] error logging

[Lain]

# With Apache + Passenger + Sinatra
> tail -f /var/log/apache2/error.log
127.0.0.1 - - [16/Mar/2010 23:18:59] "GET / " 200 2036 0.0018

Any idea why 200 OK requests are logged to error.log?

[Travis Bell]

I'm actually getting this too but I haven't been clear on whether it's a Passenger thing, or Sinatra. I've tried making sure all logging is disabled and yet, it still logs to the error log of all places.

Cheers,

--

Travis Bell

--
You received this message because you are subscribed to the Google Groups "sinatrarb" group.
To post to this group, send email to sina...@googlegroups.com.
To unsubscribe from this group, send email to sinatrarb+...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/sinatrarb?hl=en.

[Francesco Negri]

On Mar 21, 5:31 pm, Travis Bell <travisdb...@gmail.com> wrote:
> I'm actually getting this too but I haven't been clear on whether it's a Passenger thing, or Sinatra. I've tried making sure all logging is disabled and yet, it still logs to the error log of all places.

It's a Sinatra thing: by default it logs all requests to stdout, which
Passenger redirects to the general apache error.log
Just tell Sinatra to log its stuff to a file instead that stdout. Try
with this in your config.ru:

FileUtils.mkdir_p 'log' unless File.exists?('log')
log = File.new('log/sinatra.log', 'a')
$stdout.reopen(log)
$stderr.reopen(log)

[Randy Fischer]

I think there's a lot of misinformation out there, on logging in sinatra.
I'll tell you what I've found works in my environment, which is:

   * redhat linux
   * apache
   * passenger phusion
   * one classic app per virtual host
   * production mode
   * sinatra 1.0

I hope you find it useful.

The first clue to me  is

>  127.0.0.1 - - [16/Mar/2010 23:18:59] "GET / " 200 2036 0.0018

That trailing elapsed time, and the space before the " indicates
that Rack::CommonLogger is involved.   By default,  the common
logger writes to env['rack.errors'], unless something else
intervenes.  Suffice it to say, under sinatra this usually ends
up being stderr.

Stderr eventually gets to the apache error_log file.

You can disable common logger from being loaded by simply
doing

 configure do
   disable :logging
   ....
 end

There's more,  however:  you can tell common logger where to
put it's stuff, I do it in the configure section after the :logging
disable:

  use Rack::CommonLogger,  my-ob

my-ob basically can be just about anything with a
"write" method on it - I use an object that uses Log4r
under the hood.  You could create a class that writes to
a file of your choice of course.

CommonLogger turns out not to be so useful.   You really
can't use it log your own stuff - the elapsed time in the logs
are nice, but realize it adds it's own overhead.  You can write
to stderr yourself,  but then the common logger output comes
after your own information.  At that point, you might just as well
write your own request log in a before filter.

I *really* like Log4r, by the way.   I point it to syslog and can
break out warning/error/info etc into separate files if I want,
and use logrotate to compress and age them - all without
modifying my application code.   Syslog time stamps its
own entries,  so the common logger entries become a bit
redundant.

Another technique worth looking into  is to

   set :raise_errors, false

so that you can capture your exceptions in an error
handler:

 error do
  e = @env['sinatra.error']
  ... do logging stuff with exception e
  [ halt 500, { 'Content-Type' => 'text/plain' }, "Internal Server Error - #{e.message}\n" ]
 end

If you go that route,  you might want to do the following

   disable :dump_errors

otherwise sinatra  will write backtraces to stderr whether you
handle the errors or not.  (I do the disable  in the configure
section, not sure if it's necessary to do it there or if anywhere
works).   Then you can write the backtraces yourself, if you
want, in the error handler - send them to  stderr if you
like.

But I leave apache to write what it wants to its own
access_log and error_log.   I rarely need to look at its
error_log - only when I'm debugging my error handler
code.  Everything else I take care of using Log4r in the
error handler.

At least, that's what I'm doing this month.

Again,  many of these settings override defaults that are
only true in certain environments, so YMMV.

Hope this helps - I've found most of the examples out there
in blogland wrong or at least wrong-headed.

-Randy Fischer

[J. Case Schilder]

Thank you Randy. That clears things up.