Date::Manip "arguments must be valid dates" bug

Today, a Perl program, part of a parallel site crawling project I am working on for a customer, reported the following issue (reformatted for easy reading):

WARNING: [cmp] Arguments must be valid dates: date1
Sort subroutine didn't return a numeric value at 
/usr/local/lib/perl5/site_perl/5.10.1/Date/Manip/Recur.pm line 1291.

Spoiler: if you are having this same issue and are using Log4perl check the version of Date::Manip. If it's 6.07 upgrading to 6.22 fixed this issue in my case.

Since the program uses the excellent Log4j implementation for Perl; Log::Log4perl to log and rotate the log files I was very sure that the call was made from Log::Dispatch::FileRotate, as I assumed that Date::Manip is used to parse the value of DatePattern I've specified in the configuration file as follows:

log4perl.appender.LOGFILE.DatePattern = yyyy-MM-dd-HH

To be sure it happened during initialisation I put a warn statement before and after the call of the init class method of Log::Log4perl in a custom module I had written as follows:

    warn "pre INIT";
    Log::Log4perl->init( $log4perl_conf );
    warn "INIT called";

Since I did get the following output I got proof that somewhere during the initialization things went wrong:

pre INIT at Some/Custom/Module.pm line xxx.
WARNING: [cmp] Arguments must be valid dates: date1
Sort subroutine didn't return a numeric value at 
/usr/local/lib/perl5/site_perl/5.10.1/Date/Manip/Recur.pm line 1291.

Next, I wanted to find the call to Date::Manip that caused this. I used grep to find all modules in the Log namespace as follows:

grep -rl 'Date::Manip' modules/Log

Note that I've installed the Log4perl modules in a local modules directory using CPAN.

The -r option to grep searches all files recursively inside the Log directory. The -l option causes only the names of files that have a match to be printed. The output of this command was just one line:

modules/Log/Dispatch/FileRotate.pm

Next, I opened the file in vi and searched for Date::Manip. Shortly after I had found the following call in the private method _gen_occurance:

my @dates = ParseRecur($pat,$base,$start,$range);

Instead of turning debug mode on to have the preceding statement print the parameters:

warn "ParseRecur($pat,$base,$start,$range);\n" if $self->{debug};

I decided to put the following in the code, before the call to ParseRecur:

warn "ParseRecur('$pat','$base','$start','$range');\n";

Note the single quotes around the arguments, which makes it easier to reuse the output (as you will see soon). After restarting the program once again I got the following output (reformatted):

ParseRecur('0:0:0:0:1*0:0', '1 days ago',
           '+0:0:-0:0:23:59:59', '4 days later')

I used the above output to run the following from the command line:

perl -MDate::Manip \
     -e"print ParseRecur('0:0:0:0:1*0:0', '1 days ago', \
        '+0:0:-0:0:23:59:59', '4 days later')"

Which resulted in the same error message (reformatted):

WARNING: [cmp] Arguments must be valid dates: date1
Sort subroutine didn't return a numeric value at 
/usr/local/lib/perl5/site_perl/5.10.1/Date/Manip/Recur.pm line 1291.

Next, I used the following command to obtain the version of Date::Manip:

perl -MDate::Manip -e'print "$Date::Manip::VERSION\n"'

This reported 6.07 on the computer of my customer. Next, executed both commands on my developement computer at home. Instead of an error the first command gave the following output (excerpt):

2011030815:00:002011030816:00:002011030817:00:002011030818:0...

And the version of Date::Manip reported by the second one was 5.54. To me this suggested that at least I could downgrade to 5.54. But first I wanted to try to upgrade to the latest version on CPAN, version 6.22. At first I tried to do this via perl -MCPAN -e'shell' but this tried to upgrade the 6.07 version in a location I had no rights to. Since I couldn't figure out how to install the new version using CPAN in the local modules directory, to which I do have access, ignoring 6.07, I downloaded the tarbal using wget and copied the contents of the lib directory from the extracted archive to the local module directory. Note that this is not really the recommended way to install Perl modules but in this case I didn't expect any problems.

After the installation, running the first command, as I was hoping for, didn't report an error but output similar to what I got on my development computer, a Dell Vostro ST 200 running Ubuntu 9.10 (excerpt):

2011030816:00:002011030817:00:002011030818:00:002011030819:0...

And the second command reported 6.22, as expected, of course.

At this time of writing I have no idea what caused this issue. The programs I wrote have been running for months now, and this issue only started to show up today (or maybe yesterday).

Summary: How I tackled this bug

1. Pin point at what stage the bug is triggered, inserting warn statements into the original code.
2. Locate where the call is made that causes the issue, and display the parameters used in the call, again by inserting warn before the call itself.
3. Try to reproduce the issue with the smallest possible program.
4. Check this program on another system and/or against a different module version.
5. If the issue can't be reproduced with an older or newer version of the module downgrade or upgrade this module.

Happy bug hunting!

Also today

• Bugs and a little explorer (overview)
• The Little Bookworm