netlog_summary.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 Class to hold methods for processing netlog messages.
 */

var netlogSummary = {};

/**
 * Object used for passing state between main processing loop and
 * regeular expression handler functions.
 * @constructor
 * @type {Object}
 * @param {LogSummary} logSummary object holding log state after processing
 * @param {Manager} currentManager object of the current manager in log
 * @param {String} time timestamp of current log line
 * @param {String[]} results results from regex test
 */
function ProcessingState(logSummary, currentManager, time, results) {
  this.logSummary = logSummary;
  this.currentManager = currentManager;
  this.time = time;
  this.results = results;
}

/**
 * Array of Objects holding regexs and handlers for netlog subsections
 * @type {Object[]}
 * @return {string} handler functions return log line tag label
 */
netlogSummary.taggedLines = {
  'new_manager': {
    re: /Manager started./,
    handler: function(processingState, result) {
      var logSummary = processingState.logSummary;
      var currentManager = processingState.currentManager;
      if (processingState.time != null) {
        var new_manager;
        var offset = logHelper.getOffsetMS(processingState.time);
        if (!currentManager) {
          new_manager = new Manager(1,
                                    Date.parse(processingState.time[0]),
                                    offset);
        } else {
          new_manager = new Manager(processingState.currentManager.id + 1,
                                    Date.parse(processingState.time[0]),
                                    offset);
          logSummary.managers[logSummary.managers.length - 1].endTime =
              logSummary.prevLogLineTime;
        }
        logSummary.managers.push(new_manager);
        processingState.currentManager = new_manager;
        console.log('added a new manager!', logSummary.managers);
      } else {
        console.log('time == null');
      }
      return 'basic';
    }
  },
  'shill_exit': {
    re: /shill.* Process exiting/,
    handler: function(processingState, result) {
      console.log('shill is exiting');
      var manager = processingState.currentManager;
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        'shill - Process exiting');
      return 'basic';
    }
  },
  'service_state': {
    // In Manager::UpdateService
    re: /Service (\w+) updated; state:* (\w+)( failure: )?(\w+)?/,
    handler: function(processingState, result) {
      var logSummary = processingState.logSummary;
      var currentManager = processingState.currentManager;
      var id = result[1];
      var state = result[2];
      var failure = result[4];  // [3] = ' failure: ' if provided.
      if (!failure || failure == 'Unknown') {
        failure = null;
      }
      console.log('*****Service state update!');
      console.log('service [' + id + '][' + state + ']');
      console.log('managers.length: ' + logSummary.managers.length);
      console.log('managers: ', logSummary.managers);
      var currentService = currentManager.getService(id);
      var update = {state: state, time: processingState.time[0]};
      if (failure) {
        console.log('failure: ' + failure);
        update.failure = failure;
      }
      currentService.addUpdate(update);
      console.log(currentService);
      if (state == 'Online') {
        // add logic to track time to connect from suspend
        var connFromSuspend = currentManager.connFromSuspend;
        var cLength = connFromSuspend.length;
        if (cLength > 0 && !connFromSuspend[cLength - 1].conn) {
          connFromSuspend[cLength - 1].conn =
              Date.parse(processingState.time[0]) - currentManager.startTime;
        }
      }
      if (currentService.isActive) {
        return 'serviceStateActive';
      }
      return 'serviceState';
    }
  },
  'service_state_hint': {
    // In Service::SetState()
    re: /Service (\w+): state (\w+) -> (\w+)/,
    handler: function(processingState, result) {
      var id = result[1];
      var state = result[2];
      console.log('service state hint!!!');
      var serviceCheck = processingState.currentManager.getService(id);
      if (!serviceCheck.getCurrentUpdate()) {
        var update = {state: state, time: null};
        serviceCheck.addUpdate(update);
      }
      return 'basic';
    }
  },
  'service_destroyed': {
    // In Service::~Service()
    re: /Service (\d+) destroyed/,
    handler: function(processingState, result) {
      var id = result[1];
      var current_service = processingState.currentManager.getService(id);
      var current_update = current_service.getCurrentUpdate();
      if (current_update != null) {
        logHelper.addNote(current_update,
                          processingState.time[0],
                          'destroyed');
      } else {
        logHelper.addNote(current_service,
                          processingState.time[0],
                          'destroyed');
      }
      return 'faint';
    }
  },
  'service_connect': {
    // In Service::Connect()
    re: /Connecting to \S+ Service (\w+): .*/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[0]);
      return 'basic';
    }
  },
  'link_monitor': {
    re: /link_monitor\S+ (.*$)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        'Link Monitor: ' + result[0]);
      return 'basic';
    }
  },
  'traffic_monitor': {
    re: /traffic_monitor\S+ (.*$)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        'Traffic Monitor: ' + result[1]);
      return 'basic';
    }
  },
  'suspend_imminent': {
    re: /shill.* SuspendImminent(.*$)/,
    handler: function(processingState, result) {
      var time = processingState.time;
      var currentManager = processingState.currentManager;
      logHelper.addNote(currentManager, time[0], 'SuspendImminent');
      var active_service = currentManager.getActiveService();
      if (active_service) {
        var current_update = active_service.getCurrentUpdate();
        logHelper.addNote(current_update, time[0], 'SuspendImminent');
      }
      currentManager
          .addEventDetail('suspend',
                          false,
                          Date.parse(time[0]) - currentManager.startTime);
      return 'suspend';
    }
  },
  'suspend_done': {
    re: /shill.* SuspendDone(.*$)/,
    handler: function(processingState, result) {
      var time = processingState.time;
      var currentManager = processingState.currentManager;
      logHelper.addNote(currentManager, time[0], 'SuspendDone');
      var active_service = currentManager.getActiveService();
      if (active_service) {
        var current_update = active_service.getCurrentUpdate();
        logHelper.addNote(current_update, time[0], 'SuspendDone');
      }
      currentManager
          .addEventDetail('suspend',
                          true,
                          Date.parse(time[0]) - currentManager.startTime);
      return 'suspend';
    }
  },
  'dark_suspend_imminent': {
    re: / DarkSuspendImminent(.*$)/,
    handler: function(processingState, result) {
      var time = processingState.time;
      var currentManager = processingState.currentManager;
      logHelper.addNote(currentManager, time[0], result[0]);
      var active_service = currentManager.getActiveService();
      if (active_service) {
        var current_update = active_service.getCurrentUpdate();
        logHelper.addNote(current_update, time[0], result[0]);
      }
      currentManager
          .addEventDetail('darksuspend',
                          false,
                          Date.parse(time[0]) - currentManager.startTime);
      return 'suspend';
    }
  },
  'dark_suspend_done': {
    re: /shill.* ReportSuspendReadinessInternal.*dark=true\)/,
    handler: function(processingState, result) {
      var time = processingState.time;
      var currentManager = processingState.currentManager;
      logHelper.addNote(currentManager, time[0], 'DarkSuspendDone');
      var active_service = currentManager.getActiveService();
      if (active_service) {
        var current_update = active_service.getCurrentUpdate();
        logHelper.addNote(current_update, time[0], 'DarkSuspendDone');
      }
      currentManager
          .addEventDetail('darksuspend',
                          true,
                          Date.parse(time[0]) - currentManager.startTime);
      return 'suspend';
    }
  },
  'completed': {
    re: / WiFi \w+ StateChanged completed -> completed/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[0]);
      return 'basic';
    }
  },
  'update_from_ip_config': {
    re: /UpdateFromIPConfig.*/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[0]);
      return 'basic';
    }
  },
  'device_updated': {
    re: /Device.*updated:.*/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[0]);
      return 'basic';
    }
  },
  'profile_internal': {
    re: /\)\] (.*ProfileInternal.*)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'scan': {
    re: / Scan .* from .*/,
    handler: function(processingState, result) {
      var currentManager = processingState.currentManager;
      var time = processingState.time;
      logHelper.addNote(currentManager, time[0], result[0]);
      currentManager.scans++;
      currentManager
          .addEventDetail('scan',
                          false,
                          Date.parse(time[0]) - currentManager.startTime);
      return 'basic';
    }
  },
  'scandone': {
    re: / ScanDone/,
    handler: function(processingState, result) {
      var currentManager = processingState.currentManager;
      var time = processingState.time;
      currentManager
          .addEventDetail('scan',
                          true,
                          Date.parse(time[0]) - currentManager.startTime);
      return 'basic';
    }
  },
  'ap_scan': {
    re: /\]: (.*AP scan.*)/,
    handler: function(processingState, result) {
      var currentManager = processingState.currentManager;
      var time = processingState.time;
      logHelper.addNote(currentManager, time[0], result[1]);
      currentManager.scans++;
      return 'basic';
    }
  },
  'auth_timed_out': {
    re: /Event.*AUTH_TIMED_OUT.*/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[0]);
      return 'basic';
    }
  },
  'added_bssid': {
    re: /Added BSSID.*/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[0]);
      return 'basic';
    }
  },
  'event_disconnected': {
    re: /\]: (.*CTRL-EVENT-DISCONNECTED.*)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'wpa_rx': {
    re: /\]: (.*WPA: RX.*)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'wpa_tx': {
    re: /\]: (.*WPA: Sending.*)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'wpa_group_rekey': {
    re: /\]: (.*WPA: Group rekeying.*)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'skip_roam': {
    re: /\]: (.*Skip roam.*)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'connectivity_test': {
    re: /\)\] (.*ConnectivityTest.*)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'deauth_event': {
    re: /\]: (.*Event DEAUTH.*)/,
    handler: function(processingState, result) {
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'disconnect_reason': {
    re: /\] (.*DisconnectReason to (-?\d*)( \(was (-?\d*)\))?)/,
    handler: function(processingState, result) {
      // new reason code at result[2] old reason (if applicable) result[4]
      logHelper.addNote(processingState.currentManager,
                        processingState.time[0],
                        result[1]);
      return 'basic';
    }
  },
  'supplicant_state': {
    re: / wpa_supplicant\[?.*\]?: .*: State: (.*) -> (.*)/,
    handler: function(processingState, result) {
      var oldState = result[1].toUpperCase();
      var newState = result[2].toUpperCase();
      var updateTimestamp = processingState.time[0];
      var elapsedTime = Date.parse(updateTimestamp) -
          processingState.currentManager.startTime;
      var update = {oldState: oldState,
                    newState: newState,
                    time: elapsedTime};
      var supplicantStates = processingState.currentManager.supplicantStates;
      // With shill logs we can assume the first supplicant state is the state
      // from the start of this log.  Add a start point at the elapsed time '0'
      // for the old state in this update.
      if (supplicantStates.length == 0) {
        var initialState = {newState: oldState, time: null};
        logHelper.addState(supplicantStates, initialState);
      }
      logHelper.addState(supplicantStates, update);
      logHelper.addNote(processingState.currentManager,
                        updateTimestamp,
                        result[0]);
      return 'supplicant';
    }
  },
  'eap_state': {
    re: / EAP: EAP entering state (.*)/,
    handler: function(processingState, result) {
      var oldState = 'UNKNOWN'
      var newState = result[1].toUpperCase();
      var updateTimestamp = processingState.time[0];
      var elapsedTime = Date.parse(updateTimestamp) -
          processingState.currentManager.startTime;
      var statesList = processingState.currentManager.eapStates;
      if (statesList.length == 0) {
        var initialState = {newState: oldState, time: null};
        logHelper.addState(statesList, initialState);
      } else {
        oldState = statesList[statesList.length - 1].y;
      }
      var update = {oldState: oldState,
                    newState: newState,
                    time: elapsedTime};
      logHelper.addState(statesList, update);
      return 'eap';
    }
  }
};



