Notes/src/services/sync.js

"use strict";

const log = require('./log');
const sql = require('./sql');
const optionService = require('./options');
const utils = require('./utils');
const instanceId = require('./member_id');
const dateUtils = require('./date_utils');
const syncUpdateService = require('./sync_update');
const contentHashService = require('./content_hash');
const appInfo = require('./app_info');
const syncOptions = require('./sync_options');
const syncMutexService = require('./sync_mutex');
const cls = require('./cls');
const request = require('./request');
const ws = require('./ws');
const entityChangesService = require('./entity_changes');
const entityConstructor = require('../becca/entity_constructor');
const becca = require("../becca/becca");

let proxyToggle = true;

let outstandingPullCount = 0;

async function sync() {
    try {
        return await syncMutexService.doExclusively(async () => {
            if (!syncOptions.isSyncSetup()) {
                return { success: false, errorCode: 'NOT_CONFIGURED', message: 'Sync not configured' };
            }

            let continueSync = false;

            do {
                const syncContext = await login();

                await pushChanges(syncContext);

                await pullChanges(syncContext);

                await pushChanges(syncContext);

                await syncFinished(syncContext);

                continueSync = await checkContentHash(syncContext);
            }
            while (continueSync);

            ws.syncFinished();

            return {
                success: true
            };
        });
    }
    catch (e) {
        proxyToggle = !proxyToggle;

        if (e.message &&
                (e.message.includes('ECONNREFUSED') ||
                 e.message.includes('ERR_') || // node network errors
                 e.message.includes('Bad Gateway'))) {

            ws.syncFailed();

            log.info("No connection to sync server.");

            return {
                success: false,
                message: "No connection to sync server."
            };
        }
        else {
            log.info(`sync failed: ${e.message}
stack: ${e.stack}`);

            ws.syncFailed();

            return {
                success: false,
                message: e.message
            }
        }
    }
}

async function login() {
    const setupService = require('./setup'); // circular dependency issue

    if (!await setupService.hasSyncServerSchemaAndSeed()) {
        await setupService.sendSeedToSyncServer();
    }

    return await doLogin();
}

async function doLogin() {
    const timestamp = dateUtils.utcNowDateTime();

    const documentSecret = optionService.getOption('documentSecret');
    const hash = utils.hmac(documentSecret, timestamp);

    const syncContext = { cookieJar: {} };
    const resp = await syncRequest(syncContext, 'POST', '/api/login/sync', {
        timestamp: timestamp,
        syncVersion: appInfo.syncVersion,
        hash: hash
    });

    if (resp.instanceId === instanceId) {
        throw new Error(`Sync server has member ID '${resp.instanceId}' which is also local. This usually happens when the sync client is (mis)configured to sync with itself (URL points back to client) instead of the correct sync server.`);
    }

    syncContext.instanceId = resp.instanceId;

    const lastSyncedPull = getLastSyncedPull();

    // this is important in a scenario where we set up the sync by manually copying the document
    // lastSyncedPull then could be pretty off for the newly cloned client
    if (lastSyncedPull > resp.maxEntityChangeId) {
        log.info(`Lowering last synced pull from ${lastSyncedPull} to ${resp.maxEntityChangeId}`);

        setLastSyncedPull(resp.maxEntityChangeId);
    }

    return syncContext;
}

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
        const changesUri = `/api/sync/changed?instanceId=${instanceId}&lastEntityChangeId=${lastSyncedPull}&logMarkerId=${logMarkerId}`;

        const startDate = Date.now();

        const resp = await syncRequest(syncContext, 'GET', changesUri);
        const {entityChanges, lastEntityChangeId} = resp;

        outstandingPullCount = resp.outstandingPullCount;

        const pulledDate = Date.now();

        sql.transactional(() => {
            for (const {entityChange, entity} of entityChanges) {
                const changeAppliedAlready = entityChange.changeId
                    && !!sql.getValue("SELECT id FROM entity_changes WHERE changeId = ?", [entityChange.changeId]);

                if (!changeAppliedAlready) {
                    if (!atLeastOnePullApplied) { // send only for first
                        ws.syncPullInProgress();

                        atLeastOnePullApplied = true;
                    }

                    syncUpdateService.updateEntity(entityChange, entity, syncContext.instanceId);
                }
            }

            if (lastSyncedPull !== lastEntityChangeId) {
                setLastSyncedPull(lastEntityChangeId);
            }
        });

        if (entityChanges.length === 0) {
            break;
        } else {
            const sizeInKb = Math.round(JSON.stringify(resp).length / 1024);

            log.info(`Sync ${logMarkerId}: Pulled ${entityChanges.length} changes in ${sizeInKb} KB, starting at entityChangeId=${lastSyncedPull} in ${pulledDate - startDate}ms and applied them in ${Date.now() - pulledDate}ms, ${outstandingPullCount} outstanding pulls`);
        }
    }

    log.info("Finished pull");
}

