log_helper.js

// Copyright 2015 The Chromium OS Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
'use strict';

/**
 * @fileoverview Helper class for shill log processing.
 */

var logHelper = {};

/**
 * RegExp for netlog start.
 * @type {RegExp}
 */
logHelper.NET_LOG_START = /netlog=<multiline>/;

/**
 * RegExp for netlog end.
 * @type {RegExp}
 */
logHelper.NET_LOG_END = /---------- END ----------/;

/**
 * RegExp for syslog start.
 * @type {RegExp}
 */
logHelper.SYS_LOG_START = /syslog=<multiline>/;

/**
 * RegExp for system.log section end.
 * @type {RegExp}
 */
logHelper.MULTILINE_LOG_END = /---------- END ----------/;

/**
 * RegExp for brillo log start.
 * @type {RegExp}
 */
logHelper.BRILLO_LOG_START = /--------- beginning of main/;

/**
 * RegExp for start of main log section.
 * @type {RegExp}
 */
logHelper.ANDROID_MAIN_SECTION = /--------- beginning of main/;

/**
 * RegExp for end of Android log section.
 * @type {RegExp}
 */
logHelper.ANDROID_SECTION_END = /\[logcat: \d+.\d+s elapsed\]/;

/**
 * RegExp for start of "LAST LOGCAT" section.
 * @type {RegExp}
 */
logHelper.ANDROID_LAST_LOGCAT_SECTION = / LAST LOGCAT /;

/**
 * RegExp for start of Android bug report file
 * @type {RegExp}
 */
logHelper.ANDROID_BUG_REPORT =
    /== dumpstate: \d{4}-\d{2}-\d{2}.\d{2}:\d{2}:\d{2}/;

/**
 * RegExp for log timestamp.
 * Sample timestamp from ChomeOS net.log:
 *   2015-10-28T15:40:30.879026-05:00
 * @type {RegExp}
 */
logHelper.TIME_FORMAT =
    /\d{4}-\d+-\d+T\d{2}:\d{2}:\d{2}.\d{6}(-|\+)(\d{2}):(\d{2})/;

/**
 * RegExp for brillo log timestamp.  Due to an issue with multiple times being
 * logged, also eliminates log lines that appear to be from the kernel.
 * Sample valid timestamp from Brillo log:
 *   10-30 22:49:30.243   238   238
 * Sample timestamp to skip from Brillo log:
 *   10-30 22:49:30.243     0     0
 * @type {RegExp}
 */
logHelper.BRILLO_TIME_FORMAT =
    /(\d{2}-\d{2}.\d{2}:\d{2}:\d{2}.\d{3})(?: +[1-9][0-9]* +[1-9][0-9]*)/;

/**
 * RegExp for Android log timestamp.
 * Sample valid timestamp from Android log:
 *   11-20 12:08:06.412
 * @type {RegExp}
 */
logHelper.ANDROID_TIME_FORMAT = /(\d{2}-\d{2}.\d{2}:\d{2}:\d{2}.\d{3})/;

/**
 * Method to get time offset from log line.
 *
 * @param {Object} timeMatchResults results from matching regex.
 * @return {Number} offsetMS offset ms for log time.
 * @public
 */
logHelper.getOffsetMS = function(timeMatchResults) {
  if (timeMatchResults.length == 2) {
    // Brillo logs omit time zone.  Assume all lines in same time zone.
    return 0;
  }

  // first get minutes
  var offset = parseInt(timeMatchResults[3]);
  // next get hours
  offset += parseInt(timeMatchResults[2]) * 60;
  if (offset == 0) {
    // returns -0 when attempting to test -00:00 offset
    return 0;
  }
  // convert to ms
  offset = offset * 60 * 1000;
  // and check + or -
  if (timeMatchResults[1] == '-')
    offset *= -1;
  return offset;
};

/**
 * Method to format an elapsed time in ms to HH:MM:SS.
 *
 * @param {Number} elapsedMS elapsed ms to format.
 * @return {string} HH:MM:SS formatted version of the elapsed (ms) time
 * @public
 */
