Skip Menu |

This queue is for tickets about the Algorithm-Cron CPAN distribution.

Report information
The Basics
Id: 84352
Status: resolved
Priority: 0/
Queue: Algorithm-Cron
People
Owner: Nobody in particular
Requestors: chris [...] netnix.org
Cc:
AdminCc:
Bug Information
Severity: (no value)
Broken in: (no value)
Fixed in: 0.07

History Show all quoted text
  Mon Apr 01 16:04:24 2013 chris [...] netnix.org - Ticket created
Subject: Bug in Algorithm::Cron
Date: Mon, 1 Apr 2013 21:04:08 +0100
To: bug-Algorithm-Cron [...] rt.cpan.org
From: Chris Mason <chris [...] netnix.org>
Hi, I have been using the Algorithm::Cron module for some time and up to now it has been brilliant! However, I noticed an issue this week when it failed to fire an event - when I checked the next fire time it was a lot further in the future than I was expecting: To demonstrate this bug, I have put together the following script: my $t = time (); print "Time: " . $t . "\n\n"; foreach my $base ('local', 'utc') { my $c = new Algorithm::Cron (base => $base, crontab => "0 4 * * *"); print "Base: " . $base . "\n"; print "Crontab: 0 4 * * *\n"; print "Current time: " . strftime ('%H:%M:%S on %d/%b/%Y', localtime ($t)) . "\n"; print "Next run time: " . strftime ('%H:%M:%S on %d/%b/%Y', localtime ($c->next_time ($t))) . "\n\n"; } After some investigation, the issue only occurs when I use the "local" base - and when I execute the above script I get the following output: Time: 1364846197 Base: local Crontab: 0 4 * * * Current time: 20:56:37 on 01/Apr/2013 Next run time: 04:00:00 on 27/Oct/2013 <--- Issue here with the date?!?! Base: utc Crontab: 0 4 * * * Current time: 20:56:37 on 01/Apr/2013 Next run time: 05:00:00 on 02/Apr/2013 My version of Perl is as follows running on Solaris 10: Summary of my perl5 (revision 5 version 8 subversion 4) configuration: Platform: osname=solaris, osvers=2.10, archname=sun4-solaris-64int uname='sunos localhost 5.10 sun4u sparc SUNW,Ultra-2' config_args='' hint=recommended, useposix=true, d_sigaction=define usethreads=undef use5005threads=undef useithreads=undef usemultiplicity=undef useperlio=define d_sfio=undef uselargefiles=define usesocks=undef use64bitint=define use64bitall=undef uselongdouble=undef usemymalloc=n, bincompat5005=undef Compiler: cc='cc', ccflags ='-D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -xarch=v8 -D_TS_ERRNO', optimize='-xO3 -xspace -xildoff', cppflags='' ccversion='Sun WorkShop', gccversion='', gccosandvers='' intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=87654321 d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=16 ivtype='long long', ivsize=8, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8 alignbytes=8, prototype=define Linker and Libraries: ld='cc', ldflags ='' libpth=/lib /usr/lib /usr/ccs/lib libs=-lsocket -lnsl -ldl -lm -lc perllibs=-lsocket -lnsl -ldl -lm -lc libc=/lib/libc.so, so=so, useshrplib=true, libperl=libperl.so gnulibc_version='' Dynamic Linking: dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-R /usr/perl5/5.8.4/lib/sun4-solaris-64int/CORE' cccdlflags='-KPIC', lddlflags='-G' Characteristics of this binary (from libperl): Compile-time options: USE_64_BIT_INT USE_LARGE_FILES Locally applied patches: 22667 The optree builder was looping when constructing the ops ... 22715 Upgrade to FileCache 1.04 22733 Missing copyright in the README. 22746 fix a coredump caused by rv2gv not fully converting a PV ... 22755 Fix 29149 - another UTF8 cache bug hit by substr. 22774 [perl #28938] split could leave an array without ... 22775 [perl #29127] scalar delete of empty slice returned garbage 22776 [perl #28986] perl -e "open m" crashes Perl 22777 add test for change #22776 ("open m" crashes Perl) 22778 add test for change #22746 ([perl #29102] Crash on assign ... 22781 [perl #29340] Bizarre copy of ARRAY make sure a pad op's ... 22796 [perl #29346] Double warning for int(undef) and abs(undef) ... 22818 BOM-marked and (BOMless) UTF-16 scripts not working 22823 [perl #29581] glob() misses a lot of matches 22827 Smoke [5.9.2] 22818 FAIL(F) MSWin32 WinXP/.Net SP1 (x86/1 cpu) 22830 [perl #29637] Thread creation time is hypersensitive 22831 improve hashing algorithm for ptr tables in perl_clone: ... 22839 [perl #29790] Optimization busted: '@a = "b", sort @a' ... 22850 [PATCH] 'perl -v' fails if local_patches contains code snippets 22852 TEST needs to ignore SCM files 22886 Pod::Find should ignore SCM files and dirs 22888 Remove redundant %SIG assignments from FileCache 23006 [perl #30509] use encoding and "eq" cause memory leak 23074 Segfault using HTML::Entities 23106 Numeric comparison operators mustn't compare addresses of ... 23320 [perl #30066] Memory leak in nested shared data structures ... 23321 [perl #31459] Bug in read() 27722 perlio.c breaks on Solaris/gcc when > 256 FDs are available SPRINTF0 - fixes for sprintf formatting issues - CVE-2005-3962 6663288 Upgrade to CGI.pm 3.33 REGEXP0 - fix for UTF-8 recoding in regexps - CVE-2007-5116 6758953 Perl Sys::Syslog can log messages with wrong severity Built under solaris Compiled at May 18 2009 02:52:06 %ENV: PERL5LIB="/export/home/cmason/lib/perl" @INC: /export/home/cmason/lib/perl /usr/perl5/5.8.4/lib/sun4-solaris-64int /usr/perl5/5.8.4/lib /usr/perl5/site_perl/5.8.4/sun4-solaris-64int /usr/perl5/site_perl/5.8.4 /usr/perl5/site_perl /usr/perl5/vendor_perl/5.8.4/sun4-solaris-64int /usr/perl5/vendor_perl/5.8.4 /usr/perl5/vendor_perl . Thanks, Chris
  Sat Apr 06 15:24:00 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added
On Mon Apr 01 16:04:24 2013, chris@netnix.org wrote: Show quoted text
> Base: local > Crontab: 0 4 * * * > Current time: 20:56:37 on 01/Apr/2013 > Next run time: 04:00:00 on 27/Oct/2013 <--- Issue here with the > date?!?!
Hmm, this is awkward, I'm afraid I can't reproduce it. If I use the current time() I get $ perl -Mblib rt84352.pl Time: 1365276076 Base: local Crontab: 0 4 * * * Current time: 20:21:16 on 06/Apr/2013 Next run time: 04:00:00 on 07/Apr/2013 Base: utc Crontab: 0 4 * * * Current time: 20:21:16 on 06/Apr/2013 Next run time: 05:00:00 on 07/Apr/2013 and if instead I use the time you provided I get $ perl -Mblib rt84352.pl 1364846197 Time: 1364846197 Base: local Crontab: 0 4 * * * Current time: 20:56:37 on 01/Apr/2013 Next run time: 04:00:00 on 02/Apr/2013 Base: utc Crontab: 0 4 * * * Current time: 20:56:37 on 01/Apr/2013 Next run time: 05:00:00 on 02/Apr/2013 Might be timezone and/or perl version related though? I'm in Europe/London, so BST currently. Running 5.14.2 from debian/testing. -- Paul Evans
  Sat Apr 06 15:24:01 2013 The RT System itself - Status changed from 'new' to 'open'
  Sat Apr 06 16:02:19 2013 chris [...] netnix.org - Correspondence added
Subject: Re: [rt.cpan.org #84352] Bug in Algorithm::Cron
Date: Sat, 6 Apr 2013 21:01:58 +0100
To: bug-Algorithm-Cron [...] rt.cpan.org
From: Chris Mason <chris [...] netnix.org>
Hi Paul, I am also in Europe/London and I assumed it was something to do with daylight savings as it only started to happen a couple of days before the clocks went forward. However, I have done some further investigation and it appears to be a Solaris issue as I am unable to reproduce it under Debian Linux either. I was struggling a little to understand what your code was doing, but I can run a small Perl script on Solaris to determine if localtime() or mktime() isn't working as expected? Thanks, Chris On 6 April 2013 20:24, Paul Evans via RT <bug-Algorithm-Cron@rt.cpan.org> wrote: Show quoted text
> <URL: https://rt.cpan.org/Ticket/Display.html?id=84352 > > > On Mon Apr 01 16:04:24 2013, chris@netnix.org wrote:
>> Base: local >> Crontab: 0 4 * * * >> Current time: 20:56:37 on 01/Apr/2013 >> Next run time: 04:00:00 on 27/Oct/2013 <--- Issue here with the >> date?!?!
> > Hmm, this is awkward, I'm afraid I can't reproduce it. > > If I use the current time() I get > > $ perl -Mblib rt84352.pl > Time: 1365276076 > > Base: local > Crontab: 0 4 * * * > Current time: 20:21:16 on 06/Apr/2013 > Next run time: 04:00:00 on 07/Apr/2013 > > Base: utc > Crontab: 0 4 * * * > Current time: 20:21:16 on 06/Apr/2013 > Next run time: 05:00:00 on 07/Apr/2013 > > > and if instead I use the time you provided I get > > $ perl -Mblib rt84352.pl 1364846197 > Time: 1364846197 > > Base: local > Crontab: 0 4 * * * > Current time: 20:56:37 on 01/Apr/2013 > Next run time: 04:00:00 on 02/Apr/2013 > > Base: utc > Crontab: 0 4 * * * > Current time: 20:56:37 on 01/Apr/2013 > Next run time: 05:00:00 on 02/Apr/2013 > > > Might be timezone and/or perl version related though? I'm in Europe/London, so BST currently. Running 5.14.2 from debian/testing. > > -- > > Paul Evans
  Fri Apr 12 18:14:14 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added
On Sat Apr 06 16:02:19 2013, chris@netnix.org wrote: Show quoted text
> I was struggling a little to understand what your code was doing, but > I can run a small Perl script on Solaris to determine if localtime() > or mktime() isn't working as expected?
Well, you could certainly do that. Please apply the analogous of this shell log, and we'll see what the result looks like: $ perlsh eval: use POSIX 'mktime'; undef eval: [ localtime 1364846197 ] [ '37', '56', '20', '1', '3', '113', '1', '90', '1' ] ## At this point, I manually set sec=0 min=0 hour=4 and rolled over the mday to the next value, 2: eval: my $t = mktime 0,0,4, 2, 3, 113; '1364871600' eval: scalar localtime $t 'Tue Apr 2 04:00:00 2013' See what your machine makes of that. -- Paul Evans
  Sat Apr 13 04:12:06 2013 chris [...] netnix.org - Correspondence added
Subject: Re: [rt.cpan.org #84352] Bug in Algorithm::Cron
Date: Sat, 13 Apr 2013 09:11:52 +0100
To: bug-Algorithm-Cron [...] rt.cpan.org
From: Chris Mason <chris [...] netnix.org>
Hi Paul, Show quoted text
> Well, you could certainly do that. Please apply the analogous of this shell log, and we'll see what the result looks like: > > $ perlsh > eval: use POSIX 'mktime'; > undef > > eval: [ localtime 1364846197 ] > [ '37', '56', '20', '1', '3', '113', '1', '90', '1' ] > > ## At this point, I manually set sec=0 min=0 hour=4 and rolled over the mday to the next value, 2: > > eval: my $t = mktime 0,0,4, 2, 3, 113; > '1364871600' > > eval: scalar localtime $t > 'Tue Apr 2 04:00:00 2013'
The only difference I see is that it moves localtime forward by 1 hour: $ perlsh eval: use POSIX 'mktime'; undef eval: [ localtime 1364846197 ] [ '37', '56', '20', '1', '3', '113', '1', '90', '1' ] ## At this point, I manually set sec=0 min=0 hour=4 and rolled over the mday to the next value, 2: eval: my $t = mktime 0,0,4, 2, 3, 113; '1364875200' eval: scalar localtime $t 'Tue Apr 2 05:00:00 2013' Just to verify I am still getting the issue, I re-run my test script and got the following output with the same inputs: Time: 1364846197 Base: local Crontab: 0 4 * * * Current time: 20:56:37 on 01/Apr/2013 Next run time: 04:00:00 on 27/Oct/2013 I also tried this on another Solaris 10 system and got an identical result. So, I attempted to try it with the time set to a month earlier and got the correct results: Time: 1362196800 Base: local Crontab: 0 4 * * * Current time: 04:00:00 on 02/Mar/2013 Next run time: 04:00:00 on 03/Mar/2013 eval: scalar localtime 1362196800 'Sat Mar 2 04:00:00 2013' Thanks, Chris
  Sat Apr 13 08:08:00 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added
On Sat Apr 13 04:12:06 2013, chris@netnix.org wrote: Show quoted text
> eval: my $t = mktime 0,0,4, 2, 3, 113; > '1364875200' > > eval: scalar localtime $t > 'Tue Apr 2 05:00:00 2013'
Oh dear. :( This would be one of mktime or localtime being broken then, because they ought to be inverses of each other; a mktime->localtime roundtrip should yield the same time. I imagine that's what is upsetting Algorithm::Cron. It tries to hit 4am on one day, but finds it's now gone past it to 5am, so it'll have to try 4am the next day. It keeps going, every day, until that point in October when the BST offset changes back and suddenly it can manage to hit 4am again. Having read further around on the subject, it appears that on Solaris, mktime() is rather too trusting of the tm_isdst field given in to it. You have to specify -1 to let it not trust that. So perhaps try again with: eval: my $t = mktime 0,0,4, 2, 3, 113, 0, 0, -1; '1364871600' eval: scalar localtime $t; 'Tue Apr 2 04:00:00 2013' Or failing that, maybe set -1 as all three of those last fields. If that works then I guess that'll be the solution. -- Paul Evans
  Sat Apr 13 16:39:39 2013 chris [...] netnix.org - Correspondence added
Subject: Re: [rt.cpan.org #84352] Bug in Algorithm::Cron
Date: Sat, 13 Apr 2013 21:39:26 +0100
To: bug-Algorithm-Cron [...] rt.cpan.org
From: Chris Mason <chris [...] netnix.org>
Show quoted text
> I imagine that's what is upsetting Algorithm::Cron. It tries to hit 4am on one day, but finds it's now gone past it to 5am, so it'll have to try 4am the next day. It keeps going, every day, until that point in October when the BST offset changes back and suddenly it can manage to hit 4am again.
This does sound plausible, however I had another example using the crontab of "0 8 * * 1" which resulted in the following: Time: 1364846197 Base: local Crontab: 0 8 * * 1 Current time: 20:56:37 on 01/Apr/2013 Next run time: 11:00:00 on 08/Apr/2013 Show quoted text
> Having read further around on the subject, it appears that on Solaris, mktime() is rather too trusting of the tm_isdst field given in to it. You have to specify -1 to let it not trust that. So perhaps try again with: > > eval: my $t = mktime 0,0,4, 2, 3, 113, 0, 0, -1; > '1364871600' > > eval: scalar localtime $t; > 'Tue Apr 2 04:00:00 2013' > > Or failing that, maybe set -1 as all three of those last fields.
I ended up with the correct result after setting the last 3 fields to -1 (the time was still 05:00 with just a single or double -1): eval: my $t = mktime 0,0,4, 2, 3, 113, 0, 0, -1, -1, -1; '1364871600' eval: scalar localtime $t; 'Tue Apr 2 04:00:00 2013' As a result of this I modified Cron.pm and changed the following line: local => [ sub { localtime $_[0] }, \&mktime, sub { localtime mktime @_[0..5] } ], to read: local => [ sub { localtime $_[0] }, \&mktime, sub { localtime mktime @_[0..5], -1, -1, -1 } ], and it has resolved the problem for both of my use cases above. This also seems to work fine under Debian Linux as well. Thank you for your time, other people would have put this down as a Solaris issue, but now I can stop using 'utc' and keep having to change it every time the clocks change :) Chris
  Sun Apr 14 09:17:58 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added
On Sat Apr 13 16:39:39 2013, chris@netnix.org wrote: Show quoted text
> I ended up with the correct result after setting the last 3 fields to > -1 (the time was still 05:00 with just a single or double -1): > > eval: my $t = mktime 0,0,4, 2, 3, 113, 0, 0, -1, -1, -1; > '1364871600' > > eval: scalar localtime $t; > 'Tue Apr 2 04:00:00 2013' > > As a result of this I modified Cron.pm and changed the following line: > > local => [ sub { localtime $_[0] }, \&mktime, sub { localtime > mktime @_[0..5] } ], > > to read: > > local => [ sub { localtime $_[0] }, \&mktime, sub { localtime > mktime @_[0..5], -1, -1, -1 } ], > > and it has resolved the problem for both of my use cases above.
Excellent. Glad to know that finally fixed it. I'll pop that in the next version then. -- Paul Evans
  Sun Apr 14 09:17:58 2013 leonerd-cpan [...] leonerd.org.uk - Status changed from 'open' to 'patched'
  Sat Aug 31 19:56:19 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added
Was released in 0.07 -- Paul Evans
  Sat Aug 31 19:56:20 2013 leonerd-cpan [...] leonerd.org.uk - Status changed from 'patched' to 'resolved'
  Sat Aug 31 19:56:20 2013 leonerd-cpan [...] leonerd.org.uk - Fixed in 0.07 added