Instrumentation

Bug: T243364
Change-Id: I8573993db0dad408f09202e548206b009c106cc9

extension.json

@@ -55,7 +55,8 @@
 			"dependencies": [
 				"rangefix",
 				"ext.discussionTools.parser",
-				"ext.discussionTools.modifier"
+				"ext.discussionTools.modifier",
+				"ext.discussionTools.logger"
 			],
 			"messages": [
 				"discussiontools-error-comment-disappeared",
@@ -64,6 +65,14 @@
 				"discussiontools-replywidget-loading"
 			]
 		},
+		"ext.discussionTools.logger": {
+			"packageFiles": [
+				"logger.js"
+			],
+			"dependencies": [
+				"mediawiki.util"
+			]
+		},
 		"ext.discussionTools.init": {
 			"packageFiles": [
 				"dt.init.js"
@@ -100,6 +109,7 @@
 			],
 			"dependencies": [
 				"ext.discussionTools.controller",
+				"ext.discussionTools.logger",
 				"mediawiki.widgets.AbandonEditDialog"
 			]
 		},

modules/controller.js

@@ -3,6 +3,7 @@
 var
 	parser = require( 'ext.discussionTools.parser' ),
 	modifier = require( 'ext.discussionTools.modifier' ),
+	logger = require( 'ext.discussionTools.logger' ),
 	pageDataCache = {},
 	$pageContainer,
 	scrollPadding = { top: 10, bottom: 10 },
@@ -26,6 +27,16 @@ function setupComment( comment ) {
 		.on( 'click', function () {
 			var $link = $( this );
 
+			logger( {
+				action: 'init',
+				type: 'page',
+				mechanism: 'click',
+				// TODO: when we have actual visual mode, this needs to do better at
+				// working out which will be used:
+				// eslint-disable-next-line camelcase
+				editor_interface: config.useVisualEditor ? 'wikitext-2017' : 'wikitext'
+			} );
+
 			$link.addClass( 'dt-init-replylink-active' );
 			// TODO: Allow users to use multiple reply widgets simlutaneously
 			// Currently as all widgets share the same Parsoid doc, this could
@@ -55,6 +66,11 @@ function setupComment( comment ) {
 				}, function () {
 					$link.removeClass( 'dt-init-replylink-active' );
 					$pageContainer.removeClass( 'dt-init-replylink-open' );
+
+					logger( {
+						action: 'abort',
+						type: 'preinit'
+					} );
 				} );
 			}
 			widgetPromise.then( function ( replyWidget ) {
@@ -62,6 +78,9 @@ function setupComment( comment ) {
 				replyWidget.setup();
 				replyWidget.scrollElementIntoView( { padding: scrollPadding } );
 				replyWidget.focus();
+
+				logger( { action: 'ready' } );
+				logger( { action: 'loaded' } );
 			} );
 		} );
 

modules/dt.ui.ReplyWidget.js

@@ -1,5 +1,6 @@
 var controller = require( 'ext.discussionTools.controller' ),
