js/tests/post-process-logs.pl

   1 #!/usr/bin/perl -w
   2 # -*- Mode: Perl; tab-width: 4; indent-tabs-mode: nil; -*-
   3 # ***** BEGIN LICENSE BLOCK *****
   4 # Version: MPL 1.1/GPL 2.0/LGPL 2.1
   5 #
   6 # The contents of this file are subject to the Mozilla Public License Version
   7 # 1.1 (the "License"); you may not use this file except in compliance with
   8 # the License. You may obtain a copy of the License at
   9 # http://www.mozilla.org/MPL/
  10 #
  11 # Software distributed under the License is distributed on an "AS IS" basis,
  12 # WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
  13 # for the specific language governing rights and limitations under the
  14 # License.
  15 #
  16 # The Original Code is Mozilla JavaScript Testing Utilities
  17 #
  18 # The Initial Developer of the Original Code is
  19 # Mozilla Corporation.
  20 # Portions created by the Initial Developer are Copyright (C) 2007
  21 # the Initial Developer. All Rights Reserved.
  22 #
  23 # Contributor(s): Bob Clary <bclary@bclary.com>
  24 #
  25 # Alternatively, the contents of this file may be used under the terms of
  26 # either the GNU General Public License Version 2 or later (the "GPL"), or
  27 # the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
  28 # in which case the provisions of the GPL or the LGPL are applicable instead
  29 # of those above. If you wish to allow use of your version of this file only
  30 # under the terms of either the GPL or the LGPL, and not to allow others to
  31 # use your version of this file under the terms of the MPL, indicate your
  32 # decision by deleting the provisions above and replace them with the notice
  33 # and other provisions required by the GPL or the LGPL. If you do not delete
  34 # the provisions above, a recipient may use your version of this file under
  35 # the terms of any one of the MPL, the GPL or the LGPL.
  36 #
  37 # ***** END LICENSE BLOCK *****
  38
  39 use Getopt::Mixed "nextOption";
  40 use File::Temp qw/ tempfile tempdir /;
  41 use File::Basename;
  42
  43 sub dbg;
  44 sub outresults;
  45 sub outputrecord;
  46
  47 local $file;
  48 local $temp;
  49 my $debug = $ENV{DEBUG};
  50 my $test_dir = $ENV{TEST_DIR};
  51
  52 die "FATAL ERROR: environment variable TEST_DIR must be set to the Sisyphus root directory" unless ($test_dir);
  53
  54 # required for mac os x 10.5 to prevent sort from
  55 # complaining about illegal byte sequences
  56 $ENV{LC_ALL} = 'C';
  57
  58 (undef, $temp) = tempfile();
  59
  60 open TEMP, ">$temp" or
  61     die "FATAL ERROR: Unable to open temporary file $temp for writing: $!\n";
  62
  63 local ($test_id,
  64        $tmp_test_id,
  65        $tmp_test_exit_status,
  66        %test_id,
  67        %test_reported,
  68        $test_result,
  69        $test_type,
  70        $tmp_test_type,
  71        $test_description,
  72        @messages,
  73        $test_processortype,
  74        $test_kernel,
  75        $test_suite,
  76        $test_exit_status,
  77        @expected_exit_code_list,
  78        $expected_exit_code,
  79        $exit_code,
  80        $state);
  81
  82 local $test_memory = 0;
  83 local $test_cpuspeed = 0;
  84 local %test_reported = ();
  85 local $test_repo = 'CVS';
  86
  87 while ($file = shift @ARGV)
  88 {
  89     @messages = ();
  90
  91     dbg "file: $file";
  92
  93     my $filename = basename $file;
  94
  95     dbg "filename: $file";
  96
  97     local ($test_date, $test_product, $test_branchid, $test_buildtype,
  98            $test_os,
  99            $test_machine,$test_global_target) = split /,/, $filename;
 100
 101     $test_branchid =~ s/[^0-9.]//g;
 102     $test_global_target =~ s/.log$//;
 103
 104     local ($test_timezone) = $test_date;
 105     $test_timezone =~ s/.*([-+]\d{4,4})/$1/;
 106
 107     my $filemode;
 108
 109     if ($file =~ /\.bz2$/)
 110     {
 111         $filemode = "bzcat $file|";
 112     }
 113     elsif ($file =~ /\.gz$/)
 114     {
 115         $filemode = "zcat $file|";
 116     }
 117     else
 118     {
 119         $filemode = "<$file";
 120     }
 121
 122     open FILE, "$filemode" or die "FATAL ERROR: unable to open $file for reading: $!\n";
 123
 124     dbg "process header with environment variables used in test";
 125
 126     while (<FILE>)
 127     {
 128         $state = 'failure';
 129
 130         chomp;
 131
 132         # remove carriage returns, bels and other annoyances.
 133         $_ =~ s/[\r]$//;
 134         $_ =~ s/[\r]/CR/g;
 135         $_ =~ s/[\x01-\x08]//g;
 136         $_ =~ s/\s+$//;
 137
 138         if ($debug)
 139         {
 140             dbg "\nINPUT: $_";
 141         }
 142
 143         last if ( $_ =~ /^arguments:/);
 144
 145         if (($envval) = $_ =~ /^environment: TEST_MOZILLA_HG=http:\/\/hg.mozilla.org\/(.*)/ )
 146         {
 147             $test_repo = $envval;
 148         }
 149         elsif (($envvar, $envval) = $_ =~ /^environment: (TEST_[A-Z0-9_]*)=(.*)/ )
 150         {
 151             dbg "envvar=$envvar, envval=$envval";
 152             if ($envvar =~ /TEST_KERNEL/)
 153             {
 154                 $envval =~ s/([0-9]+)\.([0-9]+)\.([0-9]+).*/$1.$2.$3/;
 155                 dbg "found TEST_KERNEL";
 156             }
 157             $envvar =~ tr/A-Z/a-z/;
 158             $$envvar = $envval;
 159             dbg $envvar . "=" . $$envvar;
 160         }
 161         elsif (($envval) = $_ =~ /^environment: OSID=(.*)/ )
 162         {
 163             $test_os = $envval;
 164         }
 165     }
 166
 167     if ($test_cpuspeed < 4)
 168     {
 169         $test_cpuspeed = 'slow';
 170     }
 171     elsif ($test_cpuspeed < 9)
 172     {
 173         $test_cpuspeed = 'medium';
 174     }
 175     else
 176     {
 177         $test_cpuspeed = 'fast';
 178     }
 179
 180     if ($test_product eq "js")
 181     {
 182         $test_type       = "shell";
 183     }
 184     elsif ($test_product eq "firefox" || $test_product eq "thunderbird")
 185     {
 186         $test_buildtype  = "nightly" unless $test_buildtype;
 187         $test_type       = "browser";
 188     }
 189
 190 #  Expected sequence if all output written to the log.
 191 #
 192 #    Input
 193 # -----------------------------
 194 # JavaScriptTest: Begin Run
 195 # JavaScriptTest: Begin Test t;
 196 # jstest: t
 197 # t:.*EXIT STATUS:
 198 # JavaScriptTest: End Test t
 199 # JavaScriptTest: End Run
 200 # EOF
 201 #
 202     %test_id         = ();
 203     @messages        = ();
 204     $test_exit_status = '';
 205     $state           = 'idle';
 206
 207     while (<FILE>)
 208     {
 209         chomp;
 210
 211         if ($debug)
 212         {
 213             dbg "\nINPUT: '$_'";
 214         }
 215
 216         $_ =~ s/[\r]$//;
 217         $_ =~ s/[\r]/CR/g;
 218         $_ =~ s/[\x01-\x08]//g;
 219         $_ =~ s/\s+$//;
 220
 221         if ( /^JavaScriptTest: Begin Run/)
 222         {
 223             dbg "Begin Run";
 224
 225             if ($state eq 'idle')
 226             {
 227                 $state = 'beginrun';
 228             }
 229             else
 230             {
 231                 warn "WARNING: state: $state, expected: idle, log: $file";
 232                 $state = 'beginrun';
 233             }
 234         }
 235         elsif ( ($tmp_test_id) = $_ =~ /^JavaScriptTest: Begin Test ([^ ]*)/)
 236         {
 237             dbg "Begin Test: $tmp_test_id";
 238
 239             if ($state eq 'beginrun' || $state eq 'endtest')
 240             {
 241                 $state = 'runningtest';
 242             }
 243             else
 244             {
 245                 warn "WARNING: state: $state, expected: beginrun, endtest, log: $file";
 246                 $state = 'runningtest';
 247             }
 248
 249             $test_id{$state}         = $tmp_test_id;
 250             @messages                = ();
 251             @expected_exit_code_list = ();
 252             $expected_exit_code      = ();
 253
 254             $test_id          = '';
 255             $test_result      = '';
 256             $test_exit_status = 'NORMAL'; # default to normal, so subtests will have a NORMAL status
 257             $test_description = '';
 258
 259             push @expected_exit_code_list, (3) if ($tmp_test_id =~ /-n.js$/);
 260
 261         }
 262         elsif ( ($expected_exit_code) = $_ =~ /WE EXPECT EXIT CODE ([0-9]*)/ )
 263         {
 264             dbg "Expected Exit Code: $expected_exit_code";
 265
 266             push @expected_exit_code_list, ($expected_exit_code);
 267         }
 268         elsif ( ($tmp_test_id) = $_ =~ /^jstest: (.*?) *bug:/)
 269         {
 270             dbg "jstest: $tmp_test_id";
 271
 272 #            if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 273 #            {
 274 #                warn "WARNING: state: $state, expected runningtest, reportingtest. mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 275 #            }
 276
 277             if ($state eq 'runningtest')
 278             {
 279                 $state = 'reportingtest';
 280             }
 281             elsif ($state eq 'reportingtest')
 282             {
 283                 $state = 'reportingtest';
 284             }
 285             else
 286             {
 287                 warn "WARNING: test_id: $test_id{$state}, state: $state, expected: runningtest, reportingtest, log: $file";
 288                 $state = 'reportingtest';
 289             }
 290
 291             ($test_result)      = $_ =~ /result: (.*?) *type:/;
 292             ($tmp_test_type)    = $_ =~ /type: (.*?) *description:/;
 293
 294             die "FATAL ERROR: test_id: $test_id{$state}, jstest test type mismatch: start test_type: $test_type, current test_type: $tmp_test_type, test state: $state, log: $file"
 295                 if ($test_type ne $tmp_test_type);
 296
 297             ($test_description) = $_ =~ /description: (.*)/;
 298
 299             if (!$test_description)
 300             {
 301                 $test_description = "";
 302             }
 303             $test_description .= '; messages: ' . (join '; ', @messages) . ';';
 304
 305             outputrecord $tmp_test_id, $test_description, $test_result;
 306
 307             $test_id{$state} = $tmp_test_id;
 308         }
 309         elsif ( $state ne 'idle' && (($tmp_test_id) = $_ =~ /^([^:]*):.* EXIT STATUS: NORMAL/))
 310         {
 311             $test_exit_status = 'NORMAL';
 312             dbg "Exit Status Normal: $tmp_test_id, $test_exit_status";
 313
 314             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 315             {
 316                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 317             }
 318
 319             if ($state eq 'reportingtest' || $state eq 'runningtest')
 320             {
 321                 $state = 'exitedtest';
 322             }
 323             else
 324             {
 325                 warn "WARNING: state: $state, expected: reportingtest, runningtest, log: $file";
 326                 $state = 'exitedtest';
 327             }
 328
 329             if (! $test_reported{$tmp_test_id})
 330             {
 331                 dbg "No test results reported: $tmp_test_id";
 332
 333                 $test_result = 'FAILED';
 334                 $test_description = 'No test results reported; messages: ' . (join '; ', @messages) . ';';
 335
 336                 outputrecord $tmp_test_id, $test_description, $test_result;
 337             }
 338
 339             $test_id{$state} = $tmp_test_id;
 340         }
 341         elsif ( $state ne 'idle' && (($tmp_test_id) = $_ =~ /^([^:]*):.* EXIT STATUS: TIMED OUT/))
 342         {
 343             $test_exit_status = 'TIMED OUT';
 344             dbg "Exit Status Timed Out: $tmp_test_id, $test_exit_status";
 345
 346             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 347             {
 348                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 349             }
 350
 351             if ($state eq 'reportingtest' || $state eq 'runningtest')
 352             {
 353                 $state = 'exitedtest';
 354             }
 355             else
 356             {
 357                 dbg "state: $state, expected: reportingtest, runningtest";
 358                 $state = 'exitedtest';
 359             }
 360
 361             $test_result     = 'FAILED';
 362             $test_description .= '; messages: ' . (join '; ', @messages) . ';';
 363
 364             outputrecord $tmp_test_id, $test_description, $test_result;
 365
 366             $test_id{$state} = $tmp_test_id;
 367         }
 368         elsif ( $state ne 'idle' && (($tmp_test_id, $tmp_test_exit_status) = $_ =~ /^([^:]*):.* EXIT STATUS: (CRASHED signal [0-9]+ [A-Z]+) \([0-9.]+ seconds\)/))
 369         {
 370             $test_exit_status = $tmp_test_exit_status;
 371             dbg "Exit Status Crashed: $tmp_test_id, $test_exit_status";
 372
 373             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 374             {
 375                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 376             }
 377
 378             if ($state eq 'reportingtest' || $state eq 'runningtest')
 379             {
 380                 $state = 'exitedtest';
 381             }
 382             else
 383             {
 384                 dbg "state: $state, expected: reportingtest, runningtest";
 385                 $state = 'exitedtest';
 386             }
 387
 388             $test_result     = 'FAILED';
 389             $test_description .= '; messages: ' . (join '; ', @messages) . ';';
 390
 391             outputrecord $tmp_test_id, $test_description, $test_result;
 392
 393             $test_id{$state} = $tmp_test_id;
 394         }
 395         elsif ( $state ne 'idle' && (($tmp_test_id, $tmp_test_exit_status) = $_ =~ /^([^:]*):.* EXIT STATUS: (ABNORMAL [0-9]+) \([0-9.]+ seconds\)/))
 396         {
 397             $test_exit_status = $tmp_test_exit_status;
 398             dbg "Exit Status Abnormal: $tmp_test_id, $test_exit_status";
 399
 400             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 401             {
 402                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 403             }
 404
 405             if ($state eq 'reportingtest'  || $state eq 'runningtest')
 406             {
 407                 $state = 'exitedtest';
 408             }
 409             else
 410             {
 411                 dbg "state: $state, expected: reportingtest, runningtest";
 412                 $state = 'exitedtest';
 413             }
 414
 415             ($exit_code) = $test_exit_status =~ /ABNORMAL ([0-9]+)/;
 416
 417             if (grep /$exit_code/, @expected_exit_code_list)
 418             {
 419                 $test_result = 'PASSED';
 420             }
 421             else
 422             {
 423                 $test_result = 'FAILED';
 424             }
 425
 426             $test_description .= '; messages: ' . (join '; ', @messages) . ';';
 427
 428             dbg "Exit Code: $exit_code, Test Result: $test_result, Expected Exit Codes: " . (join '; ', @expected_exit_code_list);
 429
 430             outputrecord $tmp_test_id, $test_description, $test_result;
 431
 432             $test_id{$state} = $tmp_test_id;
 433         }
 434         elsif ( ($tmp_test_id) = $_ =~ /^JavaScriptTest: End Test ([^ ]*)/)
 435         {
 436             dbg "End Test: $tmp_test_id";
 437
 438             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 439             {
 440                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 441             }
 442
 443             if ($state eq 'exitedtest' || $state eq 'runningtest' || $state eq 'reportingtest')
 444             {
 445                 $state = 'endtest';
 446             }
 447             else
 448             {
 449                 warn "WARNING: state: $state, expected: runningtest, reportingtest, exitedtest, log: $file";
 450                 $state = 'endtest';
 451             }
 452
 453             $test_id{$state} = $tmp_test_id;
 454         }
 455         elsif ( /^JavaScriptTest: End Run/)
 456         {
 457             dbg "End Run";
 458
 459             if ($state eq 'endtest')
 460             {
 461                 $state = 'endrun';
 462             }
 463             else
 464             {
 465                 warn "WARNING: state: $state, expected: endtest, log: $file";
 466                 $state = 'endrun';
 467             }
 468         }
 469         elsif ($_ &&
 470                !/^\s+$/ &&
 471                !/^(STATUS:| *PASSED!| *FAILED!)/ &&
 472                !/^JavaScriptTest:/ &&
 473                !/^[*][*][*]/ &&
 474                !/^[-+]{2,2}(WEBSHELL|DOMWINDOW)/ &&
 475                !/^Spider:/ &&
 476                !/real.*user.*sys.*$/ &&
 477                !/user.*system.*elapsed/)
 478         {
 479             if ('runningtest, reportingtest' =~ /$state/)
 480             {
 481
 482                 if (/error: can.t allocate region/ || /set a breakpoint in malloc_error_break/ ||
 483                     /set a breakpoint in szone_error to debug/ || /malloc:.*mmap/ || /vm_allocate/ ||
 484                     /terminate called after throwing an instance of .*bad_alloc/)
 485                 {
 486                     dbg "Adding message: $_ converted to /$test_id{$state}:0: out of memory";
 487                     push @messages, ('/' . $test_id{$state} . ':0: out of memory');
 488                 }
 489                 elsif (/\.js, line [0-9]+: out of memory/ )
 490                 {
 491                     s/\.js, line ([0-9]+): out of memory/\.js:$1:/;
 492                     dbg "Adding message: $_ converted to /$test_id{$state}:0: out of memory";
 493                     push @messages, ('/' . $test_id{$state} . ':0: out of memory');
 494                 }
 495                 else
 496                 {
 497                     dbg "Adding message: $_";
 498                     push @messages, ($_);
 499                 }
 500             }
 501         }
 502         elsif ($debug)
 503         {
 504             dbg "Skipping: $_";
 505         }
 506
 507         if ($debug)
 508         {
 509             if ($test_id{$state})
 510             {
 511                 dbg "test_id{$state}=$test_id{$state}, " . (join '; ', @messages);
 512             }
 513             else
 514             {
 515                 dbg "state=$state, " . (join '; ', @messages);
 516             }
 517         }
 518     }
 519     if ($state eq 'endrun')
 520     {
 521         $state = 'success';
 522     }
 523     die "FATAL ERROR: Test run terminated prematurely. state: $state, log: $file" if ($state ne 'success');
 524
 525 }
 526 close FILE;
 527 close TEMP;
 528
 529 undef $test_branchid;
 530 undef $test_date;
 531 undef $test_buildtype;
 532 undef $test_machine;
 533 undef $test_product;
 534 undef $test_suite;
 535
 536 outresults;
 537
 538 unlink $temp;
 539
 540 sub dbg {
 541     if ($debug)
 542     {
 543         my $msg = shift;
 544         print STDERR "DEBUG: $msg\n";
 545     }
 546 }
 547
 548 sub outresults
 549 {
 550     dbg "sorting temp file $temp";
 551     system("sort < $temp | uniq");
 552     dbg "finished sorting";
 553 }
 554
 555 sub outputrecord
 556 {
 557     my ($test_id, $test_description, $test_result) = @_;
 558
 559     # cut off the extra jstest: summaries as they duplicate the other
 560     # output and follow it.
 561     $test_description =~ s/jstest:.*//;
 562
 563 #    if (length($test_description) > 6000)
 564 #    {
 565 #        $test_description = substr($test_description, 0, 6000);
 566 #    }
 567 #
 568
 569     my $output =
 570         "TEST_ID=$test_id, " .
 571         "TEST_BRANCH=$test_branchid, " .
 572         "TEST_REPO=$test_repo, " .
 573         "TEST_BUILDTYPE=$test_buildtype, " .
 574         "TEST_TYPE=$test_type, " .
 575         "TEST_OS=$test_os, " .
 576         "TEST_KERNEL=$test_kernel, " .
 577         "TEST_PROCESSORTYPE=$test_processortype, " .
 578         "TEST_MEMORY=$test_memory, " .
 579         "TEST_CPUSPEED=$test_cpuspeed, " .
 580         "TEST_TIMEZONE=$test_timezone, " .
 581         "TEST_RESULT=$test_result, " .
 582         "TEST_EXITSTATUS=$test_exit_status, " .
 583         "TEST_DESCRIPTION=$test_description, " .
 584         "TEST_MACHINE=$test_machine, " .
 585         "TEST_DATE=$test_date" .
 586         "\n";
 587
 588     if ($debug)
 589     {
 590         dbg "RECORD: $output";
 591     }
 592     print TEMP $output;
 593
 594     $test_reported{$test_id} = 1;
 595     @messages = ();
 596 }