async function pushChanges(syncContext) {
    let lastSyncedPush = getLastSyncedPush();

    while (true) {
        const entityChanges = sql.getRows('SELECT * FROM entity_changes WHERE isSynced = 1 AND id > ? LIMIT 1000', [lastSyncedPush]);

        if (entityChanges.length === 0) {
            log.info("Nothing to push");

            break;
        }

        const filteredEntityChanges = entityChanges.filter(entityChange => {
            if (entityChange.instanceId === syncContext.instanceId) {
                // this may set lastSyncedPush beyond what's actually sent (because of size limit)
                // so this is applied to the database only if there's no actual update
                lastSyncedPush = entityChange.id;

                return false;
            }
            else {
                return true;
            }
        });

        if (filteredEntityChanges.length === 0) {
            // there still might be more sync changes (because of batch limit), just all the current batch
            // has been filtered out
            setLastSyncedPush(lastSyncedPush);

            continue;
        }

        const entityChangesRecords = getEntityChangeRecords(filteredEntityChanges);
        const startDate = new Date();

        const logMarkerId = utils.randomString(10); // to easily pair sync events between client and server logs

        await syncRequest(syncContext, 'PUT', `/api/sync/update?logMarkerId=${logMarkerId}`, {
            entities: entityChangesRecords,
            instanceId
        });

        ws.syncPushInProgress();

        log.info(`Sync ${logMarkerId}: Pushing ${entityChangesRecords.length} sync changes in ${Date.now() - startDate.getTime()}ms`);

        lastSyncedPush = entityChangesRecords[entityChangesRecords.length - 1].entityChange.id;

        setLastSyncedPush(lastSyncedPush);
    }
}

async function syncFinished(syncContext) {
    await syncRequest(syncContext, 'POST', '/api/sync/finished');
}

async function checkContentHash(syncContext) {
    const resp = await syncRequest(syncContext, 'GET', '/api/sync/check');
    const lastSyncedPullId = getLastSyncedPull();

    if (lastSyncedPullId < resp.maxEntityChangeId) {
        log.info(`There are some outstanding pulls (${lastSyncedPullId} vs. ${resp.maxEntityChangeId}), skipping content check.`);

        return true;
    }

    const notPushedSyncs = sql.getValue("SELECT EXISTS(SELECT 1 FROM entity_changes WHERE isSynced = 1 AND id > ?)", [getLastSyncedPush()]);

    if (notPushedSyncs) {
        log.info(`There's ${notPushedSyncs} outstanding pushes, skipping content check.`);

        return true;
    }

    const failedChecks = contentHashService.checkContentHashes(resp.entityHashes);

    if (failedChecks.length > 0) {
        // before requeuing sectors, make sure the entity changes are correct
        const consistencyChecks = require("./consistency_checks");
        consistencyChecks.runEntityChangesChecks();

        await syncRequest(syncContext, 'POST', `/api/sync/check-entity-changes`);
    }

    for (const {entityName, sector} of failedChecks) {
        entityChangesService.addEntityChangesForSector(entityName, sector);

        await syncRequest(syncContext, 'POST', `/api/sync/queue-sector/${entityName}/${sector}`);
    }

    return failedChecks.length > 0;
}

const PAGE_SIZE = 1000000;

