tags:

views:

124

answers:

4

Is there an easy way to time tag errors going to stderr? In order to troubleshoot problems, I need to know when an error occurred.

Example:

Dec 10 12:00:00 Can't call method "str" on an undefined value

Thanks!

+11  A: 

See Log::Log4perl. Way more options about logging than you'll ever need, but at least that's one of the options.

Randal Schwartz
+10  A: 

Define custom handlers for handling warnings and fatal errors:

use strict;
use warnings;

$SIG{__WARN__} = sub { warn sprintf("[%s] ", scalar localtime), @_ };
$SIG{__DIE__}  = sub { die  sprintf("[%s] ", scalar localtime), @_ };

warn;
die;

Output:

[Fri Dec 11 14:35:37 2009] Warning: something's wrong at c:\temp\foo.pl line 7.
[Fri Dec 11 14:35:37 2009] Died at c:\temp\foo.pl line 8.

You might want to use gmtime instead of localtime.

Michael Carman
This is the quick and dirty solution I was looking for. Also had to add $SIG{__DIE__} handler to time tag some errors. Thanks!
macbus
Hmmm...I'm getting two timestamps in the output on dies.[Thu Dec 10 13:23:51 2009] [Thu Dec 10 13:23:51 2009] blah blah blah
macbus
@macbus: Are you calling `warn` from your `__DIE__` handler? If so, don't. I've updated the answer to include an example.
Michael Carman
@carman: Nope, I've got die in there. And your examples works so something is wonky on my end. I am using Exception::Class and Moose so maybe that has something to do with the double time tag?
macbus
Ah...assume (Exception::Class) throw calls die and then in my code, I catch it, print an message, and call die again. Hence the double time tags.
macbus
+7  A: 

Create a handler for the __WARN__ signal and add the date there:

use Date::Format;

$SIG{'__WARN__'} = sub { warn time2str( '%C ', time ), $_[0] };

....
# rest of your script here.
innaM
Thanks for voting this up! It was completely broken.
innaM
+9  A: 

__WARN__ handlers only catch warnings. They don't catch print STDERR. If you want to catch everything, you have to tie STDERR.

#!/usr/bin/perl -w

package Tie::Handle::Timestamp;

use strict;
use warnings;

use base 'Tie::Handle';

sub stamp {
    return scalar localtime() .": ";
}

sub TIEHANDLE {
    my $class = shift;
    my $handle = shift;

    # Dup the filehandle otherwise we'll be calling ourself
    open my $fh, ">&", $handle or die $!;

    return bless $fh, $class;
}

sub PRINT {
    my $self = shift;
    print { $self } $self->stamp, @_;
}

sub PRINTF {
    my $self = shift;
    my $format = shift;
    printf { $self } $self->stamp . $format, @_;
}

sub CLOSE {
    my $self = shift;
    close $self;
}


package main;

# Tie it at compile time to catch compile time warnings
BEGIN {
    tie *STDERR, "Tie::Handle::Timestamp", *STDERR or die;
}

print STDERR "Foo\n";
warn "Bar";
undef == 2;

This has its own perils as you're now relying on how good your tie implementation is. I'd be surprised there's not already a CPAN module for this, but I don't know of any one I could recommend.

Schwern
ysth
gmtime++, localtime--
ysth
SWATCH BEATS! SCREW THE SUN!
Schwern