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         $test_product eq "fennec")
 186     {
 187         $test_buildtype  = "nightly" unless $test_buildtype;
 188         $test_type       = "browser";
 189     }
 190
 191 #  Expected sequence if all output written to the log.
 192 #
 193 #    Input
 194 # -----------------------------
 195 # JavaScriptTest: Begin Run
 196 # JavaScriptTest: Begin Test t;
 197 # jstest: t
 198 # t:.*EXIT STATUS:
 199 # JavaScriptTest: End Test t
 200 # JavaScriptTest: End Run
 201 # EOF
 202 #
 203     %test_id         = ();
 204     @messages        = ();
 205     $test_exit_status = '';
 206     $state           = 'idle';
 207
 208     while (<FILE>)
 209     {
 210         chomp;
 211
 212         if ($debug)
 213         {
 214             dbg "\nINPUT: '$_'";
 215         }
 216
 217         $_ =~ s/[\r]$//;
 218         $_ =~ s/[\r]/CR/g;
 219         $_ =~ s/[\x01-\x08]//g;
 220         $_ =~ s/\s+$//;
 221
 222         if ( /^JavaScriptTest: Begin Run/)
 223         {
 224             dbg "Begin Run";
 225
 226             if ($state eq 'idle')
 227             {
 228                 $state = 'beginrun';
 229             }
 230             else
 231             {
 232                 warn "WARNING: state: $state, expected: idle, log: $file";
 233                 $state = 'beginrun';
 234             }
 235         }
 236         elsif ( ($tmp_test_id) = $_ =~ /^JavaScriptTest: Begin Test ([^ ]*)/)
 237         {
 238             dbg "Begin Test: $tmp_test_id";
 239
 240             if ($state eq 'beginrun' || $state eq 'endtest')
 241             {
 242                 $state = 'runningtest';
 243             }
 244             else
 245             {
 246                 warn "WARNING: state: $state, expected: beginrun, endtest, log: $file";
 247                 $state = 'runningtest';
 248             }
 249
 250             $test_id{$state}         = $tmp_test_id;
 251             @messages                = ();
 252             @expected_exit_code_list = ();
 253             $expected_exit_code      = ();
 254
 255             $test_id          = '';
 256             $test_result      = '';
 257             $test_exit_status = 'NORMAL'; # default to normal, so subtests will have a NORMAL status
 258             $test_description = '';
 259
 260             push @expected_exit_code_list, (3) if ($tmp_test_id =~ /-n.js$/);
 261
 262         }
 263         elsif ( ($expected_exit_code) = $_ =~ /WE EXPECT EXIT CODE ([0-9]*)/ )
 264         {
 265             dbg "Expected Exit Code: $expected_exit_code";
 266
 267             push @expected_exit_code_list, ($expected_exit_code);
 268         }
 269         elsif ( ($tmp_test_id) = $_ =~ /^jstest: (.*?) *bug:/)
 270         {
 271             dbg "jstest: $tmp_test_id";
 272
 273 #            if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 274 #            {
 275 #                warn "WARNING: state: $state, expected runningtest, reportingtest. mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 276 #            }
 277
 278             if ($state eq 'runningtest')
 279             {
 280                 $state = 'reportingtest';
 281             }
 282             elsif ($state eq 'reportingtest')
 283             {
 284                 $state = 'reportingtest';
 285             }
 286             else
 287             {
 288                 warn "WARNING: test_id: $test_id{$state}, state: $state, expected: runningtest, reportingtest, log: $file";
 289                 $state = 'reportingtest';
 290             }
 291
 292             ($test_result)      = $_ =~ /result: (.*?) *type:/;
 293             ($tmp_test_type)    = $_ =~ /type: (.*?) *description:/;
 294
 295             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"
 296                 if ($test_type ne $tmp_test_type);
 297
 298             ($test_description) = $_ =~ /description: (.*)/;
 299
 300             if (!$test_description)
 301             {
 302                 $test_description = "";
 303             }
 304             $test_description .= '; messages: ' . (join '; ', @messages) . ';';
 305
 306             outputrecord $tmp_test_id, $test_description, $test_result;
 307
 308             $test_id{$state} = $tmp_test_id;
 309         }
 310         elsif ( $state ne 'idle' && (($tmp_test_id) = $_ =~ /^([^:]*):.* EXIT STATUS: NORMAL/))
 311         {
 312             $test_exit_status = 'NORMAL';
 313             dbg "Exit Status Normal: $tmp_test_id, $test_exit_status";
 314
 315             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 316             {
 317                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 318             }
 319
 320             if ($state eq 'reportingtest' || $state eq 'runningtest')
 321             {
 322                 $state = 'exitedtest';
 323             }
 324             else
 325             {
 326                 warn "WARNING: state: $state, expected: reportingtest, runningtest, log: $file";
 327                 $state = 'exitedtest';
 328             }
 329
 330             if (! $test_reported{$tmp_test_id})
 331             {
 332                 dbg "No test results reported: $tmp_test_id";
 333
 334                 $test_result = 'FAILED';
 335                 $test_description = 'No test results reported; messages: ' . (join '; ', @messages) . ';';
 336
 337                 outputrecord $tmp_test_id, $test_description, $test_result;
 338             }
 339
 340             $test_id{$state} = $tmp_test_id;
 341         }
 342         elsif ( $state ne 'idle' && (($tmp_test_id) = $_ =~ /^([^:]*):.* EXIT STATUS: TIMED OUT/))
 343         {
 344             $test_exit_status = 'TIMED OUT';
 345             dbg "Exit Status Timed Out: $tmp_test_id, $test_exit_status";
 346
 347             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 348             {
 349                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 350             }
 351
 352             if ($state eq 'reportingtest' || $state eq 'runningtest')
 353             {
 354                 $state = 'exitedtest';
 355             }
 356             else
 357             {
 358                 dbg "state: $state, expected: reportingtest, runningtest";
 359                 $state = 'exitedtest';
 360             }
 361
 362             $test_result     = 'FAILED';
 363             $test_description .= '; messages: ' . (join '; ', @messages) . ';';
 364
 365             outputrecord $tmp_test_id, $test_description, $test_result;
 366
 367             $test_id{$state} = $tmp_test_id;
 368         }
 369         elsif ( $state ne 'idle' && (($tmp_test_id, $tmp_test_exit_status) = $_ =~ /^([^:]*):.* EXIT STATUS: (CRASHED signal [0-9]+ [A-Z]+) \([0-9.]+ seconds\)/))
 370         {
 371             $test_exit_status = $tmp_test_exit_status;
 372             dbg "Exit Status Crashed: $tmp_test_id, $test_exit_status";
 373
 374             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 375             {
 376                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 377             }
 378
 379             if ($state eq 'reportingtest' || $state eq 'runningtest')
 380             {
 381                 $state = 'exitedtest';
 382             }
 383             else
 384             {
 385                 dbg "state: $state, expected: reportingtest, runningtest";
 386                 $state = 'exitedtest';
 387             }
 388
 389             $test_result     = 'FAILED';
 390             $test_description .= '; messages: ' . (join '; ', @messages) . ';';
 391
 392             outputrecord $tmp_test_id, $test_description, $test_result;
 393
 394             $test_id{$state} = $tmp_test_id;
 395         }
 396         elsif ( $state ne 'idle' && (($tmp_test_id, $tmp_test_exit_status) = $_ =~ /^([^:]*):.* EXIT STATUS: (ABNORMAL [0-9]+) \([0-9.]+ seconds\)/))
 397         {
 398             $test_exit_status = $tmp_test_exit_status;
 399             dbg "Exit Status Abnormal: $tmp_test_id, $test_exit_status";
 400
 401             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 402             {
 403                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 404             }
 405
 406             if ($state eq 'reportingtest'  || $state eq 'runningtest')
 407             {
 408                 $state = 'exitedtest';
 409             }
 410             else
 411             {
 412                 dbg "state: $state, expected: reportingtest, runningtest";
 413                 $state = 'exitedtest';
 414             }
 415
 416             ($exit_code) = $test_exit_status =~ /ABNORMAL ([0-9]+)/;
 417
 418             if (grep /$exit_code/, @expected_exit_code_list)
 419             {
 420                 $test_result = 'PASSED';
 421             }
 422             else
 423             {
 424                 $test_result = 'FAILED';
 425             }
 426
 427             $test_description .= '; messages: ' . (join '; ', @messages) . ';';
 428
 429             dbg "Exit Code: $exit_code, Test Result: $test_result, Expected Exit Codes: " . (join '; ', @expected_exit_code_list);
 430
 431             outputrecord $tmp_test_id, $test_description, $test_result;
 432
 433             $test_id{$state} = $tmp_test_id;
 434         }
 435         elsif ( ($tmp_test_id) = $_ =~ /^JavaScriptTest: End Test ([^ ]*)/)
 436         {
 437             dbg "End Test: $tmp_test_id";
 438
 439             if ($test_id{$state} && $tmp_test_id ne $test_id{$state})
 440             {
 441                 warn "WARNING: state: $state, mismatched test_id: expected: $tmp_test_id, actual: $test_id{$state}, log: $file";
 442             }
 443
 444             if ($state eq 'exitedtest' || $state eq 'runningtest' || $state eq 'reportingtest')
 445             {
 446                 $state = 'endtest';
 447             }
 448             else
 449             {
 450                 warn "WARNING: state: $state, expected: runningtest, reportingtest, exitedtest, log: $file";
 451                 $state = 'endtest';
 452             }
 453
 454             $test_id{$state} = $tmp_test_id;
 455         }
 456         elsif ( /^JavaScriptTest: End Run/)
 457         {
 458             dbg "End Run";
 459
 460             if ($state eq 'endtest')
 461             {
 462                 $state = 'endrun';
 463             }
 464             else
 465             {
 466                 warn "WARNING: state: $state, expected: endtest, log: $file";
 467                 $state = 'endrun';
 468             }
 469         }
 470         elsif ($_ &&
 471                !/^\s+$/ &&
 472                !/^(STATUS:| *PASSED!| *FAILED!)/ &&
 473                !/^JavaScriptTest:/ &&
 474                !/^[*][*][*]/ &&
 475                !/^[-+]{2,2}(WEBSHELL|DOMWINDOW)/ &&
 476                !/^Spider:/ &&
 477                !/real.*user.*sys.*$/ &&
 478                !/user.*system.*elapsed/)
 479         {
 480             if ('runningtest, reportingtest' =~ /$state/)
 481             {
 482
 483                 if (/error: can.t allocate region/ || /set a breakpoint in malloc_error_break/ ||
 484                     /set a breakpoint in szone_error to debug/ || /malloc:.*mmap/ || /vm_allocate/ ||
 485                     /terminate called after throwing an instance of .*bad_alloc/)
 486                 {
 487                     dbg "Adding message: $_ converted to /$test_id{$state}:0: out of memory";
 488                     push @messages, ('/' . $test_id{$state} . ':0: out of memory');
 489                 }
 490                 elsif (/\.js, line [0-9]+: out of memory/ )
 491                 {
 492                     s/\.js, line ([0-9]+): out of memory/\.js:$1:/;
 493                     dbg "Adding message: $_ converted to /$test_id{$state}:0: out of memory";
 494                     push @messages, ('/' . $test_id{$state} . ':0: out of memory');
 495                 }
 496                 else
 497                 {
 498                     dbg "Adding message: $_";
 499                     push @messages, ($_);
 500                 }
 501             }
 502         }
 503         elsif ($debug)
 504         {
 505             dbg "Skipping: $_";
 506         }
 507
 508         if ($debug)
 509         {
 510             if ($test_id{$state})
 511             {
 512                 dbg "test_id{$state}=$test_id{$state}, " . (join '; ', @messages);
 513             }
 514             else
 515             {
 516                 dbg "state=$state, " . (join '; ', @messages);
 517             }
 518         }
 519     }
 520     if ($state eq 'endrun')
 521     {
 522         $state = 'success';
 523     }
 524     die "FATAL ERROR: Test run terminated prematurely. state: $state, log: $file" if ($state ne 'success');
 525
 526 }
 527 close FILE;
 528 close TEMP;
 529
 530 undef $test_branchid;
 531 undef $test_date;
 532 undef $test_buildtype;
 533 undef $test_machine;
 534 undef $test_product;
 535 undef $test_suite;
 536
 537 outresults;
 538
 539 unlink $temp;
 540
 541 sub dbg {
 542     if ($debug)
 543     {
 544         my $msg = shift;
 545         print STDERR "DEBUG: $msg\n";
 546     }
 547 }
 548
 549 sub outresults
 550 {
 551     dbg "sorting temp file $temp";
 552     system("sort -u < $temp");
 553     dbg "finished sorting";
 554 }
 555
 556 sub outputrecord
 557 {
 558     my ($test_id, $test_description, $test_result) = @_;
 559
 560     # cut off the extra jstest: summaries as they duplicate the other
 561     # output and follow it.
 562     $test_description =~ s/jstest:.*//;
 563
 564 #    if (length($test_description) > 6000)
 565 #    {
 566 #        $test_description = substr($test_description, 0, 6000);
 567 #    }
 568 #
 569
 570     my $output =
 571         "TEST_ID=$test_id, " .
 572         "TEST_BRANCH=$test_branchid, " .
 573         "TEST_REPO=$test_repo, " .
 574         "TEST_BUILDTYPE=$test_buildtype, " .
 575         "TEST_TYPE=$test_type, " .
 576         "TEST_OS=$test_os, " .
 577         "TEST_KERNEL=$test_kernel, " .
 578         "TEST_PROCESSORTYPE=$test_processortype, " .
 579         "TEST_MEMORY=$test_memory, " .
 580         "TEST_CPUSPEED=$test_cpuspeed, " .
 581         "TEST_TIMEZONE=$test_timezone, " .
 582         "TEST_RESULT=$test_result, " .
 583         "TEST_EXITSTATUS=$test_exit_status, " .
 584         "TEST_DESCRIPTION=$test_description, " .
 585         "TEST_MACHINE=$test_machine, " .
 586         "TEST_DATE=$test_date" .
 587         "\n";
 588
 589     if ($debug)
 590     {
 591         dbg "RECORD: $output";
 592     }
 593     print TEMP $output;
 594
 595     $test_reported{$test_id} = 1;
 596     @messages = ();
 597 }