/*! * Extremely detailed logging of function calls and state changes * * @copyright See AUTHORS.txt */ /** * A scrupulous event logger that logs state at every function call, and * shortlists potentially significant observations for strict scrutiny. * * Functions are wrapped to log entry/exit. This creates a comprehensive log of * every watched function call (typically thousands per keystroke), together * with the corresponding call stack. * * Observer callbacks can be registered to watch certain global values (e.g. * the DOM/DM content and selection). These at every watched function * entry/exit, and when there is a change (typically a few times per keystroke), * an observation is logged. Each observation shows the state change and call * stack, and has a log number that points into the full call log. * * Function wrapping generally takes place after object initialization. * That means property lookups that have already happened (e.g. through * .bind or setTimeout in a constructor) will not pass through the wrapper. * * This code is inspired by United States v. Carolene Products Company, 304 * U.S. 144 (1938), Footnote Four. * * @class ve.Filibuster */ /** * @constructor * @param {string[]} eventNames List of event names to listen to */ ve.Filibuster = function VeFilibuster() { this.count = 0; this.states = {}; this.observers = {}; // Tree of call frames this.callTree = { children: [] }; // Current call frame this.frame = this.callTree; // Path (index offsets) to current call frame this.callPath = []; // Index offset tree: { // changes: {enter: xxx, exit: xxx } // children: { index offset tree } // } this.observationTree = { children: {} }; this.active = false; this.startTime = null; }; OO.initClass( ve.Filibuster ); /** * Clears logs, without detaching observers */ ve.Filibuster.prototype.clearLogs = function () { this.count = 0; for ( const name in this.states ) { delete this.states[ name ]; } this.observationTree.children = {}; this.callTree.children.length = 0; this.frame = this.callTree; this.callPath.length = 0; }; /** * Attaches an observer callback. The callback returns a value representing the current state, * which must be a string (this ensures state values are immutable, comparable with strict * equality and easily dumpable). * * The observer will be called before and after every function call. An observation is logged * every time there is a difference between the current return value and the previous one. * * @param {string} name The name of the observer, for display in the logs. * @param {Function} callback The callback; must return a string * @return {ve.Filibuster} * @chainable */ ve.Filibuster.prototype.setObserver = function ( name, callback ) { this.observers[ name ] = callback; return this; }; /** * Calls each observer, logging an observation if a change is detected. Called at the start * and end of every monitored function call. * * @param {string} action The function call phase: call|return|throw */ ve.Filibuster.prototype.observe = function ( action ) { const changes = {}; for ( const name in this.observers ) { const callback = this.observers[ name ]; const oldState = this.states[ name ]; let newState; try { newState = callback(); } catch ( ex ) { newState = 'Error: ' + ex; } if ( typeof newState !== 'string' ) { // Be strict about the allowed types, to ensure immutability ve.error( 'Illegal state:', newState ); throw new Error( 'Illegal state: ' + newState ); } if ( this.states[ name ] !== newState ) { if ( Object.prototype.hasOwnProperty.call( this.states, name ) ) { // State change: write observation changes[ name ] = { oldState: oldState, newState: newState }; } this.states[ name ] = newState; } } // Save any changes into observations tree if ( Object.keys( changes ).length > 0 ) { // Navigate along tree branch, creating as necessary let ptr = this.observationTree; for ( let j = 0, jLen = this.callPath.length; j < jLen; j++ ) { const offset = this.callPath[ j ]; if ( !ptr.children ) { ptr.children = {}; } if ( !ptr.children[ offset ] ) { ptr.children[ offset ] = {}; } ptr = ptr.children[ offset ]; } if ( !ptr.changes ) { ptr.changes = {}; } if ( action === 'call' ) { ptr.changes.enter = changes; } else { ptr.changes.exit = changes; } } }; /** * Log a function call. Called at the start and end of every monitored function call. * * @param {string} funcName The name of the function * @param {string} action The function call phase: call|return|throw * @param {Array} [args] The call arguments (if action === 'call') * @param {any} [returned] The return value (if action === 'return') */ ve.Filibuster.prototype.log = function ( funcName, action, args, returned ) { if ( !this.active ) { return; } const time = ve.now() - this.startTime; if ( action === 'call' ) { // Descend down the call tree (adding a new frame) // Store arguments as a cloned plain object, to avoid anachronistic changes and // for easy display. const parentFrame = this.frame; if ( !parentFrame.children ) { parentFrame.children = []; } this.callPath.push( parentFrame.children.length ); this.frame = { count: this.count++, funcName: funcName, args: this.constructor.static.clonePlain( args ), // returned: xxx, // thrown: xxx start: time, // end: xxx, // children: xxx, parent: parentFrame }; parentFrame.children.push( this.frame ); } this.observe( action, time ); if ( action === 'return' || action === 'throw' ) { // Check funcName, store values, ascend call tree if ( this.frame.funcName === undefined ) { throw new Error( 'No call logged, but leaving "' + funcName + '" (' + action + ')' ); } if ( this.frame.funcName !== funcName ) { throw new Error( 'Logged call to "' + this.frame.funcName + '"' + ' but leaving "' + funcName + '" (' + action + ')' ); } this.frame.end = time; if ( action === 'return' ) { this.frame.returned = this.constructor.static.clonePlain( returned ); } else if ( action === 'throw' ) { this.frame.thrown = true; } this.frame = this.frame.parent; this.callPath.pop(); } }; /** * Replace a reference to a function with a wrapper that performs logging. * * Note that the same function can be referenced multiple times; each reference would * need wrapping separately. * * @param {Object} container The container with the function as a property * @param {string} klassName The name of the container, for display in the logs * @param {string} fnName The property name of the function in the container * @return {ve.Filibuster} * @chainable */ ve.Filibuster.prototype.wrapFunction = function ( container, klassName, fnName ) { const filibuster = this, fullName = ( klassName || 'unknown' ) + '.' + fnName; const fn = container[ fnName ]; const wrapper = function () { let returnVal, fnReturned = false; filibuster.log( fullName, 'call', Array.prototype.slice.call( arguments ), undefined ); try { returnVal = fn.apply( this, arguments ); fnReturned = true; filibuster.log( fullName, 'return', undefined, returnVal ); return returnVal; } finally { if ( !fnReturned ) { // Can't easily get the error without affecting the call stack filibuster.log( fullName, 'throw', undefined, undefined ); } } }; wrapper.wrappedFunction = fn; container[ fnName ] = wrapper; return this; }; /** * Wrap the functions in a class with wrappers that perform logging. * * @param {Object} klass The class with the function as a property * @param {Function[]} [nowrapList] Functions that should not be wrapped * @return {ve.Filibuster} * @chainable */ ve.Filibuster.prototype.wrapClass = function ( klass, nowrapList ) { const container = klass.prototype; const fnNames = Object.getOwnPropertyNames( container ); for ( let i = 0, len = fnNames.length; i < len; i++ ) { const fnName = fnNames[ i ]; if ( fnName === 'prototype' || fnName === 'constructor' ) { continue; } const fn = container[ fnName ]; if ( typeof fn !== 'function' || fn.wrappedFunction ) { continue; } if ( nowrapList && nowrapList.indexOf( fn ) !== -1 ) { continue; } this.wrapFunction( container, klass.name, fnName ); } return this; }; /** * Recursively wrap the functions in a namespace with wrappers that perform logging. * * @param {Object} ns The namespace whose functions should be wrapped * @param {string} nsName The name of the namespace, for display in logs * @param {Function[]} [nowrapList] Functions that should not be wrapped * @return {ve.Filibuster} * @chainable */ ve.Filibuster.prototype.wrapNamespace = function ( ns, nsName, nowrapList ) { const propNames = Object.getOwnPropertyNames( ns ); for ( let i = 0, len = propNames.length; i < len; i++ ) { const propName = propNames[ i ]; const prop = ns[ propName ]; if ( nowrapList && nowrapList.indexOf( prop ) !== -1 ) { continue; } const isConstructor = ( typeof prop === 'function' && !ve.isEmptyObject( prop.prototype ) ); if ( isConstructor ) { this.wrapClass( prop, nowrapList ); } else if ( typeof prop === 'function' ) { this.wrapFunction( ns, nsName, propName ); } else if ( $.isPlainObject( prop ) ) { // Might be a namespace; recurse this.wrapNamespace( prop, nsName + '.' + propName, nowrapList ); } } return this; }; /** * Start logging */ ve.Filibuster.prototype.start = function () { this.active = true; this.startTime = ve.now(); }; /** * Stop logging */ ve.Filibuster.prototype.stop = function () { this.active = false; }; /** * Get an HTML representation of part of the call tree, opened at each observation * * In general, building HTML fragments like this is ugly; but this turns out to give * better performance if the HTML representation is really large. * * @param {number[]} [branchPath] Path to the part of the tree to represent * @return {string} HTML representation */ ve.Filibuster.prototype.getObservationsHtml = function ( branchPath ) { function showArgs( args ) { return '(' + ve.escapeHtml( args.map( ( arg ) => JSON.stringify( arg ) ).join( ', ' ) ) + ')'; } function showVal( val ) { return ve.escapeHtml( JSON.stringify( val ) ); } function showChanges( changes, phase ) { return ( ( phase === 'enter' ? '