Post-process hb timestamps in eSEL.pl

Hostboot timestamps in the parsed eSEL logs were incorrect.
The eSEL.pl script was changed to collect the timestamps from
the BMC eSEL logs and re-populate them in output text file.

Change-Id: Id1017cbfc76fb609ee53ef102aa469c41e7de256
CQ:SW408483
Reviewed-on: http://ralgit01.raleigh.ibm.com/gerrit1/50879
Reviewed-by: Matt Derksen <mderkse1@us.ibm.com>
Tested-by: Jenkins Server <pfd-jenkins+hostboot@us.ibm.com>
Reviewed-by: William G. Hoffa <wghoffa@us.ibm.com>
Tested-by: Jenkins OP Build CI <op-jenkins+hostboot@us.ibm.com>
Tested-by: FSP CI Jenkins <fsp-CI-jenkins+hostboot@us.ibm.com>
Tested-by: Jenkins OP HW <op-hw-jenkins+hostboot@us.ibm.com>
Reviewed-by: Daniel M. Crowell <dcrowell@us.ibm.com>

1 files changed, 79 insertions, 4 deletions

diff --git a/src/build/debug/eSEL.pl b/src/build/debug/eSEL.pl
index ec4e05c55..629a2b363 100755
--- a/src/build/debug/eSEL.pl
+++ b/src/build/debug/eSEL.pl
@@ -6,7 +6,7 @@
 #
 # OpenPOWER HostBoot Project
 #
-# Contributors Listed Below - COPYRIGHT 2017
+# Contributors Listed Below - COPYRIGHT 2017,2018
 # [+] International Business Machines Corp.
 #
 #
@@ -26,11 +26,12 @@
 use strict;
 use Cwd;
 use POSIX;
+use POSIX qw(strftime);
 use Switch;
 use Getopt::Long qw(:config no_ignore_case);
 use File::Basename;
 use Data::Dumper;
-use File::Copy qw(copy);
+use File::Copy;
 use Fcntl qw(:seek);
 
 use constant ESEL_HEADER_LENGTH   => 16;
@@ -58,6 +59,10 @@ my $filterAcked = 0;
 my $keepTempFiles = 0;
 my @filesToDelete = ();
 my $ecc_executable  = "";
+my $esel_record_count = 0;
+my @esel_timestamps = ();
+my $timestamp = "";
+my $txt_file_name = "";
 
 my %options_table = (
     get_ami_data => 0,
@@ -249,6 +254,7 @@ elsif ($options_table{"decode_obmc_data"})
 {
     DecodeObmcEselData();
     DecodeBinarySelData();
+    ReplaceHostbootTimestamps();
 }
 elsif ($options_table{"decode_hbel_data"})
 {
@@ -304,6 +310,50 @@ sub HandleOption
     ($debug) && print Dumper \%options_table;
 }
 
+# Hostboot timestamps in the eSEL logs generated by BMC are incorrect.
+# This function will re-populate the timestamps from the array gathered
+# during the processing of the BMC eSELs. We need to post-process the
+# actual output text file and substitute all broken timestamps with the
+# good ones. The function expects @esel_timestamps to be populated already.
+sub ReplaceHostbootTimestamps
+{
+    ($debug) && print "Opening $txt_file_name to replace hb timestamps\n";
+    open TXT_FILE, "<", $txt_file_name or die "Unable to open TXT_FILE $txt_file_name\n";
+    # We need the temp file to substitute the selected lines from the original
+    # text output file. We move the temp at the end to the original.
+    open TEMP_TXT_FILE, ">", $txt_file_name.".tmp" or die "Unable to open TEMP_TXT_FILE $$txt_file_name.tmp\n";
+    my $current_esel_number = 0;
+    while(<TXT_FILE>)
+    {
+        my $line = $_;
+        chomp($line);
+        # We're looking for "Created at" and "Committed at"
+        if($line =~ m{[Created|Committed] at})
+        {
+            # Replace with the matching timestamp from the array of timestamps
+            # we gathered while processing OBMC eSELs.
+            # Match the following pattern "dd/mm/yyyy hh:mm:ss"
+            # Note that we can't match only numbers here since the broken hb
+            # timestamp may contain hex letters
+            $line =~ s{(..)/(..)/(....) ..:..:..}{$esel_timestamps[$current_esel_number]}g;
+            ($debug) && print "Made substitution: $line\n";
+
+            # Only move to the next timestamp when we've seen the "Committed at"
+            # record (we need to put the same timestamp in two places, and the
+            # "Committed at" entry follows the "Created at").
+            if($line =~ m{Committed at})
+            {
+                $current_esel_number++;
+            }
+        }
+        print TEMP_TXT_FILE $line."\n";
+    }
+    close TXT_FILE;
+    close TEMP_TXT_FILE;
+
+    move $txt_file_name.".tmp", $txt_file_name;
+}
+
 sub FilterACKedLogs
 {
     my $fileSize = -s $esel_file;
@@ -388,7 +438,7 @@ sub ProcessEselString
     if($inputString =~ /ESEL=/)
     {
         $inputString =~ s/ESEL=//g; # strip ESEL=
-        ($debug) && print "ESEL data = $inputString\n";
+        ($debug) && print "ESEL data #$esel_record_count = $inputString\n";
     }
     # If the SEL entry contains the "df" key, AND it has '040020' it's our eSEL
     if(!($inputString =~ /df/) or !($inputString =~ /20 00 04/))
@@ -437,7 +487,6 @@ sub RemoveEccFromFile
 # open and create errorlog text output file, if possible
 sub DecodeBinarySelData
 {
-    my $txt_file_name = "";
     my $bin_file_name = "";
     if (-e "$errl_path/errl")
     {
@@ -503,10 +552,36 @@ sub DecodeObmcEselData
         {
             next;
         }
+        # only collect the timestamps if we're processing OBMC eSELs.
+        elsif($options_table{"decode_obmc_data"})
+        {
+            # found PEL string, now find the datestamp associated with it
+            # (the next Timestamp in the log)
+            my $next_line = "";
+            do
+            {
+                $next_line = <LOG_FILE>;
+            } while (!($next_line =~ /Timestamp/));
+            # strip the "Timestamp", commas, spaces, and the newline
+            $next_line =~ s/"Timestamp"://g;
+            $next_line =~ s/,//g;
+            $next_line =~ s/ //g;
+            chomp $next_line;
+
+            # convert to date/time (we are given the timestamp in ms, so divide
+            # by 1000 to get s).
+            $timestamp = strftime("%m/%d/%Y %H:%M:%S", localtime($next_line/1000));
+            ($debug) && print "Timestamp for ESEL #$esel_record_count:$next_line\n";
+            ($debug) && print "Decoded timestamp for ESEL #$esel_record_count:$timestamp\n";
+
+            push @esel_timestamps, $timestamp;
+            ($debug) && $esel_record_count++;
+        }
 
         $line_size = split / /, $pelString;
         print OUT_FILE HexPack($pelString, $line_size);
     }
+    ($debug) && print "Timestamps: @esel_timestamps\n";
     close OUT_FILE;
     close LOG_FILE;
     # Make sure the file naming is consistent with what parsing function expects