Capturing STDERR for use in log handler

I've searched the web and this mailing list for the answer to this
question. I've found several places that seem to hover around the
answer (including a PDF of chapter 16 of the mod_perl cookbook) but I
can't figure out how to implement it in my code. BTW, I don't own the
mod_perl cookbook and am desperately short on money right now, so
buying the book would be a difficult next step.

I'm writing a custom log which will do all sorts of fun, fancy stuff
for me. I had little difficulty getting the URI, status and other
request information and storing it into a database. Here's my log
handler so far - it just grabs some information and puts it into a
database, I haven't gotten to the fancy parts yet:

package MyProject::ModPerl::Log;
use strict;
use warnings;
use Apache2::RequestRec ();
use Apache2::Connection ();
use Apache2::Const -compile => qw(OK DECLINED);
use DBI;

# handler
sub handler {
my ($r) = @_;
my ($dbh, $sql);

# open database
$dbh = DBI->connect("dbi:SQLite:dbname=/my/log/path") or die
$DBI::errstr;

# insert record
$sql = "insert into events (uri, status, msg) values (?, ?, ?)";
$dbh->do($sql, undef, $r->uri, $r->status, 'STDERR here');
$DBI::err and die "db err: $DBI::err: $DBI::errstr";

# return OK
return Apache2::Const::OK;
}

# return true
1;

So far so good, it adds the information I've got to the database quite
nicely. But the one more thing I really need is all the STDERR that
was generated while processing the request. Recipe 6.10 provides a
method for outputting STDERR to a different file but I'd like to grab
it and put it into my database.

What would be a good way to do this? Thanks for any help!

Tom

Re: Capturing STDERR for use in log handler

On Tue 17 Mar 2009, Tom Spencer wrote:
> So far so good, it adds the information I've got to the database
> quite nicely. =A0But the one more thing I really need is all the STDERR
> that was generated while processing the request. =A0Recipe 6.10
> provides a method for outputting STDERR to a different file but I'd
> like to grab it and put it into my database.

=46irst thing, you have to specify your understanding of "all the STDERR"=20
in more detail. Is it

1) the warn and die output
2) all that perl writes to STDERR
3) something that XS modules or rather libraries used by XS modules=20
write to filedescriptor 2
4) the stuff that apache logs to the virtual hosts errorlog

Here are some ideas how to solve these problems:

1) set $SIG{__WARN__} and $SIG{__DIE__} or implement &CORE::GLOBAL::warn=20
and &CORE::GLOBAL::die

2) reopen STDERR to a memory filehandle, eg:
perl -Mstrict -e '
# list our open fds to see what is going on
system "ls -l /proc/$$/fd";
# save fd2 as SAVEERR
open SAVEERR, ">&STDERR" or die "Cannot dup: $!";
close STDERR;
# make sure that nobody else can open fd2 by chance
open my $acquirefd2, ">", "/dev/null" or die "acquire: $!";
# check it
system "ls -l /proc/$$/fd";
my $err;
# open memory filehandle
open STDERR, ">", \$err or die "open: $!";
# this output must not differ from the previous
system "ls -l /proc/$$/fd";
# some printout to STDERR and a warning
# nothing appears on the terminal
print STDERR "print to STDERR\n";
warn "warning";
# print the error output to STDOUT surrounded by >><<
print ">>$err<<\n";
close STDERR;
system "ls -l /proc/$$/fd";
# release fd2
close $acquirefd2;
# redirect STDERR to the original fd2
open STDERR, ">&SAVEERR" or die "restore: $!";
close SAVEERR;
# check it
system "ls -l /proc/$$/fd";
# these will appear on the terminal
print STDERR "print to STDERR\n";
warn "warning";
'

