Re: Seeking clarifaction of tai64nlocal and leap seconds

On Wed, Sep 19, 2012 at 02:52:15PM -0700, Russ Allbery wrote:
> Sure, but what those files do is adjust for a system clock that's in TAI
> so that you still get human-readable times in UTC.  That doesn't help if
> you have timestamps that you think are TAI but aren't.

Where I'm spinning:

I have a CentOS 5.7 box managed by NTP, in the Etc/UTC time zone.

I wrote a simple perl program to kick out the current time:

  #!/usr/bin/perl

  use strict;
  use warnings;
  use POSIX qw(strftime);
  
  use Time::HiRes qw(gettimeofday);
  
  $| = 1; # make unbuffered
  
  my ($seconds, $microseconds) = gettimeofday;
  my @time=localtime($seconds);
  
  my $time = strftime('%F %T.', @time).
             $microseconds.
             strftime(' %Z', @time).
             "\n";

  print $time;

I spun this for about five seconds, pumping it through multilog:

  (while true; do perl ./timestamp.pl; done ) | \
    /usr/bin/multilog t /var/tmp/multilog_test

I ran some gunky awk code, to show me the skew (in seconds) between
those timestamps, and those recorded by multilog.  By all means,
check my math.  This yeilds the multilog timestamp, converted by
tai64nlocal, followed by how far in the past the perl code wrote
it's current time:

  tai64nlocal < /var/tmp/multilog_test/current | \
   awk '{print $2 ":" $4}' | \
  awk -F: '{print $1 ":" $2 ":" $3 " " ($1*3600 + $2*60 + $3) - ($4*3600 +
$5*60 + $6)}' > out

And what's weird, is about ten percent yeild a negative number:

  # wc -l out
  130 out
  # grep -e '-' out | wc -l
  12
  # grep -e '-' out
  22:27:04.018789500 -0.167311
  22:27:04.052439500 -0.4702
  22:27:04.085872500 -0.771078
  22:27:05.022971500 -0.205008
  22:27:05.056508500 -0.506782
  22:27:05.089965500 -0.807995
  22:27:06.031346500 -0.280313
  22:27:06.064729500 -0.580831
  22:27:06.098136500 -0.881533
  22:27:07.032824500 -0.293675
  22:27:07.066171500 -0.593808
  22:27:07.099472500 -0.893597

And, if I look for those multilog timestamps, indeed things seem
to have happened out-of-order. e.g.:

  # tai64nlocal < /var/tmp/multilog_test/current | grep 22:27:04.018789500
2012-09-19 22:27:04.018789500 2012-09-19 22:27:04.18610 UTC

Multilog recorded a message _before_ the perl code did. :)

Is this a leap-second error?  If so, how did I introduce it?

> -- 
> Russ Allbery ([email protected])             <http://www.eyrie.org/~eagle/>

-- 
Brian Reichert				<[email protected]>
BSD admin/developer at large