more logging for sync

src/routes/api/sync.js

@@ -166,11 +166,7 @@ function update(req) {
 
     const {entities, instanceId} = body;
 
-    sql.transactional(() => {
+    sql.transactional(() => syncUpdateService.updateEntities(entities, instanceId));
-        for (const {entityChange, entity} of entities) {
-            syncUpdateService.updateEntity(entityChange, entity, instanceId);
-        }
-    });
 }
 
 setInterval(() => {

src/services/sync.js

@@ -126,8 +126,6 @@ async function doLogin() {
 }
 
 async function pullChanges(syncContext) {
-    let atLeastOnePullApplied = false;
-
     while (true) {
         const lastSyncedPull = getLastSyncedPull();
         const logMarkerId = utils.randomString(10); // to easily pair sync events between client and server logs
@@ -143,22 +141,7 @@ async function pullChanges(syncContext) {
         const pulledDate = Date.now();
 
         sql.transactional(() => {
-            for (const {entityChange, entity} of entityChanges) {
+            syncUpdateService.updateEntities(entityChanges, syncContext.instanceId);
-                const changeAppliedAlready = entityChange.changeId
-                    && !!sql.getValue("SELECT 1 FROM entity_changes WHERE changeId = ?", [entityChange.changeId]);
-
-                if (changeAppliedAlready) {
-                    continue;
-                }
-
-                if (!atLeastOnePullApplied) { // send only for first
-                    ws.syncPullInProgress();
-
-                    atLeastOnePullApplied = true;
-                }
-
-                syncUpdateService.updateEntity(entityChange, entity, syncContext.instanceId);
-            }
 
             if (lastSyncedPull !== lastEntityChangeId) {
                 setLastSyncedPull(lastEntityChangeId);

src/services/sync_update.js

@@ -3,15 +3,51 @@ const log = require('./log');
 const entityChangesService = require('./entity_changes');
 const eventService = require('./events');
 const entityConstructor = require("../becca/entity_constructor");
+const ws = require("./ws");
 
-function updateEntity(remoteEC, remoteEntityRow, instanceId) {
+function updateEntities(entityChanges, instanceId) {
+    if (entityChanges.length === 0) {
+        return;
+    }
+
+    let atLeastOnePullApplied = false;
+    const updateContext = {
+        updated: {},
+        alreadyUpdated: 0,
+        erased: 0,
+        alreadyErased: 0
+    };
+
+    for (const {entityChange, entity} of entityChanges) {
+        const changeAppliedAlready = entityChange.changeId
+            && !!sql.getValue("SELECT 1 FROM entity_changes WHERE changeId = ?", [entityChange.changeId]);
+
+        if (changeAppliedAlready) {
+            updateContext.alreadyUpdated++;
+
+            continue;
+        }
+
+        if (!atLeastOnePullApplied) { // avoid spamming and send only for first
+            ws.syncPullInProgress();
+
+            atLeastOnePullApplied = true;
+        }
+
+        updateEntity(entityChange, entity, instanceId, updateContext);
+    }
+
+    logUpdateContext(updateContext);
+}
+
+function updateEntity(remoteEC, remoteEntityRow, instanceId, updateContext) {
     if (!remoteEntityRow && remoteEC.entityName === 'options') {
         return; // can be undefined for options with isSynced=false
     }
 
     const updated = remoteEC.entityName === 'note_reordering'
         ? updateNoteReordering(remoteEC, remoteEntityRow, instanceId)
-        : updateNormalEntity(remoteEC, remoteEntityRow, instanceId);
+        : updateNormalEntity(remoteEC, remoteEntityRow, instanceId, updateContext);
 
     if (updated) {
         if (remoteEntityRow?.isDeleted) {
@@ -29,11 +65,12 @@ function updateEntity(remoteEC, remoteEntityRow, instanceId) {
     }
 }
 
-function updateNormalEntity(remoteEC, remoteEntityRow, instanceId) {
+function updateNormalEntity(remoteEC, remoteEntityRow, instanceId, updateContext) {
     const localEC = sql.getRow(`SELECT * FROM entity_changes WHERE entityName = ? AND entityId = ?`, [remoteEC.entityName, remoteEC.entityId]);
 
     if (!localEC?.isErased && remoteEC.isErased) {
         eraseEntity(remoteEC, instanceId);
+        updateContext.erased++;
 
         return true;
     } else if (localEC?.isErased && !remoteEC.isErased) {
@@ -42,6 +79,7 @@ function updateNormalEntity(remoteEC, remoteEntityRow, instanceId) {
 
         return false;
     } else if (localEC?.isErased && remoteEC.isErased) {
+        updateContext.alreadyErased++;
         return false;
     }
 
@@ -65,6 +103,9 @@ function updateNormalEntity(remoteEC, remoteEntityRow, instanceId) {
 
         sql.replace(remoteEC.entityName, remoteEntityRow);
 
+        updateContext.updated[remoteEC.entityName] = updateContext.updated[remoteEC.entityName] || [];
+        updateContext.updated[remoteEC.entityName].push(remoteEC.entityId);
+
         if (!localEC || localEC.utcDateChanged < remoteEC.utcDateChanged) {
             entityChangesService.putEntityChangeWithInstanceId(remoteEC, instanceId);
         }
@@ -118,6 +159,15 @@ function eraseEntity(entityChange, instanceId) {
     entityChangesService.putEntityChangeWithInstanceId(entityChange, instanceId);
 }
 
+function logUpdateContext(updateContext) {
+    const message = JSON.stringify(updateContext)
+        .replaceAll('"', '')
+        .replaceAll(":", ": ")
+        .replaceAll(",", ", ");
+
+    log.info(message.substr(1, message.length - 2));
+}
+
 module.exports = {
-    updateEntity
+    updateEntities
 };