This is what I see (a bit commented):
total 0
lrwx------ 1 r2 users 64 2009-03-18 12:32 0 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 1 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 12 -> socket:[12916]
lrwx------ 1 r2 users 64 2009-03-18 12:32 13 -> socket:[12917]
# fd2 points to my terminal
lrwx------ 1 r2 users 64 2009-03-18 12:32 2 -> /dev/pts/9
lr-x------ 1 r2 users 64 2009-03-18 12:32 3 -> pipe:[10303]
l-wx------ 1 r2 users 64 2009-03-18 12:32 4 -> pipe:[10303]
lr-x------ 1 r2 users 64 2009-03-18 12:32 5 -> pipe:[31529]
lrwx------ 1 r2 users 64 2009-03-18 12:32 7 -> socket:[12899]
total 0
lrwx------ 1 r2 users 64 2009-03-18 12:32 0 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 1 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 12 -> socket:[12916]
lrwx------ 1 r2 users 64 2009-03-18 12:32 13 -> socket:[12917]
# now it points to /dev/null
lrwx------ 1 r2 users 64 2009-03-18 12:32 2 -> /dev/null
lr-x------ 1 r2 users 64 2009-03-18 12:32 3 -> pipe:[10303]
l-wx------ 1 r2 users 64 2009-03-18 12:32 4 -> pipe:[10303]
# but fd5 (SAVEERR) points to my terminal
lr-x------ 1 r2 users 64 2009-03-18 12:32 5 -> /dev/pts/9
lr-x------ 1 r2 users 64 2009-03-18 12:32 6 -> pipe:[31546]
lrwx------ 1 r2 users 64 2009-03-18 12:32 7 -> socket:[12899]
total 0
lrwx------ 1 r2 users 64 2009-03-18 12:32 0 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 1 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 12 -> socket:[12916]
lrwx------ 1 r2 users 64 2009-03-18 12:32 13 -> socket:[12917]
lrwx------ 1 r2 users 64 2009-03-18 12:32 2 -> /dev/null
lr-x------ 1 r2 users 64 2009-03-18 12:32 3 -> pipe:[10303]
l-wx------ 1 r2 users 64 2009-03-18 12:32 4 -> pipe:[10303]
lr-x------ 1 r2 users 64 2009-03-18 12:32 5 -> /dev/pts/9
lr-x------ 1 r2 users 64 2009-03-18 12:32 6 -> pipe:[31554]
lrwx------ 1 r2 users 64 2009-03-18 12:32 7 -> socket:[12899]
# the framed output
>>print to STDERR
warning at -e line 19.
<<
total 0
lrwx------ 1 r2 users 64 2009-03-18 12:32 0 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 1 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 12 -> socket:[12916]
lrwx------ 1 r2 users 64 2009-03-18 12:32 13 -> socket:[12917]
# still the same: fd2 points to /dev/null, fd5 to my terminal
lrwx------ 1 r2 users 64 2009-03-18 12:32 2 -> /dev/null
lr-x------ 1 r2 users 64 2009-03-18 12:32 3 -> pipe:[10303]
l-wx------ 1 r2 users 64 2009-03-18 12:32 4 -> pipe:[10303]
lr-x------ 1 r2 users 64 2009-03-18 12:32 5 -> /dev/pts/9
lr-x------ 1 r2 users 64 2009-03-18 12:32 6 -> pipe:[31561]
lrwx------ 1 r2 users 64 2009-03-18 12:32 7 -> socket:[12899]
total 0
lrwx------ 1 r2 users 64 2009-03-18 12:32 0 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 1 -> /dev/pts/9
lrwx------ 1 r2 users 64 2009-03-18 12:32 12 -> socket:[12916]
lrwx------ 1 r2 users 64 2009-03-18 12:32 13 -> socket:[12917]
# here it is reverted, fd2 is the terminal, fd5 is something else
# (due to the ls command)
lrwx------ 1 r2 users 64 2009-03-18 12:32 2 -> /dev/pts/9
lr-x------ 1 r2 users 64 2009-03-18 12:32 3 -> pipe:[10303]
l-wx------ 1 r2 users 64 2009-03-18 12:32 4 -> pipe:[10303]
lr-x------ 1 r2 users 64 2009-03-18 12:32 5 -> pipe:[31568]
lrwx------ 1 r2 users 64 2009-03-18 12:32 7 -> socket:[12899]
# this output is now unframed
print to STDERR
warning at -e line 33.

3) save file descriptor 2 to another one (via dup), close it, reopen it=20
on a temporary file, read that file in your log handler and restore the=20
original filedescriptor 2 (for each request). (similar to 2))

4) requires a bit of C-hacking. Apache provides an error-log hook that=20
cannot be used by now from perl.

error_log
declared in ./include/http_log.h
implemented in ./server/log.c
type is VOID
void error_log(const char *file, int line, int level, apr_status_t=20
status, const server_rec *s, const request_rec *r, apr_pool_t *pool,=20
const char *errstr)

Torsten

=2D-=20
Need professional mod_perl support?
Just hire me: torsten.foertsch@gmx.net