async function syncRequest(syncContext, method, requestPath, body) {
    body = body ? JSON.stringify(body) : '';

    const timeout = syncOptions.getSyncTimeout();

    let response;

    const requestId = utils.randomString(10);
    const pageCount = Math.max(1, Math.ceil(body.length / PAGE_SIZE));

    for (let pageIndex = 0; pageIndex < pageCount; pageIndex++) {
        const opts = {
            method,
            url: syncOptions.getSyncServerHost() + requestPath,
            cookieJar: syncContext.cookieJar,
            timeout: timeout,
            paging: {
                pageIndex,
                pageCount,
                requestId
            },
            body: body.substr(pageIndex * PAGE_SIZE, Math.min(PAGE_SIZE, body.length - pageIndex * PAGE_SIZE)),
            proxy: proxyToggle ? syncOptions.getSyncProxy() : null
        };

        response = await utils.timeLimit(request.exec(opts), timeout);
    }

    return response;
}

function getEntityChangeRow(entityName, entityId) {
    if (entityName === 'note_reordering') {
        return sql.getMap("SELECT branchId, notePosition FROM branches WHERE parentNoteId = ? AND isDeleted = 0", [entityId]);
    }
    else {
        const primaryKey = entityConstructor.getEntityFromEntityName(entityName).primaryKeyName;

        if (!primaryKey) {
            throw new Error(`Unknown entity '${entityName}'`);
        }

        const entityRow = sql.getRow(`SELECT * FROM ${entityName} WHERE ${primaryKey} = ?`, [entityId]);

        if (!entityRow) {
            throw new Error(`Entity ${entityName} '${entityId}' not found.`);
        }

        if (entityName === 'blobs' && entityRow.content !== null) {
            if (typeof entityRow.content === 'string') {
                entityRow.content = Buffer.from(entityRow.content, 'utf-8');
            }

            entityRow.content = entityRow.content.toString("base64");
        }

        return entityRow;
    }
}

function getEntityChangeRecords(entityChanges) {
    const records = [];
    let length = 0;

    for (const entityChange of entityChanges) {
        if (entityChange.isErased) {
            records.push({entityChange});

            continue;
        }

        const entity = getEntityChangeRow(entityChange.entityName, entityChange.entityId);

        const record = { entityChange, entity };

        records.push(record);

        length += JSON.stringify(record).length;

        if (length > 1000000) {
            break;
        }
    }

    return records;
}

function getLastSyncedPull() {
    return parseInt(optionService.getOption('lastSyncedPull'));
}

function setLastSyncedPull(entityChangeId) {
    const lastSyncedPullOption = becca.getOption('lastSyncedPull');

    if (lastSyncedPullOption) { // might be null in initial sync when becca is not loaded
        lastSyncedPullOption.value = `${entityChangeId}`;
    }

    // this way we avoid updating entity_changes which otherwise means that we've never pushed all entity_changes
    sql.execute("UPDATE options SET value = ? WHERE name = ?", [entityChangeId, 'lastSyncedPull']);
}

function getLastSyncedPush() {
    const lastSyncedPush = parseInt(optionService.getOption('lastSyncedPush'));

    ws.setLastSyncedPush(lastSyncedPush);

    return lastSyncedPush;
}

function setLastSyncedPush(entityChangeId) {
    ws.setLastSyncedPush(entityChangeId);

    const lastSyncedPushOption = becca.getOption('lastSyncedPush');

    if (lastSyncedPushOption) { // might be null in initial sync when becca is not loaded
        lastSyncedPushOption.value = `${entityChangeId}`;
    }

    // this way we avoid updating entity_changes which otherwise means that we've never pushed all entity_changes
    sql.execute("UPDATE options SET value = ? WHERE name = ?", [entityChangeId, 'lastSyncedPush']);
}

function getMaxEntityChangeId() {
    return sql.getValue('SELECT COALESCE(MAX(id), 0) FROM entity_changes');
}

function getOutstandingPullCount() {
    return outstandingPullCount;
}

require("../becca/becca_loader").beccaLoaded.then(() => {
    setInterval(cls.wrap(sync), 60000);

    // kickoff initial sync immediately, but should happen after initial consistency checks
    setTimeout(cls.wrap(sync), 5000);

    // called just so ws.setLastSyncedPush() is called
    getLastSyncedPush();
});

module.exports = {
    sync,
    login,
    getEntityChangeRecords,
    getOutstandingPullCount,
    getMaxEntityChangeId
};