| // 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; |
| }; |
| |