/**
 * Helper method checking if a given service state is active.
 *
 * @param {String} state Service state to check.
 * @return {boolean} returns true if the state is considered active
 */
netlogSummary.isActive = function(state) {
  if (state == 'Associating' ||
      state == 'Configuring' ||
      state == 'Connected' ||
      state == 'Online' ||
      state == 'Portal' ||
      state == 'Failure') {
    return true;
  }
  return false;
};

/**
 * This method processes each log line in the supplied String array.  Each log
 * line is checked to see if matches one of the regular expressions from the
 * logHelper.  Each flagged log line is then processed and adds state to the
 * associated manager or service.  If the method does not find an appropriate
 * start for the net.log portion of the log, it will make a second pass and
 * attempt to parse the entire file as a net.log file.
 *
 * @param {String[]} logLines String array for lines in a log.
 * @param {LogSummary} logSummary Object to hold processed log state.
 * @return {Object[]} Returns an Object[] of text and anchor labels if the log
 * was processed, null if the log is not a recognized format.
 */
netlogSummary.processLogLines = function(logLines, logSummary) {
  /**
   * Object used for passing state between main processing loop and
   * regeular expression handler functions.
   * @constructor
   * @type {Object}
   * @param {LogSummary} logSummary object holding log state after processing
   * @param {Manager} currentManager object of the current manager in log
   * @param {String} time timestamp of current log line
   * @param {String[]} results results from regex test
   */
  function ProcessingState(logSummary, currentManager, time, results) {
    this.logSummary = logSummary;
    this.currentManager = currentManager;
    this.time = time;
    this.results = results;
  }

  var logStart = -1;
  var time;
  var logText = [];
  var timeCheck;
  var processingState = new ProcessingState(logSummary, null, null, null);
  var logType = 'netlog';

  for (var i = 0; i < logLines.length; i++) {
    // do we have a start time?
    time = logLines[i].match(logHelper.TIME_FORMAT);
    processingState.time = time;
    if (time == null) {
      if (time = logLines[i].match(logHelper.BRILLO_TIME_FORMAT)) {
        time[0] = time[1];
        processingState.time = time;
        logType = 'brillo';
      } else {
        console.log('logline: ', logLines[i]);
        console.log('not a valid time...  continue');
        continue;
      }
    }
    logHelper.getOffsetMS(time);
    timeCheck = Date.parse(time[0]);
    if (logStart == -1 && time !== null) {
      logStart = time[0];
      logSummary.logStartTime = timeCheck;
      logSummary.prevLogLineTime = logSummary.logStartTime;
      if (logSummary.managers.length == 0 &&
          !logLines[i].match(netlogSummary.taggedLines['new_manager'].re)) {
        //need to add default manager
        processingState.currentManager =
            new Manager(1,
                        logSummary.logStartTime,
                        logHelper.getOffsetMS(time));
        logSummary.managers.push(processingState.currentManager);
      }
    }
    if (timeCheck < logSummary.logEndTime) {
      console.log('warning: log time has rolled back, check timezone');
    } else {
      logSummary.logEndTime = timeCheck;
      logSummary.prevLogLineTime = timeCheck;
    }
    console.log('log_line: ' + logLines[i]);
    var tempLogText = {text: logLines[i],
                       tag: null,
                       type: 'basic',
                       file: logType,
                       ts: timeCheck};
    for (var taggedLine in netlogSummary.taggedLines) {
      var result = logLines[i].match(netlogSummary.taggedLines[taggedLine].re);
      if (result !== null) {
        tempLogText.type =
            netlogSummary.taggedLines[taggedLine].handler(processingState,
                                                          result);
        tempLogText.tag = time[0];
        break;
      }
    }

    logText.push(tempLogText);
  }

  if (logSummary.managers.length == 0) {
    console.log('Valid netlog not found.');
    return null;
  }

  console.log('this is the end of our log...');
  logSummary.managers[logSummary.managers.length - 1].endTime =
      logSummary.logEndTime;

  return logText;
};

/**
 * This method processes each log line in the supplied String array to determine
 * if the log is a netlog.
 *
 * @param {String[]} logLines String array for lines in a log.
 * @return {boolean} Returns true is the log is a netlog, false otherwise.
 */
netlogSummary.netlogTypeCheck = function(logLines) {
  for (var i = 0; i < logLines.length; i++) {
    if (netlogSummary.taggedLines['service_state'].re.test(logLines[i]) &&
        logHelper.TIME_FORMAT.test(logLines[i])) {
      return true;
    }
  }
  return false;
};

/**
 * This method processes each log line in the supplied String array to determine
 * if the log is a brillolog.
 *
 * @param {String[]} logLines String array for lines in a log.
 * @return {boolean} Returns true is the log is a netlog, false otherwise.
 */
netlogSummary.brillologTypeCheck = function(logLines) {
  for (var i = 0; i < logLines.length; i++) {
    if (netlogSummary.taggedLines['service_state'].re.test(logLines[i]) &&
        logHelper.BRILLO_TIME_FORMAT.test(logLines[i])) {
      return true;
    }
  }
  return false;
};