-	modifier = require( 'ext.discussionTools.modifier' );
+	modifier = require( 'ext.discussionTools.modifier' ),
+	logger = require( 'ext.discussionTools.logger' );
 
 /**
  * DiscussionTools ReplyWidget class
@@ -132,9 +133,19 @@ ReplyWidget.prototype.tryTeardown = function () {
 				if ( !( data && data.action === 'discard' ) ) {
 					return $.Deferred().reject().promise();
 				}
+				logger( {
+					action: 'abort',
+					mechanism: 'cancel',
+					type: 'abandon'
+				} );
 			} );
 	} else {
 		promise = $.Deferred().resolve().promise();
+		logger( {
+			action: 'abort',
+			mechanism: 'cancel',
+			type: 'nochange'
+		} );
 	}
 	promise.then( function () {
 		widget.teardown();
@@ -201,6 +212,10 @@ ReplyWidget.prototype.onInputChange = function () {
 	} );
 };
 
+ReplyWidget.prototype.onFirstTransaction = function () {
+	logger( { action: 'firstChange' } );
+};
+
 /**
  * Bind the beforeunload handler, if needed and if not already bound.
  *
@@ -250,8 +265,12 @@ ReplyWidget.prototype.onReplyClick = function () {
 
 	this.setPending( true );
 
+	logger( { action: 'saveIntent' } );
+
 	// We must get a new copy of the document every time, otherwise any unsaved replies will pile up
 	this.getParsoidCommentData().then( function ( parsoidData ) {
+		logger( { action: 'saveAttempt' } );
+
 		return controller.postReply( widget, parsoidData );
 	} ).catch( function ( code, data ) {
 		// Handle edit conflicts. Load the latest revision of the page, then try again. If the parent
@@ -300,12 +319,45 @@ ReplyWidget.prototype.onReplyClick = function () {
 			repliedTo: widget.comment.id
 		} );
 		mw.hook( 'wikipage.content' ).fire( $container );
+
+		logger( {
+			action: 'saveSuccess',
+			// eslint-disable-next-line camelcase
+			revision_id: data.newrevid
+		} );
 	}, function ( code, data ) {
+		var typeMap = {
+			// Compare to ve.init.mw.ArticleTargetEvents.js in VisualEditor.
+			editconflict: 'editConflict',
+			wasdeleted: 'editPageDeleted',
+			abusefilter: 'extensionAbuseFilter',
+			'abusefilter-disallowed': 'extensionAbuseFilter',
+			captcha: 'extensionCaptcha',
+			spamprotectiontext: 'extensionSpamBlacklist',
+			titleblacklist: 'extensionTitleBlacklist',
+			'titleblacklist-forbidden-edit': 'extensionTitleBlacklist',
+			badtoken: 'userBadToken',
+			newuser: 'userNewUser',
+			spamblacklist: 'extensionSpamBlacklist',
+			empty: 'responseEmpty',
+			unknown: 'responseUnknown',
+			pagedeleted: 'editPageDeleted'
+		};
+
 		widget.errorMessage = new OO.ui.MessageWidget( {
 			type: 'error',
 			label: widget.api.getErrorMessage( data )
 		} );
 		widget.errorMessage.$element.insertBefore( widget.replyBodyWidget.$element );
+
+		if ( data.edit && data.edit.captcha ) {
+			code = 'captcha';
+		}
+		logger( {
+			action: 'saveFailure',
+			message: code,
+			type: typeMap[ code ] || 'responseUnknown'
+		} );
 	} ).always( function () {
 		widget.setPending( false );
 	} );

modules/dt.ui.ReplyWidgetPlain.js

@@ -55,6 +55,13 @@ ReplyWidgetPlain.prototype.isEmpty = function () {
 	return !this.replyBodyWidget.getValue().trim();
 };
 
+ReplyWidgetPlain.prototype.setup = function () {
+	// Parent method
+	ReplyWidgetPlain.super.prototype.setup.call( this );
+
+	this.replyBodyWidget.once( 'change', this.onFirstTransaction.bind( this ) );
+};
+
 ReplyWidgetPlain.prototype.onKeyDown = function ( e ) {
 	// Parent method
 	ReplyWidgetPlain.super.prototype.onKeyDown.call( this, e );

modules/dt.ui.ReplyWidgetVisual.js

@@ -54,7 +54,8 @@ ReplyWidgetVisual.prototype.setup = function () {
 	this.mode = this.replyBodyWidget.target.getSurface().getMode();
 
 	// Events
-	this.replyBodyWidget.target.getSurface().getModel().getDocument().connect( this, { transact: this.onInputChangeThrottled } );
+	this.replyBodyWidget.target.getSurface().getModel().getDocument().connect( this, { transact: this.onInputChangeThrottled } )
+		.once( 'transact', this.onFirstTransaction.bind( this ) );
 	this.replyBodyWidget.target.getSurface().connect( this, { submit: 'onReplyClick' } );
 };
 

modules/logger.js

@@ -0,0 +1,187 @@
+'use strict';
+
+var trackdebug = !!mw.util.getParamValue( 'trackdebug' );
+
+/**
+ * Logs an event to http://meta.wikimedia.org/wiki/Schema:EditAttemptStep
+ * @instance
+ * @param {Object} data
+ */
+module.exports = function ( data ) {
+	mw.track( 'dt.schemaEditAttemptStep', data );
+};
+
+// Ensure 'ext.eventLogging' first, it provides mw.eventLog.randomTokenMatch.
+// (No explicit dependency is set because we want this to just quietly not-happen
+// if EventLogging isn't installed.)
+mw.loader.using( 'ext.eventLogging' ).done( function () {
+	var // Schema class is provided by ext.eventLogging
+		Schema = mw.eventLog.Schema,
+		user = mw.user,
+		sampleRate = mw.config.get( 'wgWMESchemaEditAttemptStepSamplingRate' ),
+		actionPrefixMap = {
+			firstChange: 'first_change',
+			saveIntent: 'save_intent',
+			saveAttempt: 'save_attempt',
+			saveSuccess: 'save_success',
+			saveFailure: 'save_failure'
+		},
+		timing = {},
+		session = {},
+		/**
+		 * Edit schema
+		 * https://meta.wikimedia.org/wiki/Schema:EditAttemptStep
+		 */
+		/* eslint-disable camelcase */
+		schemaEditAttemptStep = new Schema(
+			'EditAttemptStep',
+			sampleRate,
+			// defaults:
+			{
+				page_id: mw.config.get( 'wgArticleId' ),
+				revision_id: mw.config.get( 'wgRevisionId' ),
+				page_title: mw.config.get( 'wgPageName' ),
+				page_ns: mw.config.get( 'wgNamespaceNumber' ),
+				user_id: user.getId(),
+				user_class: user.isAnon() ? 'IP' : undefined,
+				user_editcount: mw.config.get( 'wgUserEditCount', 0 ),
+				mw_version: mw.config.get( 'wgVersion' ),
+				platform: 'desktop',
+				integration: 'page',
+				page_token: user.getPageviewToken(),
+				session_token: user.sessionId(),
+				version: 1
+			}
+		);
+		/* eslint-enable camelcase */
+
+	function log() {
+		// mw.log is a no-op unless resource loader is in debug mode, so
+		// this allows trackdebug to work independently
+		// eslint-disable-next-line no-console
+		console.log.apply( console, arguments );
+	}
+
+	function computeDuration( action, event, timeStamp ) {
+		// This is duplicated from the VisualEditor extension
+		// (ve.init.mw.trackSubscriber.js). Changes to this should be kept in
+		// sync with that file, so the data remains consistent.
+		if ( event.timing !== undefined ) {
+			return event.timing;
+		}
+
+		switch ( action ) {
+			case 'ready':
+				return timeStamp - timing.init;
+			case 'loaded':
+				return timeStamp - timing.init;
+			case 'firstChange':
+				return timeStamp - timing.ready;
+			case 'saveIntent':
+				return timeStamp - timing.ready;
+			case 'saveAttempt':
+				return timeStamp - timing.saveIntent;
+			case 'saveSuccess':
+			case 'saveFailure':
+				// HERE BE DRAGONS: the caller must compute these themselves
+				// for sensible results. Deliberately sabotage any attempts to
+				// use the default by returning -1
+				mw.log.warn( 'dt.schemaEditAttemptStep: Do not rely on default timing value for saveSuccess/saveFailure' );
+				return -1;
+			case 'abort':
+				switch ( event.abort_type ) {
+					case 'preinit':
+						return timeStamp - timing.init;
+					case 'nochange':
+					case 'switchwith':
+					case 'switchwithout':
+					case 'switchnochange':
+					case 'abandon':
+						return timeStamp - timing.ready;
+					case 'abandonMidsave':
+						return timeStamp - timing.saveAttempt;
+				}
+				mw.log.warn( 'dt.schemaEditAttemptStep: Unrecognized abort type', event.type );
+				return -1;
+		}
+		mw.log.warn( 'dt.schemaEditAttemptStep: Unrecognized action', action );
+		return -1;
+	}
+
+	mw.trackSubscribe( 'dt.schemaEditAttemptStep', function ( topic, data ) {
+		var actionPrefix = actionPrefixMap[ data.action ] || data.action,
+			timeStamp = mw.now(),
+			duration = 0;
+
+		// Update the rolling session properties
+		if ( data.action === 'init' ) {
+			// eslint-disable-next-line camelcase
+			session.editing_session_id = mw.user.generateRandomSessionId();
+		}
+		// eslint-disable-next-line camelcase
+		session.editor_interface = data.editor_interface || session.editor_interface;
+
+		// Schema's kind of a mess of special properties
+		if ( data.action === 'init' || data.action === 'abort' || data.action === 'saveFailure' ) {
+			data[ actionPrefix + '_type' ] = data.type;
+		}
+		if ( data.action === 'init' || data.action === 'abort' ) {
+			data[ actionPrefix + '_mechanism' ] = data.mechanism;
+		}
+		if ( data.action !== 'init' ) {
+			// Schema actually does have an init_timing field, but we don't want to
+			// store it because it's not meaningful.
+			duration = Math.round( computeDuration( data.action, data, timeStamp ) );
+			data[ actionPrefix + '_timing' ] = duration;
+		}
+		if ( data.action === 'saveFailure' ) {
+			data[ actionPrefix + '_message' ] = data.message;
+		}
+
+		// Remove renamed properties
+		delete data.type;
+		delete data.mechanism;
+		delete data.timing;
+		delete data.message;
+		// eslint-disable-next-line camelcase
+		data.is_oversample =
+			!mw.eventLog.inSample( 1 / sampleRate );
+
+		if ( data.action === 'abort' && data.abort_type !== 'switchnochange' ) {
+			timing = {};
+		} else {
+			timing[ data.action ] = timeStamp;
+		}
+
+		// Switching between visual and source produces a chain of
+		// abort/ready/loaded events and no init event, so suppress them for
+		// consistency with desktop VE's logging.
+		if ( data.abort_type === 'switchnochange' ) {
+			// The initial abort, flagged as a switch
+			return;
+		}
+		if ( timing.abort ) {
+			// An abort was previously logged
+			if ( data.action === 'ready' ) {
+				// Just discard the ready
+				return;
+			}
+			if ( data.action === 'loaded' ) {
+				// Switch has finished; remove the abort timing so we stop discarding events.
+				delete timing.abort;
+				return;
+			}
+		}
+
+		$.extend( data, session );
+
+		if ( trackdebug ) {
+			log( topic + '.' + data.action, duration + 'ms', data, schemaEditAttemptStep.defaults );
+		} else {
+			schemaEditAttemptStep.log(
+				data,
+				mw.config.get( 'wgWMESchemaEditAttemptStepOversample' ) ? 1 : sampleRate
+			);
+		}
+	} );
+} );