diff --git a/common/models/change.js b/common/models/change.js index e2bd6030..d21bfaf9 100644 --- a/common/models/change.js +++ b/common/models/change.js @@ -446,10 +446,13 @@ module.exports = function(Change) { Change.prototype.debug = function() { if (debug.enabled) { var args = Array.prototype.slice.call(arguments); + args[0] = args[0] + ' %s'; + args.push(this.modelName); debug.apply(this, args); debug('\tid', this.id); debug('\trev', this.rev); debug('\tprev', this.prev); + debug('\tcheckpoint', this.checkpoint); debug('\tmodelName', this.modelName); debug('\tmodelId', this.modelId); debug('\ttype', this.type()); diff --git a/lib/persisted-model.js b/lib/persisted-model.js index d87d72e0..4e91a545 100644 --- a/lib/persisted-model.js +++ b/lib/persisted-model.js @@ -8,6 +8,7 @@ var runtime = require('./runtime'); var assert = require('assert'); var async = require('async'); var deprecated = require('depd')('loopback'); +var debug = require('debug')('loopback:persisted-model'); /** * Extends Model with basic query and CRUD support. @@ -855,6 +856,15 @@ PersistedModel.replicate = function(since, targetModel, options, callback) { if (err) throw err; }; + debug('replicating %s since %s to %s since %s', + sourceModel.modelName, + since.source, + targetModel.modelName, + since.target); + if (options.filter) { + debug('\twith filter %j', options.filter); + } + var tasks = [ checkpoints, getSourceChanges, @@ -866,17 +876,38 @@ PersistedModel.replicate = function(since, targetModel, options, callback) { async.waterfall(tasks, done); function getSourceChanges(cb) { - sourceModel.changes(since.source, options.filter, cb); + sourceModel.changes(since.source, options.filter, debug.enabled ? log : cb); + + function log(err, result) { + if (err) return cb(err); + debug('\tusing source changes'); + result.forEach(function(it) { debug('\t\t%j', it); }); + cb(err, result); + } } function getDiffFromTarget(sourceChanges, cb) { - targetModel.diff(since.target, sourceChanges, cb); + targetModel.diff(since.target, sourceChanges, debug.enabled ? log : cb); + + function log(err, result) { + if (err) return cb(err); + if (result.conflicts && result.conflicts.length) { + debug('\tdiff conflicts'); + result.conflicts.forEach(function(d) { debug('\t\t%j', d); }); + } + if (result.deltas && result.deltas.length) { + debug('\tdiff deltas'); + result.deltas.forEach(function(it) { debug('\t\t%j', it); }); + } + cb(err, result); + } } function createSourceUpdates(_diff, cb) { diff = _diff; diff.conflicts = diff.conflicts || []; if (diff && diff.deltas && diff.deltas.length) { + debug('\tbuilding a list of updates'); sourceModel.createUpdates(diff.deltas, cb); } else { // nothing to replicate @@ -884,7 +915,9 @@ PersistedModel.replicate = function(since, targetModel, options, callback) { } } - function bulkUpdate(updates, cb) { + function bulkUpdate(_updates, cb) { + debug('\tstarting bulk update'); + updates = _updates; targetModel.bulkUpdate(updates, cb); } @@ -894,6 +927,9 @@ PersistedModel.replicate = function(since, targetModel, options, callback) { newSourceCp = source.seq; targetModel.checkpoint(function(err, target) { newTargetCp = target.seq; + debug('\tcreated checkpoints'); + debug('\t\t%s for source model %s', newSourceCp, sourceModel.modelName); + debug('\t\t%s for target model %s', newTargetCp, targetModel.modelName); cb(err); }); }); @@ -902,6 +938,12 @@ PersistedModel.replicate = function(since, targetModel, options, callback) { function done(err) { if (err) return callback(err); + debug('\treplication finished'); + debug('\t\t%s conflict(s) detected', diff.conflicts.length); + debug('\t\t%s change(s) applied', updates && updates.length); + debug('\t\tnew checkpoints: { source: %j, target: %j }', + newSourceCp, newTargetCp); + var conflicts = diff.conflicts.map(function(change) { return new Change.Conflict( change.modelId, sourceModel, targetModel