From b381c5df7e065b6dd008e10da54a4a7abff272b1 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Miroslav=20Bajto=C5=A1?= <miroslav@strongloop.com>
Date: Wed, 4 Mar 2015 15:00:53 +0100
Subject: [PATCH] Add more debug logs to replication

---
 common/models/change.js |  3 +++
 lib/persisted-model.js  | 48 ++++++++++++++++++++++++++++++++++++++---
 2 files changed, 48 insertions(+), 3 deletions(-)

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