logHelper.formatElapsedMS = function(elapsedMS) {
  var ms = elapsedMS % 1000;
  if (ms < 10) {
    ms = '00' + ms;
  } else if (ms < 100) {
    ms = '0' + ms;
  }
  var elapsed = Math.floor(elapsedMS / 1000);
  var sec = Math.floor(elapsed % 3600 % 60);
  if (sec < 10) {
    sec = '0' + sec;
  }
  var min = Math.floor(elapsed % 3600 / 60);
  if (min < 10) {
    min = '0' + min;
  }
  var hour = Math.floor(elapsed / 3600);
  if (hour < 10) {
    hour = '0' + hour;
  }
  var formatted = hour + ':' + min + ':' + sec + '.' + ms;
  return formatted;
};

/**
 * Array of Objects holding regexs and handlers for system_log subsections
 * @type {Object[]}
 * @return  {int} returns new index into supplied String[]
 */
logHelper.logDetectors = {
  'android_bugreport': {
    re: logHelper.ANDROID_BUG_REPORT,
    handler: function(logHolder, logLines, i) {
      logHolder.fileType = 'android_log';
      while (i < logLines.length) {
        if (logHelper.ANDROID_LAST_LOGCAT_SECTION.test(logLines[i])) {
          // this is the "LAST LOGCAT" section...  skip.
          var lastLogcatSectionLength = logHelper.getSubLog(logLines, i).length;
          console.log('skipping ' + lastLogcatSectionLength +
              ' line(s) of \"LAST LOGCAT\" section');
          i = i + lastLogcatSectionLength;
        } else if (logHelper.ANDROID_MAIN_SECTION.test(logLines[i])) {
          // found start of main log
          console.log('found start of main section');
          break;
        }
        i++;
      }
      logHolder.androidlog = logHelper.getSubLog(logLines, i);
      console.log('found an android bug report: ' +
          logHolder.androidlog.length);
      return i + logHolder.androidlog.length;
    }
  },
  'android': {
    re: logHelper.ANDROID_MAIN_SECTION,
    handler: function(logHolder, logLines, i) {
      var tempLogHolder = logHelper.getSubLog(logLines, i);
      if (androidlogSummary.androidlogTypeCheck(tempLogHolder)) {
        logHolder.androidlog = tempLogHolder;
        logHolder.fileType = 'android_log';
      } else if (netlogSummary.brillologTypeCheck(tempLogHolder)) {
        logHolder.brillolog = tempLogHolder;
        logHolder.fileType = 'brillo_log';
      } else {
        console.log('Error in log type detection - ' +
                    'android time stamp but not android or brillo log');
        return i;
      }
      return i + tempLogHolder.length;
    }
  },
  'netlog_multiline': {
    re: logHelper.NET_LOG_START,
    handler: function(logHolder, logLines, i) {
      // we have a netlog section of a system_log
      logHolder.fileType = 'system_log';
      logHolder.netlog = logHelper.getSubLog(logLines, i);
      console.log('found the netlog section!: ' + logHolder.netlog.length);
      return i + logHolder.netlog.length;
    }
  },
  'syslog_multiline': {
    re: logHelper.SYS_LOG_START,
    handler: function(logHolder, logLines, i) {
      // we have a syslog section of a system_log
      logHolder.fileType = 'system_log';
      logHolder.syslog = logHelper.getSubLog(logLines, i);
      console.log('found the syslog section!: ' + logHolder.syslog.length);
      return i + logHolder.syslog.length;
    }
  }
};

/**
 * Helper method checking what type of log is being processed.
 *
 * @param {String[]} logLines String array for lines in a log.
 * @return {Object} returns String of the file type
 */
