Infinite loop in perl Carp module

Question

We have some code which catches an exception, logs the message and then calls Carp::longmess to get the stacktrace.

So a simplified view of what we are doing is:

eval { <some SOAP::Lite stuff> };
if( my $err = $@ )
{
    logwrite( "Caught Error: $err" );
}

The logwrite function is essentially:

sub logwrite($)
{
    my $msg = $_[0];
    my($pkg,$fil,$lin)=caller;
    my $timestamp = POSIX::strftime(...);
    print STDERR "$timestamp $fil/$lin $msg\n";
    print STDERR "$timestamp $fil/$lin Stack trace:\n" . Carp::longmess . "\n";
}

But in the log I am seeing:

20111030 Module.pm/42 Caught Error: at  line
Use of uninitialized value in caller at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 22.
Use of uninitialized value in string eq at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 91.
Use of uninitialized value in numeric lt (<) at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 200.
Use of uninitialized value in pattern match (m//) at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 55.
Use of uninitialized value in concatenation (.) or string at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 55.
Use of uninitialized value in concatenation (.) or string at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 142.
Use of uninitialized value in concatenation (.) or string at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 142.
Use of uninitialized value in concatenation (.) or string at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 142.
Use of uninitialized value in concatenation (.) or string at /usr/lib/perl5/5.8.8/Carp/Heavy.pm line 142.
...

And that sequence of warnings from the Carp/Heavy.pm module repeats over and over again indefiniately, blowing out the logifle. So we eventually kill it off. These warnings look like they're being triggered by the call to Carp::longmess. The other intersting thing here is the $@ variable appears to just be at. It as the at added by die, but no actual error message or line number.

Has anyone seen this before or have any idea what's coing on with the Carp package? This is rare, but has happenned a handful of times over the past month or so, and we have hundreds of these jobs running every day.

I'm not sure how to reproduce your error without knowing what your call stack looks like. Carp has definitely walked off the top of the stack. It could be a bug in Carp, or a corrupted stack. Carp is available as a CPAN module, try upgrading? https://metacpan.org/release/Carp The other option is to try Perl 5.8.9. — Schwern, Nov 01 '11 at 01:17
Could POSIX be calling carp? And have you debugged the issue by setting a breakpoint on longmess and then stepping through? — DVK, Nov 01 '11 at 01:36
Actually, `$@` does not contain `at`. It contains an empty string, or maybe undef. That's not that unusual. The inability of Carp to pickup the file name or line number is much much odder. — ikegami, Nov 01 '11 at 03:12
@Schwern. Thanks, thats useful info, more to search on. Unfortunately upgrading is not an easy option, work under a pretty tight ship where any upgrade involves a QA cycle etc. But its SOAP::Lite with callbacks and underlying calls to LWP, and there's also a couple of levels of `eval`s. So I guess its possible something in the stack could get messed up. Unfortunately its not consistent, as I said one out of hundreds of runs. Although for this dataset its 2 from 9. — Sodved, Nov 01 '11 at 14:01
@Sodved Try a local install of an upgraded Carp and see if it fixes the bug (see local::lib). The bug is likely to be inside Carp or Perl, you're going to have to upgrade or patch something. — Schwern, Nov 01 '11 at 23:49
@Schwern, its very hard to reproduce, only happenned on 5 runs out of thousands in the past 30 days. So we're probably going to just live with it until our next round of infrastructure upgrades. Do you want to collate your comments as an answer and then I'll accept it. — Sodved, Nov 07 '11 at 00:44

score 1 · Answer 1 · answered Nov 01 '11 at 05:47

Your code works for me on perl v5.10.1, with Carp.pm version 1.11.

However, note that what it does is perhaps not what you expect: the backtrace produced by longmess will show where the logwrite function was called from, not where the actual error occurred inside the eval.

score 0 · Accepted Answer · answered Nov 01 '11 at 02:50

I realize this doesn't answer your actual question, but . . . since apparently $msg eq 'at line ' in this case, maybe you should just bypass the issue by tacking unless $msg eq 'at line ' onto the end of the print ... Carp::longmess ... statement? (I mean, unless someone proposes a real solution.)

Infinite loop in perl Carp module

2 Answers2