jenkins-bot has submitted this change and it was merged. (
https://gerrit.wikimedia.org/r/344730 )
Change subject: Add logging to the rebase server and client
......................................................................
Add logging to the rebase server and client
RebaseServer and RebaseClient log events, but the log events go nowhere
unless captured. SurfaceSynchronizer caputures client events and
sends them to the server; server.js captures server and client events
and writes them to a log file.
Change-Id: Iab06a12d58ad315b269e53e6d49f0b5e04759f36
---
M .gitignore
M rebaser/server.js
M src/dm/ve.dm.RebaseClient.js
M src/dm/ve.dm.RebaseServer.js
M src/dm/ve.dm.SurfaceSynchronizer.js
5 files changed, 113 insertions(+), 53 deletions(-)
Approvals:
Divec: Looks good to me, approved
jenkins-bot: Verified
diff --git a/.gitignore b/.gitignore
index aa8e939..3b2ae48 100644
--- a/.gitignore
+++ b/.gitignore
@@ -12,6 +12,7 @@
/docs
node_modules
npm-debug.log
+rebaser/rebaser.log
# OS
.DS_Store
diff --git a/rebaser/server.js b/rebaser/server.js
index fb15bbb..378000e 100644
--- a/rebaser/server.js
+++ b/rebaser/server.js
@@ -1,40 +1,36 @@
/* eslint-disable no-console */
-var rebaseServer, docNamespaces, lastAuthorForDoc, artificialDelay,
+var rebaseServer, artificialDelay, logStream,
port = 8081,
+ fs = require( 'fs' ),
express = require( 'express' ),
app = express(),
url = require( 'url' ),
http = require( 'http' ).Server( app ),
io = require( 'socket.io' )( http ),
- ve = require( '../dist/ve-rebaser.js' );
+ ve = require( '../dist/ve-rebaser.js' ),
+ docNamespaces = new Map(),
+ lastAuthorForDoc = new Map();
-function summarize( author, backtrack, change ) {
- var storeCount = 0,
- summary = [];
- summary.push( 'author=' + author );
- if ( backtrack ) {
- summary.push( 'backtrack ' + backtrack );
+function logEvent( event ) {
+ if ( !logStream ) {
+ logStream = fs.createWriteStream( 'rebaser.log', { flags: 'a' }
);
}
- if ( change.getLength() ) {
- summary.push( change.getLength() + ' transactions (start ' +
change.start + ')' );
- }
- console.log( 'change=', change );
- change.stores.forEach( function ( store ) {
- storeCount += store.getLength();
- } );
- if ( storeCount > 0 ) {
- summary.push( storeCount + ' stored values' );
- }
- Object.keys( change.selections ).forEach( function ( author ) {
- summary.push( 'selection ' + author + ':' + change.selections[
author ].getDescription() );
- } );
- return summary.join( ', ' );
+ logStream.write( JSON.stringify( event ) + '\n' );
}
-rebaseServer = new ve.dm.RebaseServer();
-docNamespaces = new Map();
-lastAuthorForDoc = new Map();
+function logServerEvent( event ) {
+ var key;
+ for ( key in event ) {
+ if ( event[ key ] instanceof ve.dm.Change ) {
+ event[ key ] = event[ key ].serialize( true );
+ }
+ }
+ event.clientId = 'server';
+ logEvent( event );
+}
+
+rebaseServer = new ve.dm.RebaseServer( logServerEvent );
artificialDelay = parseInt( process.argv[ 2 ] ) || 0;
function makeConnectionHandler( docName ) {
@@ -42,36 +38,45 @@
var history = rebaseServer.getDocState( docName ).history,
author = 1 + ( lastAuthorForDoc.get( docName ) || 0 );
lastAuthorForDoc.set( docName, author );
- console.log( 'new client ' + author + ' for ' + docName );
+ logServerEvent( {
+ type: 'newClient',
+ doc: docName,
+ author: author
+ } );
socket.emit( 'registered', author );
// HACK Catch the client up on the current state by sending it
the entire history
// Ideally we'd be able to initialize the client using HTML,
but that's hard, see
// comments in the /raw handler. Keeping an updated linmod on
the server could be
// feasible if TransactionProcessor was modified to have a
"don't sync, just apply"
// mode and ve.dm.Document was faked with { data: ...,
metadata: ..., store: ... }
- console.log( 'Sending full history: ' + summarize( null, 0,
history ) );
+ // FIXME this will also cause the client to write the entire
history to the log in
+ // the form of an acceptChange log event
socket.emit( 'newChange', history.serialize( true ) );
socket.on( 'submitChange', setTimeout.bind( null, function (
data ) {
var change, applied;
try {
change = ve.dm.Change.static.deserialize(
data.change, null, true );
- console.log( 'receive ' + summarize( author,
data.backtrack, change ) );
applied = rebaseServer.applyChange( docName,
author, data.backtrack, change );
if ( !applied.isEmpty() ) {
- console.log( 'applied ' + summarize(
author, 0, applied ) );
docNamespaces.get( docName ).emit(
'newChange', applied.serialize( true ) );
- }
- if ( applied.getLength() < change.getLength() )
{
- console.log( author + ' rejected ' + (
applied.getLength() - change.getLength() ) );
}
} catch ( error ) {
console.error( error.stack );
}
}, artificialDelay ) );
+ socket.on( 'logEvent', function ( event ) {
+ event.clientId = author;
+ event.doc = docName;
+ logEvent( event );
+ } );
socket.on( 'disconnect', function () {
var change = rebaseServer.applyUnselect( docName,
author );
docNamespaces.get( docName ).emit( 'newChange',
change.serialize( true ) );
- console.log( 'disconnect', author, docName );
+ logServerEvent( {
+ type: 'disconnect',
+ doc: docName,
+ author: author
+ } );
} );
};
}
diff --git a/src/dm/ve.dm.RebaseClient.js b/src/dm/ve.dm.RebaseClient.js
index f29564f..259cad2 100644
--- a/src/dm/ve.dm.RebaseClient.js
+++ b/src/dm/ve.dm.RebaseClient.js
@@ -29,7 +29,6 @@
* @property {number} backtrack Number of transactions backtracked
(i.e. rejected) since the last send
*/
this.backtrack = 0;
-
};
/* Inheritance */
@@ -85,6 +84,13 @@
*/
ve.dm.RebaseClient.prototype.removeFromHistory = null;
+/**
+ * Add an event to the log. Default implementation does nothing; subclasses
should override this
+ * if they want to collect logs.
+ * @param {Object} event Event data
+ */
+ve.dm.RebaseClient.prototype.logEvent = function () {};
+
/* Methods */
/**
@@ -112,6 +118,14 @@
if ( change.isEmpty() ) {
return;
}
+ // logEvent before sendChange, for the case where the log entry is sent
to the server
+ // over the same tunnel as the change, so that there's no way the
server will log
+ // receiving the change before it receives the submitChange message.
+ this.logEvent( {
+ type: 'submitChange',
+ change: change,
+ backtrack: this.backtrack
+ } );
this.sendChange( this.backtrack, change );
this.backtrack = 0;
this.sentLength += change.getLength();
@@ -132,12 +146,13 @@
* @param {ve.dm.Change} change The committed change from the server
*/
ve.dm.RebaseClient.prototype.acceptChange = function ( change ) {
- var uncommitted, result,
+ var uncommitted, unsent, result,
author = change.firstAuthor();
if ( !author ) {
return;
}
+ unsent = this.getChangeSince( this.sentLength, false );
if ( author !== this.getAuthor() ) {
uncommitted = this.getChangeSince( this.commitLength, false );
result = ve.dm.Change.static.rebaseUncommittedChange( change,
uncommitted );
@@ -162,4 +177,15 @@
this.sentLength += change.getLength();
}
this.commitLength += change.getLength();
+
+ this.logEvent( {
+ type: 'acceptChange',
+ author: author,
+ change: change,
+ unsent: unsent,
+ // The below are undefined if it's our own change
+ rebased: result && result.rebased,
+ transposedHistory: result && result.transposedHistory,
+ rejected: result && result.rejected
+ } );
};
diff --git a/src/dm/ve.dm.RebaseServer.js b/src/dm/ve.dm.RebaseServer.js
index 2baa433..8ffca48 100644
--- a/src/dm/ve.dm.RebaseServer.js
+++ b/src/dm/ve.dm.RebaseServer.js
@@ -9,9 +9,13 @@
* DataModel rebase server
*
* @class
+ *
+ * @constructor
+ * @param {Function} [logCallback]
*/
-ve.dm.RebaseServer = function VeDmRebaseServer() {
+ve.dm.RebaseServer = function VeDmRebaseServer( logCallback ) {
this.stateForDoc = new Map();
+ this.logEvent = logCallback || function () {};
};
OO.initClass( ve.dm.RebaseServer );
@@ -67,7 +71,7 @@
* @return {ve.dm.Change} Accepted change (or initial segment thereof), as
rebased
*/
ve.dm.RebaseServer.prototype.applyChange = function applyChange( doc, author,
backtrack, change ) {
- var base, rejections, result,
+ var base, rejections, result, appliedChange,
state = this.getDocState( doc );
base = state.continueBases.get( author ) || change.truncate( 0 );
@@ -76,25 +80,34 @@
// Follow-on does not fully acknowledge outstanding conflicts:
reject entirely
rejections = rejections - backtrack +
change.transactions.length;
this.updateDocState( doc, author, null, rejections, null );
- return change.truncate( 0 );
- }
- if ( rejections < backtrack ) {
+ appliedChange = change.truncate( 0 );
+ } else if ( rejections < backtrack ) {
throw new Error( 'Backtrack=' + backtrack + ' > ' + rejections
+ '=rejections' );
- }
+ } else {
+ if ( change.start > base.start ) {
+ // Remote has rebased some committed changes into its
history since base was built.
+ // They are guaranteed to be equivalent to the start of
base. See mathematical
+ // docs for proof (Cuius rei demonstrationem mirabilem
sane deteximus hanc marginis
+ // exiguitas non caperet).
+ base = base.mostRecent( change.start );
+ }
+ base = base.concat( state.history.mostRecent( base.start +
base.getLength() ) );
- if ( change.start > base.start ) {
- // Remote has rebased some committed changes into its history
since base was built.
- // They are guaranteed to be equivalent to the start of base.
See mathematical
- // docs for proof (Cuius rei demonstrationem mirabilem sane
deteximus hanc marginis
- // exiguitas non caperet).
- base = base.mostRecent( change.start );
+ result = ve.dm.Change.static.rebaseUncommittedChange( base,
change );
+ rejections = result.rejected ? result.rejected.getLength() : 0;
+ this.updateDocState( doc, author, result.rebased, rejections,
result.transposedHistory );
+ appliedChange = result.rebased;
}
- base = base.concat( state.history.mostRecent( base.start +
base.getLength() ) );
-
- result = ve.dm.Change.static.rebaseUncommittedChange( base, change );
- rejections = result.rejected ? result.rejected.getLength() : 0;
- this.updateDocState( doc, author, result.rebased, rejections,
result.transposedHistory );
- return result.rebased;
+ this.logEvent( {
+ type: 'applyChange',
+ doc: doc,
+ author: author,
+ incoming: change,
+ applied: appliedChange,
+ backtrack: backtrack,
+ rejections: rejections
+ } );
+ return appliedChange;
};
/**
diff --git a/src/dm/ve.dm.SurfaceSynchronizer.js
b/src/dm/ve.dm.SurfaceSynchronizer.js
index dfa9655..4e8e13f 100644
--- a/src/dm/ve.dm.SurfaceSynchronizer.js
+++ b/src/dm/ve.dm.SurfaceSynchronizer.js
@@ -127,6 +127,21 @@
};
/**
+ * @inheritdoc
+ */
+ve.dm.SurfaceSynchronizer.prototype.logEvent = function ( event ) {
+ // Serialize the event data and pass it on to the server for logging
+ var key;
+ for ( key in event ) {
+ if ( event[ key ] instanceof ve.dm.Change ) {
+ event[ key ] = event[ key ].serialize();
+ }
+ }
+
+ this.socket.emit( 'logEvent', event );
+};
+
+/**
* Respond to transactions happening on the document. Ignores transactions
applied by
* SurfaceSynchronizer itself.
*
--
To view, visit https://gerrit.wikimedia.org/r/344730
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: merged
Gerrit-Change-Id: Iab06a12d58ad315b269e53e6d49f0b5e04759f36
Gerrit-PatchSet: 7
Gerrit-Project: VisualEditor/VisualEditor
Gerrit-Branch: master
Gerrit-Owner: Catrope <[email protected]>
Gerrit-Reviewer: Divec <[email protected]>
Gerrit-Reviewer: jenkins-bot <>
_______________________________________________
MediaWiki-commits mailing list
[email protected]
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