logHelper.detectFileType = function(logLines) {
  var logHolder = {fileType: 'unknown'};
  var match;
  // first check if the supplied log has subsections
  for (var i = 0; i < logLines.length; i++) {
    for (var detector in logHelper.logDetectors) {
      match = logLines[i].match(logHelper.logDetectors[detector].re);
      if (match != null) {
        i = logHelper
            .logDetectors[detector]
            .handler(logHolder, logLines, i + 2) + 1;
        break;
      }
    }
  }

  if (logHolder.fileType == 'unknown') {
    if (androidlogSummary.androidlogTypeCheck(logLines)) {
      // supplied file is an android log file
      logHolder.fileType = 'android_log';
      logHolder.androidlog = logLines;
    } else if (netlogSummary.netlogTypeCheck(logLines)) {
      // supplied file is netlog
      logHolder.fileType = 'netlog';
      logHolder.netlog = logLines;
    } else if (syslogSummary.syslogTypeCheck(logLines)) {
      // supplied file is syslog
      logHolder.fileType = 'syslog';
      logHolder.syslog = logLines;
    } else if (netlogSummary.brillologTypeCheck(logLines)) {
      // supplied file is a brillo log
      logHolder.fileType = 'brillolog';
      logHolder.brillolog = logLines;
    } else {
      console.log('file type unknown');
    }
  }

  return logHolder;
};

/**
 * Helper method to extract a sublog of a file.
 *
 * @param {String[]} logLines String array for lines in a log.
 * @param {int} i Start index for the sublog
 * @return {String[]} returns String[] of the sublog lines
 */
logHelper.getSubLog = function(logLines, i) {
  var subLog = [];
  while (i < logLines.length) {
    if (logHelper.MULTILINE_LOG_END.test(logLines[i])) {
      // subsection is done...
      return subLog;
    }
    if (logHelper.ANDROID_SECTION_END.test(logLines[i])) {
      // subsection is done...
      return subLog;
    }
    var time = logLines[i].match(logHelper.TIME_FORMAT);
    if (time == null) {
      time = logLines[i].match(logHelper.ANDROID_TIME_FORMAT);
    }
    if (time == null) {
      time = logLines[i].match(logHelper.BRILLO_TIME_FORMAT);
    }
    if (time == null) {
      console.log('processing sublog, log line time was null');
    } else {
      subLog.push(logLines[i]);
    }
    i++;
  }
  return subLog;
};

/**
 * Helper method to add flagged messages to an object.
 *
 * @param {Object} noteHolder Object to get the new note.
 * @param {Number} noteTime Time stamp from log message.
 * @param {String} noteMessage Message from the log.
 */
logHelper.addNote = function(noteHolder, noteTime, noteMessage) {
  var newNote = {time: noteTime, message: noteMessage};
  if (!noteHolder.notes) {
    noteHolder.notes = [];
  }
  var numNotes = noteHolder.notes.length;
  if (numNotes == 0) {
    noteHolder.notes.push(newNote);
    return;
  }

  // check to see if note should be inserted at the end of the array
  var ind = numNotes - 1;
  while (ind > -1) {
    var note = noteHolder.notes[ind];
    if (note.time <= noteTime) {
      // add new note after this one
      noteHolder.notes.splice(ind + 1, 0, newNote);
      return;
    }
    ind--;
  }
  noteHolder.notes.splice(0, 0, newNote);
};


/**
 * Helper method to add supplicant states to an object.
 *
 * @param {Object} supplicantStates Object to get the state update.
 * @param {Number} update Object holding supplicant state update information.
 */
logHelper.addSupplicantState = function(supplicantStates, update) {
  if (update.time == null) {
    supplicantStates.push({'x': 0, 'y': update.newState});
    return;
  }
  if (update.oldState == update.newState) {
    // not a new state transition...  still check if we have anything stored
    if (supplicantStates.length > 0) {
      // not a new transition...  return
      return;
    }
    supplicantStates.push({'x': update.time, 'y': update.oldState});
    return;
  }
  // now we know the states are different, we need to process this update
  if (supplicantStates.length > 0) {
    // should check states to make sure they match
    var lastUpdate = supplicantStates[supplicantStates.length - 1];
    if (lastUpdate.y != update.oldState) {
      supplicantStates.push({'x': update.time,
                             'y': lastUpdate.y});
      supplicantStates.push({'x': update.time,
                             'y': update.oldState});

    }
  } else {
    // need to enter previous state - use update time since we do not have the
    // start time.
    supplicantStates.push({'x': update.time, 'y': update.oldState});
  }
  supplicantStates.push({'x': update.time,
                         'y': update.oldState});
  supplicantStates.push({'x': update.time,
                         'y': update.newState});
};