1
0
mirror of https://github.com/laurent22/joplin.git synced 2024-12-21 09:38:01 +02:00
joplin/packages/lib/Synchronizer.ts

1114 lines
43 KiB
TypeScript
Raw Normal View History

import Logger from '@joplin/utils/Logger';
import LockHandler, { appTypeToLockType, hasActiveLock, LockClientType, LockType } from './services/synchronizer/LockHandler';
import Setting, { AppType } from './models/Setting';
2020-11-05 18:58:23 +02:00
import shim from './shim';
import MigrationHandler from './services/synchronizer/MigrationHandler';
import eventManager from './eventManager';
import { _ } from './locale';
import BaseItem from './models/BaseItem';
import Folder from './models/Folder';
import Note from './models/Note';
import Resource from './models/Resource';
import ItemChange from './models/ItemChange';
import ResourceLocalState from './models/ResourceLocalState';
import MasterKey from './models/MasterKey';
import BaseModel, { ModelType } from './BaseModel';
import time from './time';
import ResourceService from './services/ResourceService';
import EncryptionService from './services/e2ee/EncryptionService';
import JoplinError from './JoplinError';
import ShareService from './services/share/ShareService';
import TaskQueue from './TaskQueue';
import ItemUploader from './services/synchronizer/ItemUploader';
import { FileApi, RemoteItem } from './file-api';
import JoplinDatabase from './JoplinDatabase';
import { fetchSyncInfo, getActiveMasterKey, localSyncInfo, mergeSyncInfos, saveLocalSyncInfo, setMasterKeyHasBeenUsed, SyncInfo, syncInfoEquals, uploadSyncInfo } from './services/synchronizer/syncInfoUtils';
import { getMasterPassword, setupAndDisableEncryption, setupAndEnableEncryption } from './services/e2ee/utils';
import { generateKeyPair } from './services/e2ee/ppk';
import syncDebugLog from './services/synchronizer/syncDebugLog';
import handleConflictAction, { ConflictAction } from './services/synchronizer/utils/handleConflictAction';
import resourceRemotePath from './services/synchronizer/utils/resourceRemotePath';
import syncDeleteStep from './services/synchronizer/utils/syncDeleteStep';
import { ErrorCode } from './errors';
const { sprintf } = require('sprintf-js');
2020-11-05 18:58:23 +02:00
const { Dirnames } = require('./services/synchronizer/utils/types');
2017-05-18 21:58:01 +02:00
const logger = Logger.create('Synchronizer');
function isCannotSyncError(error: any): boolean {
if (!error) return false;
if (['rejectedByTarget', 'fileNotFound'].indexOf(error.code) >= 0) return true;
// If the request times out we give up too because sometimes it's due to the
// file being large or some other connection issues, and we don't want that
// file to block the sync process. The user can choose to retry later on.
//
// message: "network timeout at: .....
// name: "FetchError"
// type: "request-timeout"
if (error.type === 'request-timeout' || error.message.includes('network timeout')) return true;
return false;
}
export default class Synchronizer {
public static verboseMode = true;
2021-06-16 11:43:39 +02:00
private db_: JoplinDatabase;
private api_: FileApi;
private appType_: AppType;
private logger_: Logger = new Logger();
private state_ = 'idle';
private cancelling_ = false;
public maxResourceSize_: number = null;
private downloadQueue_: any = null;
private clientId_: string;
private lockHandler_: LockHandler;
private migrationHandler_: MigrationHandler;
private encryptionService_: EncryptionService = null;
private resourceService_: ResourceService = null;
private syncTargetIsLocked_ = false;
private shareService_: ShareService = null;
private lockClientType_: LockClientType = null;
// Debug flags are used to test certain hard-to-test conditions
// such as cancelling in the middle of a loop.
public testingHooks_: string[] = [];
// eslint-disable-next-line @typescript-eslint/ban-types -- Old code before rule was applied
private onProgress_: Function;
private progressReport_: any = {};
// eslint-disable-next-line @typescript-eslint/ban-types -- Old code before rule was applied
public dispatch: Function;
public constructor(db: JoplinDatabase, api: FileApi, appType: AppType) {
2017-05-19 21:12:09 +02:00
this.db_ = db;
this.api_ = api;
this.appType_ = appType;
this.clientId_ = Setting.value('clientId');
2017-07-14 21:06:01 +02:00
this.onProgress_ = function() {};
2017-07-14 21:06:01 +02:00
this.progressReport_ = {};
2017-07-16 23:17:22 +02:00
this.dispatch = function() {};
this.apiCall = this.apiCall.bind(this);
2017-05-18 21:58:01 +02:00
}
public state() {
2017-06-24 19:40:03 +02:00
return this.state_;
}
public db() {
2017-05-19 21:12:09 +02:00
return this.db_;
2017-05-18 21:58:01 +02:00
}
public api() {
2017-05-19 21:12:09 +02:00
return this.api_;
2017-05-18 21:58:01 +02:00
}
public clientId() {
return this.clientId_;
}
public setLogger(l: Logger) {
2017-06-23 23:32:24 +02:00
this.logger_ = l;
}
public logger() {
2017-06-23 23:32:24 +02:00
return this.logger_;
}
public lockHandler() {
if (this.lockHandler_) return this.lockHandler_;
this.lockHandler_ = new LockHandler(this.api());
return this.lockHandler_;
}
private lockClientType(): LockClientType {
if (this.lockClientType_) return this.lockClientType_;
this.lockClientType_ = appTypeToLockType(this.appType_);
return this.lockClientType_;
}
public migrationHandler() {
if (this.migrationHandler_) return this.migrationHandler_;
this.migrationHandler_ = new MigrationHandler(this.api(), this.db(), this.lockHandler(), this.lockClientType(), this.clientId_);
return this.migrationHandler_;
}
public maxResourceSize() {
if (this.maxResourceSize_ !== null) return this.maxResourceSize_;
return this.appType_ === AppType.Mobile ? 100 * 1000 * 1000 : Infinity;
}
public setShareService(v: ShareService) {
this.shareService_ = v;
}
public setEncryptionService(v: any) {
this.encryptionService_ = v;
}
public encryptionService() {
return this.encryptionService_;
}
public setResourceService(v: ResourceService) {
this.resourceService_ = v;
}
protected resourceService(): ResourceService {
return this.resourceService_;
}
public async waitForSyncToFinish() {
if (this.state() === 'idle') return;
while (true) {
await time.sleep(1);
if (this.state() === 'idle') return;
}
}
private static reportHasErrors(report: any): boolean {
return !!report && !!report.errors && !!report.errors.length;
}
private static completionTime(report: any): string {
const duration = report.completedTime - report.startTime;
if (duration > 1000) return `${Math.round(duration / 1000)}s`;
return `${duration}ms`;
}
public static reportToLines(report: any) {
const lines = [];
2019-07-29 15:43:53 +02:00
if (report.createLocal) lines.push(_('Created local items: %d.', report.createLocal));
if (report.updateLocal) lines.push(_('Updated local items: %d.', report.updateLocal));
if (report.createRemote) lines.push(_('Created remote items: %d.', report.createRemote));
if (report.updateRemote) lines.push(_('Updated remote items: %d.', report.updateRemote));
if (report.deleteLocal) lines.push(_('Deleted local items: %d.', report.deleteLocal));
if (report.deleteRemote) lines.push(_('Deleted remote items: %d.', report.deleteRemote));
if (report.fetchingTotal && report.fetchingProcessed) lines.push(_('Fetched items: %d/%d.', report.fetchingProcessed, report.fetchingTotal));
if (report.cancelling && !report.completedTime) lines.push(_('Cancelling...'));
if (report.completedTime) lines.push(_('Completed: %s (%s)', time.formatMsToLocal(report.completedTime), this.completionTime(report)));
if (this.reportHasErrors(report)) lines.push(_('Last error: %s', report.errors[report.errors.length - 1].toString().substr(0, 500)));
2017-07-14 21:06:01 +02:00
return lines;
}
public logSyncOperation(action: string, local: any = null, remote: RemoteItem = null, message: string = null, actionCount = 1) {
const line = ['Sync'];
2017-06-24 19:40:03 +02:00
line.push(action);
2017-07-14 21:06:01 +02:00
if (message) line.push(message);
2017-06-24 19:40:03 +02:00
2017-07-14 20:02:45 +02:00
let type = local && local.type_ ? local.type_ : null;
if (!type) type = remote && remote.type_ ? remote.type_ : null;
if (type) line.push(BaseItem.modelTypeToClassName(type));
2017-06-24 19:40:03 +02:00
if (local) {
const s = [];
2017-06-24 19:40:03 +02:00
s.push(local.id);
2019-09-19 23:51:18 +02:00
line.push(`(Local ${s.join(', ')})`);
2017-06-24 19:40:03 +02:00
}
if (remote) {
const s = [];
s.push(remote.id ? remote.id : remote.path);
2019-09-19 23:51:18 +02:00
line.push(`(Remote ${s.join(', ')})`);
2017-06-24 19:40:03 +02:00
}
2021-06-16 11:43:39 +02:00
if (Synchronizer.verboseMode) {
logger.info(line.join(': '));
2021-06-16 11:43:39 +02:00
} else {
logger.debug(line.join(': '));
2021-06-16 11:43:39 +02:00
}
2017-07-14 21:06:01 +02:00
if (!['fetchingProcessed', 'fetchingTotal'].includes(action)) syncDebugLog.info(line.join(': '));
2017-07-14 21:06:01 +02:00
if (!this.progressReport_[action]) this.progressReport_[action] = 0;
2018-01-08 22:36:00 +02:00
this.progressReport_[action] += actionCount;
2017-07-14 21:06:01 +02:00
this.progressReport_.state = this.state();
this.onProgress_(this.progressReport_);
2017-07-16 23:17:22 +02:00
// Make sure we only send a **copy** of the report since it
// is mutated within this class. Should probably use a lib
// for this but for now this simple fix will do.
const reportCopy: any = {};
for (const n in this.progressReport_) reportCopy[n] = this.progressReport_[n];
if (reportCopy.errors) reportCopy.errors = this.progressReport_.errors.slice();
this.dispatch({ type: 'SYNC_REPORT_UPDATE', report: reportCopy });
2017-06-24 19:40:03 +02:00
}
public async logSyncSummary(report: any) {
logger.info('Operations completed: ');
for (const n in report) {
2017-07-01 00:53:22 +02:00
if (!report.hasOwnProperty(n)) continue;
if (n === 'errors') continue;
if (n === 'starting') continue;
if (n === 'finished') continue;
if (n === 'state') continue;
if (n === 'startTime') continue;
if (n === 'completedTime') continue;
logger.info(`${n}: ${report[n] ? report[n] : '-'}`);
2017-06-24 19:40:03 +02:00
}
const folderCount = await Folder.count();
const noteCount = await Note.count();
const resourceCount = await Resource.count();
logger.info(`Total folders: ${folderCount}`);
logger.info(`Total notes: ${noteCount}`);
logger.info(`Total resources: ${resourceCount}`);
if (Synchronizer.reportHasErrors(report)) {
logger.warn('There was some errors:');
for (let i = 0; i < report.errors.length; i++) {
const e = report.errors[i];
logger.warn(e);
}
}
}
public async cancel() {
if (this.cancelling_ || this.state() === 'idle') return null;
2018-08-01 23:05:09 +02:00
// Stop queue but don't set it to null as it may be used to
// retrieve the last few downloads.
2019-06-14 09:11:15 +02:00
if (this.downloadQueue_) this.downloadQueue_.stop();
this.logSyncOperation('cancelling', null, null, '');
this.cancelling_ = true;
2017-10-14 20:03:23 +02:00
return new Promise((resolve) => {
const iid = shim.setInterval(() => {
if (this.state() === 'idle') {
shim.clearInterval(iid);
resolve(null);
2017-10-14 20:03:23 +02:00
}
}, 100);
});
}
public cancelling() {
return this.cancelling_;
}
public logLastRequests() {
const lastRequests = this.api().lastRequests();
if (!lastRequests || !lastRequests.length) return;
for (const r of lastRequests) {
const timestamp = time.unixMsToLocalHms(r.timestamp);
logger.info(`Req ${timestamp}: ${r.request}`);
logger.info(`Res ${timestamp}: ${r.response}`);
}
}
public static stateToLabel(state: string) {
2019-07-29 15:43:53 +02:00
if (state === 'idle') return _('Idle');
if (state === 'in_progress') return _('In progress');
return state;
}
public isFullSync(steps: string[]) {
return steps.includes('update_remote') && steps.includes('delete_remote') && steps.includes('delta');
}
private async lockErrorStatus_() {
const locks = await this.lockHandler().locks();
const currentDate = await this.lockHandler().currentDate();
const hasActiveExclusiveLock = await hasActiveLock(locks, currentDate, this.lockHandler().lockTtl, LockType.Exclusive);
if (hasActiveExclusiveLock) return 'hasExclusiveLock';
const hasActiveSyncLock = await hasActiveLock(locks, currentDate, this.lockHandler().lockTtl, LockType.Sync, this.lockClientType(), this.clientId_);
if (!hasActiveSyncLock) return 'syncLockGone';
return '';
}
private async setPpkIfNotExist(localInfo: SyncInfo, remoteInfo: SyncInfo) {
if (localInfo.ppk || remoteInfo.ppk) return localInfo;
const password = getMasterPassword(false);
if (!password) return localInfo;
localInfo.ppk = await generateKeyPair(this.encryptionService(), password);
return localInfo;
}
private async apiCall(fnName: string, ...args: any[]) {
if (this.syncTargetIsLocked_) throw new JoplinError('Sync target is locked - aborting API call', 'lockError');
try {
const output = await (this.api() as any)[fnName](...args);
return output;
} catch (error) {
const lockStatus = await this.lockErrorStatus_();
// When there's an error due to a lock, we re-wrap the error and change the error code so that error handling
// does not do special processing on the original error. For example, if a resource could not be downloaded,
// don't mark it as a "cannotSyncItem" since we don't know that.
if (lockStatus) {
throw new JoplinError(`Sync target lock error: ${lockStatus}. Original error was: ${error.message}`, 'lockError');
} else {
throw error;
}
}
}
// Synchronisation is done in three major steps:
//
// 1. UPLOAD: Send to the sync target the items that have changed since the last sync.
// 2. DELETE_REMOTE: Delete on the sync target, the items that have been deleted locally.
// 3. DELTA: Find on the sync target the items that have been modified or deleted and apply the changes locally.
public async start(options: any = null) {
2017-06-30 19:54:01 +02:00
if (!options) options = {};
2017-07-24 21:47:01 +02:00
if (this.state() !== 'idle') {
const error: any = new Error(sprintf('Synchronisation is already in progress. State: %s', this.state()));
error.code = 'alreadyStarted';
2017-07-24 21:47:01 +02:00
throw error;
2017-07-30 21:51:18 +02:00
}
this.state_ = 'in_progress';
2017-07-24 21:47:01 +02:00
this.onProgress_ = options.onProgress ? options.onProgress : function() {};
2017-07-14 21:06:01 +02:00
this.progressReport_ = { errors: [] };
2017-06-30 19:54:01 +02:00
2017-07-18 22:03:07 +02:00
const lastContext = options.context ? options.context : {};
2017-07-18 21:57:49 +02:00
2019-07-29 15:43:53 +02:00
const syncSteps = options.syncSteps ? options.syncSteps : ['update_remote', 'delete_remote', 'delta'];
// The default is to log errors, but when testing it's convenient to be able to catch and verify errors
const throwOnError = options.throwOnError === true;
2017-07-24 20:58:11 +02:00
const syncTargetId = this.api().syncTargetId();
this.syncTargetIsLocked_ = false;
this.cancelling_ = false;
2017-07-02 12:34:07 +02:00
// const masterKeysBefore = await MasterKey.count();
// let hasAutoEnabledEncryption = false;
const synchronizationId = time.unixMs().toString();
2017-06-24 19:40:03 +02:00
const outputContext = { ...lastContext };
2017-01-29 20:29:34 +02:00
this.progressReport_.startTime = time.unixMs();
this.dispatch({ type: 'SYNC_STARTED' });
eventManager.emit('syncStart');
this.logSyncOperation('starting', null, null, `Starting synchronisation to target ${syncTargetId}... supportsAccurateTimestamp = ${this.api().supportsAccurateTimestamp}; supportsMultiPut = ${this.api().supportsMultiPut} [${synchronizationId}]`);
2017-06-23 23:32:24 +02:00
const handleCannotSyncItem = async (ItemClass: any, syncTargetId: any, item: any, cannotSyncReason: string, itemLocation: any = null) => {
await ItemClass.saveSyncDisabled(syncTargetId, item, cannotSyncReason, itemLocation);
2019-07-29 15:43:53 +02:00
this.dispatch({ type: 'SYNC_HAS_DISABLED_SYNC_ITEMS' });
};
// We index resources before sync mostly to flag any potential orphan
// resource before it is being synced. That way, it can potentially be
// auto-deleted at a later time. Indexing resources is fast so it's fine
// to call it every time here.
//
// https://github.com/laurent22/joplin/issues/932#issuecomment-933736405
try {
if (this.resourceService()) {
logger.info('Indexing resources...');
await this.resourceService().indexNoteResources();
}
} catch (error) {
logger.error('Error indexing resources:', error);
}
// Before synchronising make sure all share_id properties are set
// correctly so as to share/unshare the right items.
try {
await Folder.updateAllShareIds(this.resourceService());
if (this.shareService_) await this.shareService_.checkShareConsistency();
} catch (error) {
if (error && error.code === ErrorCode.IsReadOnly) {
// We ignore it because the functions above tried to modify a
// read-only item and failed. Normally it shouldn't happen since
// the UI should prevent, but if there's a bug in the UI or some
// other issue we don't want sync to fail because of this.
logger.error('Could not update share because an item is readonly:', error);
} else {
throw error;
}
}
const itemUploader = new ItemUploader(this.api(), this.apiCall);
let errorToThrow = null;
let syncLock = null;
2017-06-29 20:03:16 +02:00
try {
await this.api().initialize();
this.api().setTempDirName(Dirnames.Temp);
try {
let remoteInfo = await fetchSyncInfo(this.api());
logger.info('Sync target remote info:', remoteInfo);
eventManager.emit('sessionEstablished');
2017-06-29 20:03:16 +02:00
let syncTargetIsNew = false;
if (!remoteInfo.version) {
logger.info('Sync target is new - setting it up...');
await this.migrationHandler().upgrade(Setting.value('syncVersion'));
remoteInfo = await fetchSyncInfo(this.api());
syncTargetIsNew = true;
}
logger.info('Sync target is already setup - checking it...');
await this.migrationHandler().checkCanSync(remoteInfo);
let localInfo = await localSyncInfo();
logger.info('Sync target local info:', localInfo);
localInfo = await this.setPpkIfNotExist(localInfo, remoteInfo);
if (syncTargetIsNew && localInfo.activeMasterKeyId) {
localInfo = setMasterKeyHasBeenUsed(localInfo, localInfo.activeMasterKeyId);
}
// console.info('LOCAL', localInfo);
// console.info('REMOTE', remoteInfo);
if (!syncInfoEquals(localInfo, remoteInfo)) {
let newInfo = mergeSyncInfos(localInfo, remoteInfo);
if (newInfo.activeMasterKeyId) newInfo = setMasterKeyHasBeenUsed(newInfo, newInfo.activeMasterKeyId);
const previousE2EE = localInfo.e2ee;
logger.info('Sync target info differs between local and remote - merging infos: ', newInfo.toObject());
await this.lockHandler().acquireLock(LockType.Exclusive, this.lockClientType(), this.clientId_, { clearExistingSyncLocksFromTheSameClient: true });
await uploadSyncInfo(this.api(), newInfo);
await saveLocalSyncInfo(newInfo);
await this.lockHandler().releaseLock(LockType.Exclusive, this.lockClientType(), this.clientId_);
// console.info('NEW', newInfo);
if (newInfo.e2ee !== previousE2EE) {
if (newInfo.e2ee) {
const mk = getActiveMasterKey(newInfo);
await setupAndEnableEncryption(this.encryptionService(), mk);
} else {
await setupAndDisableEncryption(this.encryptionService());
}
}
} else {
// Set it to remote anyway so that timestamps are the same
// Note: that's probably not needed anymore?
// await uploadSyncInfo(this.api(), remoteInfo);
}
} catch (error) {
if (error.code === 'outdatedSyncTarget') {
Setting.setValue('sync.upgradeState', Setting.SYNC_UPGRADE_STATE_SHOULD_DO);
}
throw error;
}
syncLock = await this.lockHandler().acquireLock(LockType.Sync, this.lockClientType(), this.clientId_);
this.lockHandler().startAutoLockRefresh(syncLock, (error: any) => {
logger.warn('Could not refresh lock - cancelling sync. Error was:', error);
this.syncTargetIsLocked_ = true;
2020-11-25 16:40:25 +02:00
void this.cancel();
});
// ========================================================================
// 2. DELETE_REMOTE
// ------------------------------------------------------------------------
// Delete the remote items that have been deleted locally.
// ========================================================================
if (syncSteps.indexOf('delete_remote') >= 0) {
await syncDeleteStep(
syncTargetId,
this.cancelling(),
(action, local, logSyncOperation, message, actionCount) => {
this.logSyncOperation(action, local, logSyncOperation, message, actionCount);
},
(fnName, ...args) => {
return this.apiCall(fnName, ...args);
},
action => { return this.dispatch(action); },
);
} // DELETE_REMOTE STEP
// ========================================================================
// 1. UPLOAD
// ------------------------------------------------------------------------
// First, find all the items that have been changed since the
// last sync and apply the changes to remote.
// ========================================================================
2017-06-29 20:03:16 +02:00
2019-07-29 15:43:53 +02:00
if (syncSteps.indexOf('update_remote') >= 0) {
const donePaths: string[] = [];
const completeItemProcessing = (path: string) => {
donePaths.push(path);
2019-07-29 15:43:53 +02:00
};
while (true) {
if (this.cancelling()) break;
const result = await BaseItem.itemsThatNeedSync(syncTargetId);
const locals = result.items;
await itemUploader.preUploadItems(result.items.filter((it: any) => result.neverSyncedItemIds.includes(it.id)));
for (let i = 0; i < locals.length; i++) {
if (this.cancelling()) break;
2017-06-14 00:39:45 +02:00
let local = locals[i];
const ItemClass: typeof BaseItem = BaseItem.itemClass(local);
const path = BaseItem.systemPath(local);
// Safety check to avoid infinite loops.
// - In fact this error is possible if the item is marked for sync (via sync_time or force_sync) while synchronisation is in
// progress. In that case exit anyway to be sure we aren't in a loop and the item will be re-synced next time.
// - It can also happen if the item is directly modified in the sync target, and set with an update_time in the future. In that case,
// the local sync_time will be updated to Date.now() but on the next loop it will see that the remote item still has a date ahead
// and will see a conflict. There's currently no automatic fix for this - the remote item on the sync target must be fixed manually
// (by setting an updated_time less than current time).
2019-07-29 15:43:53 +02:00
if (donePaths.indexOf(path) >= 0) throw new JoplinError(sprintf('Processing a path that has already been done: %s. sync_time was not updated? Remote item has an updated_time in the future?', path), 'processingPathTwice');
const remote: RemoteItem = result.neverSyncedItemIds.includes(local.id) ? null : await this.apiCall('stat', path);
let action = null;
let itemIsReadOnly = false;
2019-07-29 15:43:53 +02:00
let reason = '';
let remoteContent = null;
const getConflictType = (conflictedItem: any) => {
2020-05-31 17:57:16 +02:00
if (conflictedItem.type_ === BaseModel.TYPE_NOTE) return 'noteConflict';
if (conflictedItem.type_ === BaseModel.TYPE_RESOURCE) return 'resourceConflict';
return 'itemConflict';
};
if (!remote) {
if (!local.sync_time) {
2019-07-29 15:43:53 +02:00
action = 'createRemote';
reason = 'remote does not exist, and local is new and has never been synced';
} else {
// Note or item was modified after having been deleted remotely
2018-10-30 02:17:50 +02:00
// "itemConflict" is for all the items except the notes, which are dealt with in a special way
2020-05-31 17:57:16 +02:00
action = getConflictType(local);
2019-07-29 15:43:53 +02:00
reason = 'remote has been deleted, but local has changes';
2017-08-01 23:40:14 +02:00
}
} else {
// Note: in order to know the real updated_time value, we need to load the content. In theory we could
// rely on the file timestamp (in remote.updated_time) but in practice it's not accurate enough and
// can lead to conflicts (for example when the file timestamp is slightly ahead of it's real
// updated_time). updated_time is set and managed by clients so it's always accurate.
// Same situation below for updateLocal.
//
// This is a bit inefficient because if the resulting action is "updateRemote" we don't need the whole
// content, but for now that will do since being reliable is the priority.
//
// Note: assuming a particular sync target is guaranteed to have accurate timestamps, the driver maybe
// could expose this with a accurateTimestamps() method that returns "true". In that case, the test
// could be done using the file timestamp and the potentially unnecessary content loading could be skipped.
// OneDrive does not appear to have accurate timestamps as lastModifiedDateTime would occasionally be
// a few seconds ahead of what it was set with setTimestamp()
try {
remoteContent = await this.apiCall('get', path);
} catch (error) {
if (error.code === 'rejectedByTarget') {
this.progressReport_.errors.push(error);
logger.warn(`Rejected by target: ${path}: ${error.message}`);
completeItemProcessing(path);
continue;
} else {
throw error;
}
}
2019-09-19 23:51:18 +02:00
if (!remoteContent) throw new Error(`Got metadata for path but could not fetch content: ${path}`);
remoteContent = await BaseItem.unserialize(remoteContent);
if (remoteContent.updated_time > local.sync_time) {
// Since, in this loop, we are only dealing with items that require sync, if the
// remote has been modified after the sync time, it means both items have been
// modified and so there's a conflict.
2020-05-31 17:57:16 +02:00
action = getConflictType(local);
2019-07-29 15:43:53 +02:00
reason = 'both remote and local have changes';
} else {
2019-07-29 15:43:53 +02:00
action = 'updateRemote';
reason = 'local has changes';
}
}
// We no longer upload Master Keys however we keep them
// in the database for extra safety. In a future
// version, once it's confirmed that the new E2EE system
// works well, we can delete them.
if (local.type_ === ModelType.MasterKey) action = null;
this.logSyncOperation(action, local, remote, reason);
if (local.type_ === BaseModel.TYPE_RESOURCE && (action === 'createRemote' || action === 'updateRemote')) {
const localState = await Resource.localState(local.id);
if (localState.fetch_status !== Resource.FETCH_STATUS_DONE) {
// This condition normally shouldn't happen
// because the normal cases are as follow:
//
// - User creates a resource locally - in that
// case the fetch status is DONE, so we cannot
// end up here.
//
// - User fetches a new resource metadata, but
// not the blob - in that case fetch status is
// IDLE. However in that case, we cannot end
// up in this place either, because the action
// cannot be createRemote (because the
// resource has not been created locally) or
// updateRemote (because a resouce cannot be
// modified locally unless the blob is present
// too).
//
// Possibly the only case we can end up here is
// if a resource metadata has been downloaded,
// but not the blob yet. Then the sync target is
// switched to a different one. In that case, we
// can have a fetch status IDLE, with an
// "updateRemote" action, if the timestamp of
// the server resource is before the timestamp
// of the local resource.
//
// In that case we can't do much so we mark the
// resource as "cannot sync". Otherwise it will
// throw the error "Processing a path that has
// already been done" on the next loop, and sync
// will never finish because we'll always end up
// here.
logger.info(`Need to upload a resource, but blob is not present: ${path}`);
await handleCannotSyncItem(ItemClass, syncTargetId, local, 'Trying to upload resource, but only metadata is present.');
action = null;
} else {
try {
const remoteContentPath = resourceRemotePath(local.id);
const result = await Resource.fullPathForSyncUpload(local);
const resource = result.resource;
local = resource as any;
const localResourceContentPath = result.path;
if (resource.size >= 10 * 1000 * 1000) {
logger.warn(`Uploading a large resource (resourceId: ${local.id}, size:${resource.size} bytes) which may tie up the sync process.`);
}
await this.apiCall('put', remoteContentPath, null, { path: localResourceContentPath, source: 'file', shareId: resource.share_id });
} catch (error) {
if (isCannotSyncError(error)) {
await handleCannotSyncItem(ItemClass, syncTargetId, local, error.message);
action = null;
} else if (error && error.code === ErrorCode.IsReadOnly) {
action = getConflictType(local);
itemIsReadOnly = true;
logger.info('Resource is readonly and cannot be modified - handling it as a conflict:', local);
} else {
throw error;
}
}
}
}
if (action === 'createRemote' || action === 'updateRemote') {
let canSync = true;
try {
2019-07-29 15:43:53 +02:00
if (this.testingHooks_.indexOf('notesRejectedByTarget') >= 0 && local.type_ === BaseModel.TYPE_NOTE) throw new JoplinError('Testing rejectedByTarget', 'rejectedByTarget');
if (this.testingHooks_.indexOf('itemIsReadOnly') >= 0) throw new JoplinError('Testing isReadOnly', ErrorCode.IsReadOnly);
await itemUploader.serializeAndUploadItem(ItemClass, path, local);
} catch (error) {
2019-07-29 15:43:53 +02:00
if (error && error.code === 'rejectedByTarget') {
await handleCannotSyncItem(ItemClass, syncTargetId, local, error.message);
canSync = false;
} else if (error && error.code === ErrorCode.IsReadOnly) {
action = getConflictType(local);
itemIsReadOnly = true;
canSync = false;
} else {
throw error;
}
}
2017-06-19 20:58:49 +02:00
// Note: Currently, we set sync_time to update_time, which should work fine given that the resolution is the millisecond.
// In theory though, this could happen:
//
// 1. t0: Editor: Note is modified
// 2. t0: Sync: Found that note was modified so start uploading it
// 3. t0: Editor: Note is modified again
// 4. t1: Sync: Note has finished uploading, set sync_time to t0
//
// Later any attempt to sync will not detect that note was modified in (3) (within the same millisecond as it was being uploaded)
// because sync_time will be t0 too.
//
// The solution would be to use something like an etag (a simple counter incremented on every change) to make sure each
// change is uniquely identified. Leaving it like this for now.
if (canSync) {
// 2018-01-21: Setting timestamp is not needed because the delta() logic doesn't rely
// on it (instead it uses a more reliable `context` object) and the itemsThatNeedSync loop
// above also doesn't use it because it fetches the whole remote object and read the
// more reliable 'updated_time' property. Basically remote.updated_time is deprecated.
await ItemClass.saveSyncTime(syncTargetId, local, local.updated_time);
}
2020-05-31 17:57:16 +02:00
}
await handleConflictAction(
action as ConflictAction,
ItemClass,
!!remote,
remoteContent,
local,
syncTargetId,
itemIsReadOnly,
(action: any) => this.dispatch(action),
);
completeItemProcessing(path);
2017-06-20 21:25:01 +02:00
}
2017-06-18 01:49:52 +02:00
if (!result.hasMore) break;
2017-06-29 20:03:16 +02:00
}
} // UPLOAD STEP
2017-06-24 19:40:03 +02:00
// ------------------------------------------------------------------------
// 3. DELTA
2017-06-29 20:03:16 +02:00
// ------------------------------------------------------------------------
// Loop through all the remote items, find those that
2018-10-30 02:17:50 +02:00
// have been created or updated, and apply the changes to local.
2017-06-29 20:03:16 +02:00
// ------------------------------------------------------------------------
if (this.downloadQueue_) await this.downloadQueue_.stop();
this.downloadQueue_ = new TaskQueue('syncDownload');
this.downloadQueue_.logger_ = logger;
2019-07-29 15:43:53 +02:00
if (syncSteps.indexOf('delta') >= 0) {
// At this point all the local items that have changed have been pushed to remote
// or handled as conflicts, so no conflict is possible after this.
2017-06-29 20:03:16 +02:00
let context = null;
let newDeltaContext = null;
const localFoldersToDelete = [];
let hasCancelled = false;
if (lastContext.delta) context = lastContext.delta;
2017-07-18 21:57:49 +02:00
while (true) {
if (this.cancelling() || hasCancelled) break;
2017-07-18 21:57:49 +02:00
const listResult: any = await this.apiCall('delta', '', {
context: context,
2017-10-27 00:03:21 +02:00
// allItemIdsHandler() provides a way for drivers that don't have a delta API to
// still provide delta functionality by comparing the items they have to the items
// the client has. Very inefficient but that's the only possible workaround.
// It's a function so that it is only called if the driver needs these IDs. For
// drivers with a delta functionality it's a noop.
allItemIdsHandler: async () => {
return BaseItem.syncedItemIds(syncTargetId);
},
wipeOutFailSafe: Setting.value('sync.wipeOutFailSafe'),
logger: logger,
});
2017-07-23 16:11:44 +02:00
const remotes: RemoteItem[] = listResult.items;
2018-01-08 22:36:00 +02:00
2019-07-29 15:43:53 +02:00
this.logSyncOperation('fetchingTotal', null, null, 'Fetching delta items from sync target', remotes.length);
2017-07-18 21:57:49 +02:00
const remoteIds = remotes.map(r => BaseItem.pathToId(r.path));
const locals = await BaseItem.loadItemsByIds(remoteIds);
for (const remote of remotes) {
if (this.cancelling()) break;
let needsToDownload = true;
if (this.api().supportsAccurateTimestamp) {
const local = locals.find(l => l.id === BaseItem.pathToId(remote.path));
if (local && local.updated_time === remote.jop_updated_time) needsToDownload = false;
}
if (needsToDownload) {
this.downloadQueue_.push(remote.path, async () => {
return this.apiCall('get', remote.path);
});
}
}
for (let i = 0; i < remotes.length; i++) {
2019-07-29 15:43:53 +02:00
if (this.cancelling() || this.testingHooks_.indexOf('cancelDeltaLoop2') >= 0) {
hasCancelled = true;
break;
2017-07-18 22:03:07 +02:00
}
2019-07-29 15:43:53 +02:00
this.logSyncOperation('fetchingProcessed', null, null, 'Processing fetched item');
const remote = remotes[i];
if (!BaseItem.isSystemPath(remote.path)) continue; // The delta API might return things like the .sync, .resource or the root folder
const loadContent = async () => {
const task = await this.downloadQueue_.waitForResult(path);
if (task.error) throw task.error;
if (!task.result) return null;
return await BaseItem.unserialize(task.result);
};
const path = remote.path;
const remoteId = BaseItem.pathToId(path);
let action = null;
2019-07-29 15:43:53 +02:00
let reason = '';
let local = locals.find(l => l.id === remoteId);
let ItemClass = null;
let content = null;
try {
if (!local) {
if (remote.isDeleted !== true) {
2019-07-29 15:43:53 +02:00
action = 'createLocal';
reason = 'remote exists but local does not';
content = await loadContent();
ItemClass = content ? BaseItem.itemClass(content) : null;
}
} else {
ItemClass = BaseItem.itemClass(local);
local = ItemClass.filter(local);
if (remote.isDeleted) {
2019-07-29 15:43:53 +02:00
action = 'deleteLocal';
reason = 'remote has been deleted';
} else {
if (this.api().supportsAccurateTimestamp && remote.jop_updated_time === local.updated_time) {
// Nothing to do, and no need to fetch the content
} else {
content = await loadContent();
if (content && content.updated_time > local.updated_time) {
action = 'updateLocal';
reason = 'remote is more recent than local';
}
}
}
2017-07-18 22:03:07 +02:00
}
} catch (error) {
if (error.code === 'rejectedByTarget') {
this.progressReport_.errors.push(error);
logger.warn(`Rejected by target: ${path}: ${error.message}`);
action = null;
} else {
2019-09-19 23:51:18 +02:00
error.message = `On file ${path}: ${error.message}`;
throw error;
}
2017-07-18 22:03:07 +02:00
}
2017-07-18 21:57:49 +02:00
if (this.testingHooks_.indexOf('skipRevisions') >= 0 && content && content.type_ === BaseModel.TYPE_REVISION) action = null;
if (!action) continue;
2017-07-18 21:57:49 +02:00
this.logSyncOperation(action, local, remote, reason);
2017-07-18 21:57:49 +02:00
if (action === 'createLocal' || action === 'updateLocal') {
if (content === null) {
logger.warn(`Remote has been deleted between now and the delta() call? In that case it will be handled during the next sync: ${path}`);
continue;
}
content = ItemClass.filter(content);
// 2017-12-03: This was added because the new user_updated_time and user_created_time properties were added
// to the items. However changing the database is not enough since remote items that haven't been synced yet
// will not have these properties and, since they are required, it would cause a problem. So this check
// if they are present and, if not, set them to a reasonable default.
// Let's leave these two lines for 6 months, by which time all the clients should have been synced.
if (!content.user_updated_time) content.user_updated_time = content.updated_time;
if (!content.user_created_time) content.user_created_time = content.created_time;
const options: any = {
autoTimestamp: false,
nextQueries: BaseItem.updateSyncTimeQueries(syncTargetId, content, time.unixMs()),
changeSource: ItemChange.SOURCE_SYNC,
};
if (action === 'createLocal') options.isNew = true;
if (action === 'updateLocal') options.oldItem = local;
const creatingOrUpdatingResource = content.type_ === BaseModel.TYPE_RESOURCE && (action === 'createLocal' || action === 'updateLocal');
if (creatingOrUpdatingResource) {
if (content.size >= this.maxResourceSize()) {
2019-09-19 23:51:18 +02:00
await handleCannotSyncItem(ItemClass, syncTargetId, content, `File "${content.title}" is larger than allowed ${this.maxResourceSize()} bytes. Beyond this limit, the mobile app would crash.`, BaseItem.SYNC_ITEM_LOCATION_REMOTE);
continue;
}
await ResourceLocalState.save({ resource_id: content.id, fetch_status: Resource.FETCH_STATUS_IDLE });
}
if (content.type_ === ModelType.MasterKey) {
// Special case for master keys - if we download
// one, we only add it to the store if it's not
// already there. That can happen for example if
// the new E2EE migration was processed at a
// time a master key was still on the sync
// target. In that case, info.json would not
// have it.
//
// If info.json already has the key we shouldn't
// update because the most up to date keys
// should always be in info.json now.
const existingMasterKey = await MasterKey.load(content.id);
if (!existingMasterKey) {
logger.info(`Downloaded a master key that was not in info.json - adding it to the store. ID: ${content.id}`);
await MasterKey.save(content);
}
} else {
await ItemClass.save(content, options);
}
if (creatingOrUpdatingResource) this.dispatch({ type: 'SYNC_CREATED_OR_UPDATED_RESOURCE', id: content.id });
2018-10-08 20:11:53 +02:00
// if (!hasAutoEnabledEncryption && content.type_ === BaseModel.TYPE_MASTER_KEY && !masterKeysBefore) {
// hasAutoEnabledEncryption = true;
// logger.info('One master key was downloaded and none was previously available: automatically enabling encryption');
// logger.info('Using master key: ', content.id);
// await this.encryptionService().enableEncryption(content);
// await this.encryptionService().loadMasterKeysFromSettings();
// logger.info('Encryption has been enabled with downloaded master key as active key. However, note that no password was initially supplied. It will need to be provided by user.');
// }
2017-07-18 22:03:07 +02:00
2019-07-29 15:43:53 +02:00
if (content.encryption_applied) this.dispatch({ type: 'SYNC_GOT_ENCRYPTED_ITEM' });
} else if (action === 'deleteLocal') {
if (local.type_ === BaseModel.TYPE_FOLDER) {
localFoldersToDelete.push(local);
continue;
}
2017-07-18 22:03:07 +02:00
const ItemClass = BaseItem.itemClass(local.type_);
await ItemClass.delete(local.id, { trackDeleted: false, changeSource: ItemChange.SOURCE_SYNC });
}
}
// If user has cancelled, don't record the new context (2) so that synchronisation
// can start again from the previous context (1) next time. It is ok if some items
// have been synced between (1) and (2) because the loop above will handle the same
// items being synced twice as an update. If the local and remote items are identical
// the update will simply be skipped.
if (!hasCancelled) {
if (options.saveContextHandler) {
const deltaToSave = { ...listResult.context };
// Remove these two variables because they can be large and can be rebuilt
// the next time the sync is started.
delete deltaToSave.statsCache;
delete deltaToSave.statIdsCache;
options.saveContextHandler({ delta: deltaToSave });
}
if (!listResult.hasMore) {
newDeltaContext = listResult.context;
break;
2017-07-18 22:03:07 +02:00
}
context = listResult.context;
2017-07-18 22:03:07 +02:00
}
}
outputContext.delta = newDeltaContext ? newDeltaContext : lastContext.delta;
// ------------------------------------------------------------------------
// Delete the folders that have been collected in the loop above.
// Folders are always deleted last, and only if they are empty.
// If they are not empty it's considered a conflict since whatever deleted
// them should have deleted their content too. In that case, all its notes
// are marked as "is_conflict".
// ------------------------------------------------------------------------
if (!this.cancelling()) {
for (let i = 0; i < localFoldersToDelete.length; i++) {
const item = localFoldersToDelete[i];
const noteIds = await Folder.noteIds(item.id);
if (noteIds.length) {
// CONFLICT
await Folder.markNotesAsConflict(item.id);
}
await Folder.delete(item.id, { deleteChildren: false, changeSource: ItemChange.SOURCE_SYNC, trackDeleted: false });
}
2017-07-18 22:03:07 +02:00
}
2017-07-18 21:57:49 +02:00
if (!this.cancelling()) {
await BaseItem.deleteOrphanSyncItems();
2017-07-18 22:03:07 +02:00
}
} // DELTA STEP
2017-06-29 20:03:16 +02:00
} catch (error) {
if (throwOnError) {
errorToThrow = error;
} else if (error && ['cannotEncryptEncrypted', 'noActiveMasterKey', 'processingPathTwice', 'failSafe', 'lockError', 'outdatedSyncTarget'].indexOf(error.code) >= 0) {
// Only log an info statement for this since this is a common condition that is reported
// in the application, and needs to be resolved by the user.
// Or it's a temporary issue that will be resolved on next sync.
logger.info(error.message);
if (error.code === 'failSafe' || error.code === 'lockError') {
// Get the message to display on UI, but not in testing to avoid poluting stdout
if (!shim.isTestingEnv()) this.progressReport_.errors.push(error.message);
this.logLastRequests();
}
} else if (error.code === 'unknownItemType') {
this.progressReport_.errors.push(_('Unknown item type downloaded - please upgrade Joplin to the latest version'));
logger.error(error);
} else {
logger.error(error);
if (error.details) logger.error('Details:', error.details);
// Don't save to the report errors that are due to things like temporary network errors or timeout.
if (!shim.fetchRequestCanBeRetried(error)) {
this.progressReport_.errors.push(error);
this.logLastRequests();
}
}
2017-06-20 21:18:19 +02:00
}
2017-05-18 21:58:01 +02:00
if (syncLock) {
this.lockHandler().stopAutoLockRefresh(syncLock);
await this.lockHandler().releaseLock(LockType.Sync, this.lockClientType(), this.clientId_);
}
this.syncTargetIsLocked_ = false;
if (this.cancelling()) {
logger.info('Synchronisation was cancelled.');
this.cancelling_ = false;
}
// After syncing, we run the share service maintenance, which is going
// to fetch share invitations, if any.
if (this.shareService_) {
try {
await this.shareService_.maintenance();
} catch (error) {
logger.error('Could not run share service maintenance:', error);
}
}
2017-07-16 23:17:22 +02:00
this.progressReport_.completedTime = time.unixMs();
2019-09-19 23:51:18 +02:00
this.logSyncOperation('finished', null, null, `Synchronisation finished [${synchronizationId}]`);
2017-07-14 21:06:01 +02:00
await this.logSyncSummary(this.progressReport_);
eventManager.emit('syncComplete', {
withErrors: Synchronizer.reportHasErrors(this.progressReport_),
});
this.onProgress_ = function() {};
2017-07-14 21:06:01 +02:00
this.progressReport_ = {};
2017-07-16 23:17:22 +02:00
this.dispatch({ type: 'SYNC_COMPLETED', isFullSync: this.isFullSync(syncSteps) });
2017-07-30 22:22:57 +02:00
this.state_ = 'idle';
2017-07-18 21:57:49 +02:00
if (errorToThrow) throw errorToThrow;
2017-07-18 21:57:49 +02:00
return outputContext;
2017-05-18 21:58:01 +02:00
}
}