Use consistent time source for builds by having client send the build end timestamp. Fallback to using mail processing time as end timestamp if client doesn't send one.

Bug #363102 r=bear

tools/tinderbox/build-seamonkey-util.pl

@@ -24,7 +24,7 @@ use Config;         # for $Config{sig_name} and $Config{sig_num}
 use File::Find ();
 use File::Copy;
 
-$::UtilsVersion = '$Revision: 1.341 $ ';
+$::UtilsVersion = '$Revision: 1.342 $ ';
 
 package TinderUtils;
 
@@ -769,7 +769,7 @@ sub encode_log {
 }
 
 sub mail_build_finished_message {
-    my ($start_time, $build_status, $binary_url, $logfile) = @_;
+    my ($start_time, $end_time, $build_status, $binary_url, $logfile) = @_;
 
     # Rewrite LOG to OUTLOG, shortening lines.
     open OUTLOG, ">$logfile.last" or die "Unable to open logfile, $logfile: $!";
@@ -781,6 +781,7 @@ sub mail_build_finished_message {
     print OUTLOG "\n";
     print OUTLOG "tinderbox: tree: $Settings::BuildTree\n";
     print OUTLOG "tinderbox: builddate: $start_time\n";
+    print OUTLOG "tinderbox: buildenddate: $end_time\n";
     print OUTLOG "tinderbox: status: $build_status\n";
     print OUTLOG "tinderbox: binaryurl: $binary_url\n" if ($binary_url ne "");
     print OUTLOG "tinderbox: build: $Settings::BuildName\n";
@@ -1218,12 +1219,7 @@ sub BuildIt {
         close LOG;
         chdir $build_dir;
 
-        my $mailBuildEndTime = $start_time;
-        if ($Settings::TestOnlyTinderbox){
-          $mailBuildEndTime = $server_start_time;
-        }
-
-        mail_build_finished_message($mailBuildEndTime, $build_status, $binary_url, $logfile) if $Settings::ReportStatus;
+        mail_build_finished_message($mailBuildStartTime, time(), $build_status, $binary_url, $logfile) if $Settings::ReportStatus;
 
         rebootSystem() if $Settings::OS eq 'WIN98' && $Settings::RebootSystem;
 

webtools/tinderbox/README

@@ -143,13 +143,13 @@ DATA STRUCTURES IN showbuilds.cgi
 load_buildlog() creates build_list a list of hash refernces of this
 type
       $buildrec = {    
-         mailtime => $mailtime,
+         endtime => $endtime,          # formerly $mailtime
          buildtime => $buildtime,
-         buildname => ($tree2 ne '' ? $t->{name} . ' ' : '' ) . $buildname,
+         buildname => $buildname,
          errorparser => $errorparser,
          buildstatus => $buildstatus,
          logfile => $logfile,
-         binaryname => $binaryname,
+         binaryurl => $binaryurl,
          td => $t
       };
 

webtools/tinderbox/bustagestats.cgi

@@ -63,7 +63,7 @@ if (defined $tree && defined $start && defined $end) {
             my %stats;
             while (<IN>) {
                 chomp;
-                my ($mailtime, $buildtime, $buildname, $errorparser,
+                my ($endtime, $buildtime, $buildname, $errorparser,
                     $buildstatus, $logfile, $binaryurl) = 
                         split( /\|/ );
                 if ($buildtime >= $first && $buildtime <= $last) {

webtools/tinderbox/doadmin.cgi

@@ -101,7 +101,7 @@ sub trim_logs {
     open(BD, "<", "$tree/build.dat");
     open(NBD, ">", "$tree/build.dat.new");
     while( <BD> ){
-        ($mailtime,$buildtime,$buildname) = split( /\|/ );
+        ($endtime,$buildtime,$buildname) = split( /\|/ );
         if( $buildtime >= $min_date ){
             print NBD $_;
         }
@@ -193,7 +193,7 @@ sub disable_builds {
     # Read build.dat
     open(BD, "<", "$tree/build.dat");
     while( <BD> ){
-        ($mailtime,$buildtime,$bname) = split( /\|/ );
+        ($endtime,$buildtime,$bname) = split( /\|/ );
         $buildnames{$bname} = 0;
     }
     close( BD );
@@ -225,7 +225,7 @@ sub scrape_builds {
     # Read build.dat
     open(BD, "<", "$tree/build.dat");
     while( <BD> ){
-        ($mailtime,$buildtime,$bname) = split( /\|/ );
+        ($endtime,$buildtime,$bname) = split( /\|/ );
         $buildnames{$bname} = 1;
     }
     close( BD );

webtools/tinderbox/processbuild.pl

@@ -283,6 +283,25 @@ sub check_required_variables {
     $err_string .= "Variable 'tinderbox:status' must be 'success', 'busted', 'testfailed', or 'building'\n";
   }
 
+  # Build End Date - Only present in final status message
+  if ($tbx->{buildenddate} eq '') {
+      if ($tbx->{status} =~ /building/) {
+          $tbx->{buildenddate} = $tbx->{builddate};
+      } else {
+          # Fallback to using processing time as enddate for older clients
+          $tbx->{buildenddate} = time;
+      }
+  }
+  else {
+      if ($tbx->{buildenddate} =~ 
+          /([0-9]*)\/([0-9]*)\/([0-9]*)[ \t]*([0-9]*)\:([0-9]*)\:([0-9]*)/) {
+          $tbx->{buildenddate} = timelocal($6,$5,$4,$2,$1-1,$3);
+      }
+      elsif ($tbx->{buildenddate} < 7000000) {
+          $err_string .= "Variable 'tinderbox:buildenddate' not of the form MM/DD/YY HH:MM:SS or unix date\n";
+      }
+  }
+
   # Log compression
   #
   if ($tbx->{logcompression} !~ /^(bzip2|gzip)?$/) {
@@ -306,7 +325,6 @@ sub check_required_variables {
 
 sub write_build_data {
   my $tbx = $_[0];
-  $process_time = time;
   my $lockfile = "$tbx->{tree}/builddat.sem";
   my $lock = &lock_datafile($lockfile);
   unless (open(BUILDDATA, ">>", "$tbx->{tree}/build.dat")) {
@@ -314,7 +332,7 @@ sub write_build_data {
       &unlock_datafile($lock);
       return;
   }
-  print BUILDDATA "$process_time|$tbx->{builddate}|$tbx->{build}|$tbx->{errorparser}|$tbx->{status}|$tbx->{logfile}|$tbx->{binaryurl}\n";
+  print BUILDDATA "$tbx->{buildenddate}|$tbx->{builddate}|$tbx->{build}|$tbx->{errorparser}|$tbx->{status}|$tbx->{logfile}|$tbx->{binaryurl}\n";
   close BUILDDATA;
   &unlock_datafile($lock);
   unlink($lockfile);

webtools/tinderbox/showbuilds.pl

@@ -353,9 +353,6 @@ BEGIN {
           # Add build start, end, and elapsed time where possible.
           my($start, $end, $elapsed);
 
-          # Treat buildtime as the build's start and mailtime as the build's
-          # end.  We should add in explicit setting of endtime in the client
-          # scripts if they don't already have it and then use that here.
           my $start_timet = $br->{buildtime};
           my $end_timet = $br->{endtime};
 
@@ -371,7 +368,7 @@ BEGIN {
           # Grab the human-readable start time.
           $start = get_local_hms($start_timet, $need_to_qualify);
 
-          # If we're still building, the mailtime only reflects the opening
+          # If we're still building, the endtime only reflects the opening
           # mail that the build has started, not the time at which the build
           # ended.  In that case, don't use it.  Use the current time, instead.
           my $time_info = "";

webtools/tinderbox/tbglobals.pl

@@ -553,11 +553,11 @@ sub tb_find_build_record {
 
   chomp($log_entry);
   # Skip the logfile in the parse since it is already known.
-  my ($mailtime, $buildtime, $buildname, $errorparser,
+  my ($endtime, $buildtime, $buildname, $errorparser,
       $buildstatus, $binaryurl) = (split /\|/, $log_entry)[0..4,6];
 
   $buildrec = {    
-    mailtime    => $mailtime,
+    endtime     => $endtime,
     buildtime   => $buildtime,
     buildname   => $buildname,
     errorparser => $errorparser,
@@ -612,11 +612,9 @@ sub load_buildlog {
   my $internal_build_list;
   LOOP: while( $_ = $bw->readline ) {
     chomp;
-    my ($mailtime, $buildtime, $buildname,
+    my ($endtime, $buildtime, $buildname,
      $errorparser, $buildstatus, $logfile, $binaryurl) = split /\|/;
     
-    my ($endtime);
-
     # Ignore stuff in the future.
     next if $buildtime > $maxdate;
     
@@ -635,16 +633,6 @@ sub load_buildlog {
     }
     $tooearly = 0;
 
-    # We should get clients reporting their actual end time.  This would
-    # alleviate an obvious problem where a build starts immediately on the
-    # same system after another completed.  Now, since we infer the end time
-    # based on the mail time, the reported end time of the first build can
-    # be later than the reported start time of the second.
-
-    # Completed builds are eligible for inference of their end time.  If the
-    # build is on-going, it doesn't have an end time, so leave it undefined.
-    $endtime = $mailtime if ($buildstatus ne 'building');
-
     if ($form{noignore} or not $treedata->{ignore_builds}->{$buildname}) {
 
       # Latest record in build.dat for this (buildtime, buildname) tuple wins.
@@ -656,7 +644,6 @@ sub load_buildlog {
 
       my $buildrec = {    
                       endtime     => $endtime,
-                      mailtime    => $mailtime,
                       buildtime   => $buildtime,
                       buildname   => $buildname,
                       errorparser => $errorparser,
@@ -782,7 +769,7 @@ sub get_build_time_index {
   #
   foreach my $br (@{$build_list}) {
     $build_time_index->{$br->{buildtime}} = 1;
-    if ( $br->{endtime} and $display_accurate_build_end_times ) {
+    if ($display_accurate_build_end_times) {
       $build_time_index->{$br->{endtime}} = 1;
     }
   }