Improved logging handling

CliClient/app/main.js

@@ -10,20 +10,34 @@ import { Folder } from 'src/models/folder.js';
 import { Note } from 'src/models/note.js';
 import { Setting } from 'src/models/setting.js';
 import { Synchronizer } from 'src/synchronizer.js';
+import { Logger } from 'src/logger.js';
 import { uuid } from 'src/uuid.js';
 import { sprintf } from 'sprintf-js';
 import { _ } from 'src/locale.js';
 import os from 'os';
 import fs from 'fs-extra';
 
+const APPNAME = 'joplin';
+const dataDir = os.homedir() + '/.local/share/' + APPNAME;
+
+process.on('unhandledRejection', (reason, p) => {
+	console.log('Unhandled Rejection at: Promise', p, 'reason:', reason);
+});
+
+const logger = new Logger();
+logger.addTarget('file', { path: dataDir + '/log.txt' });
+logger.setLevel(Logger.LEVEL_DEBUG);
+
+const syncLogger = new Logger();
+syncLogger.addTarget('file', { path: dataDir + '/log-sync.txt' });
+syncLogger.setLevel(Logger.LEVEL_DEBUG);
 
 let db = new Database(new DatabaseDriverNode());
+db.setLogger(logger);
 let synchronizer_ = null;
 const vorpal = require('vorpal')();
-const APPNAME = 'joplin';
 
 async function main() {
-	let dataDir = os.homedir() + '/.local/share/' + APPNAME;
 	await fs.mkdirp(dataDir, 0o755);
 
 	await db.open({ name: dataDir + '/database.sqlite' });
@@ -58,17 +72,23 @@ async function main() {
 			});
 
 			let appDir = await driver.api().appDirectory();
-			console.info('App dir: ' + appDir);
+			logger.info('App dir: ' + appDir);
 			fileApi = new FileApi(appDir, driver);
+			fileApi.setLogger(logger);
 		} else {
 			throw new Error('Unknown backend: ' + remoteBackend);
 		}
 
 		synchronizer_ = new Synchronizer(db, fileApi);
+		synchronizer_.setLogger(syncLogger);
 
 		return synchronizer_;
 	}
 
+	// let s = await synchronizer('onedrive');
+	// await synchronizer_.start();
+	// return;
+
 	function switchCurrentFolder(folder) {
 		currentFolder = folder;
 		updatePrompt();
@@ -356,7 +376,7 @@ async function main() {
 			synchronizer('onedrive').then((s) => {
 				return s.start();
 			}).catch((error) => {
-				console.error(error);
+				logger.error(error);
 			}).then(() => {
 				end();
 			});

CliClient/tests/synchronizer.js

@@ -101,22 +101,18 @@ describe('Synchronizer', function() {
 		let note2 = await Note.load(note1.id);
 		note2.title = "Updated on client 2";
 		await Note.save(note2);
-
 		note2 = await Note.load(note2.id);
 
 		await synchronizer().start();
 
-		let files = await fileApi().list();
-
 		await switchClient(1);
 
 		await synchronizer().start();
 
-		note1 = await Note.load(note1.id);
+		let all = await Folder.all(true);
+		let files = await fileApi().list();
 
-		expect(!!note1).toBe(true);
-		expect(note1.title).toBe(note2.title);
-		expect(note1.body).toBe(note2.body);
+		await localItemsSameAsRemote(all, expect);
 
 		done();
 	});

CliClient/tests/test-utils.js

@@ -90,7 +90,7 @@ function db(id = null) {
 
 function synchronizer(id = null) {
 	if (id === null) id = currentClient_;
-	console.info('SYNC', id);
+	//console.info('SYNC', id);
 	return synchronizers_[id];
 }
 

ReactNativeClient/src/base-model.js

@@ -129,7 +129,6 @@ class BaseModel {
 
 	static loadByField(fieldName, fieldValue) {	
 		return this.modelSelectOne('SELECT * FROM ' + this.tableName() + ' WHERE `' + fieldName + '` = ?', [fieldValue]);
-		//return this.db().selectOne('SELECT * FROM ' + this.tableName() + ' WHERE `' + fieldName + '` = ?', [fieldValue]);
 	}
 
 	static applyPatch(model, patch) {

ReactNativeClient/src/database.js

@@ -1,6 +1,6 @@
-import { Log } from 'src/log.js';
 import { uuid } from 'src/uuid.js';
 import { promiseChain } from 'src/promise-utils.js';
+import { Logger } from 'src/logger.js'
 import { _ } from 'src/locale.js'
 
 const structureSql = `
@@ -115,6 +115,30 @@ class Database {
 		this.tableFields_ = null;
 		this.driver_ = driver;
 		this.inTransaction_ = false;
+
+		this.logger_ = new Logger();
+		this.logger_.addTarget('console');
+		this.logger_.setLevel(Logger.LEVEL_DEBUG);
+	}
+
+	// Converts the SQLite error to a regular JS error
+	// so that it prints a stacktrace when passed to
+	// console.error()
+	sqliteErrorToJsError(error, sql, params = null) {
+		let msg = sql;
+		if (params) msg += ': ' + JSON.stringify(params);
+		msg += ': ' + error.toString();
+		let output = new Error(msg);
+		if (error.code) output.code = error.code;
+		return output;
+	}
+
+	setLogger(l) {
+		this.logger_ = l;
+	}
+
+	logger() {
+		return this.logger_;
 	}
 
 	setDebugEnabled(v) {
@@ -136,26 +160,32 @@ class Database {
 
 	open(options) {
 		return this.driver().open(options).then((db) => {
-			Log.info('Database was open successfully');
+			this.logger().info('Database was open successfully');
 			return this.initialize();
 		}).catch((error) => {
-			Log.error('Cannot open database: ', error);
+			this.logger().error('Cannot open database: ', error);
 		});
 	}
 
 	selectOne(sql, params = null) {
 		this.logQuery(sql, params);
-		return this.driver().selectOne(sql, params);
+		return this.driver().selectOne(sql, params).catch((error) => {
+			throw this.sqliteErrorToJsError(error, sql, params);
+		});
 	}
 
 	selectAll(sql, params = null) {
 		this.logQuery(sql, params);
-		return this.driver().selectAll(sql, params);
+		return this.driver().selectAll(sql, params).catch((error) => {
+			throw this.sqliteErrorToJsError(error, sql, params);
+		});
 	}
 
 	exec(sql, params = null) {
 		this.logQuery(sql, params);
-		return this.driver().exec(sql, params);
+		return this.driver().exec(sql, params).catch((error) => {
+			throw this.sqliteErrorToJsError(error, sql, params);
+		});
 	}
 
 	transactionExecBatch(queries) {
@@ -254,9 +284,9 @@ class Database {
 	logQuery(sql, params = null) {
 		if (!this.debugMode()) return;
 		if (params !== null) {
-			Log.debug('DB: ' + sql, JSON.stringify(params));
+			this.logger().debug('DB: ' + sql, JSON.stringify(params));
 		} else {
-			Log.debug('DB: ' + sql);
+			this.logger().debug('DB: ' + sql);
 		}
 	}
 
@@ -329,7 +359,7 @@ class Database {
 	}
 
 	refreshTableFields() {
-		Log.info('Initializing tables...');
+		this.logger().info('Initializing tables...');
 		let queries = [];
 		queries.push(this.wrapQuery('DELETE FROM table_fields'));
 
@@ -367,10 +397,10 @@ class Database {
 	}
 
 	initialize() {
-		Log.info('Checking for database schema update...');
+		this.logger().info('Checking for database schema update...');
 
 		return this.selectOne('SELECT * FROM version LIMIT 1').then((row) => {
-			Log.info('Current database version', row);
+			this.logger().info('Current database version', row);
 			// TODO: version update logic
 
 			// TODO: only do this if db has been updated:
@@ -409,9 +439,8 @@ class Database {
 		// 	return p;
 
 		}).catch((error) => {
-			//console.info(error.code);
 			if (error && error.code != 0 && error.code != 'SQLITE_ERROR') {
-				Log.error(error);
+				this.logger().error(error);
 				return;
 			}
 	
@@ -420,14 +449,14 @@ class Database {
 			// which means the database is empty and the tables need to be created.
 			// If it's any other error there's nothing we can do anyway.
 
-			Log.info('Database is new - creating the schema...');
+			this.logger().info('Database is new - creating the schema...');
 
 			let queries = this.wrapQueries(this.sqlStringToLines(structureSql));
 			queries.push(this.wrapQuery('INSERT INTO settings (`key`, `value`, `type`) VALUES ("clientId", "' + uuid.create() + '", "' + Database.enumId('settings', 'string') + '")'));
 			queries.push(this.wrapQuery('INSERT INTO folders (`id`, `title`, `is_default`, `created_time`) VALUES ("' + uuid.create() + '", "' + _('Default list') + '", 1, ' + Math.round((new Date()).getTime() / 1000) + ')'));
 
 			return this.transactionExecBatch(queries).then(() => {
-				Log.info('Database schema created successfully');
+				this.logger().info('Database schema created successfully');
 				// Calling initialize() now that the db has been created will make it go through
 				// the normal db update process (applying any additional patch).
 				return this.refreshTableFields();

ReactNativeClient/src/file-api-driver-onedrive.js

@@ -1,5 +1,6 @@
 import moment from 'moment';
 import { time } from 'src/time-utils.js';
+import { dirname, basename } from 'src/path-utils.js';
 import { OneDriveApi } from 'src/onedrive-api.js';
 
 class FileApiDriverOneDrive {
@@ -40,8 +41,9 @@ class FileApiDriverOneDrive {
 	}
 
 	async stat(path) {
+		let item = null;
 		try {
-			let item = await this.api_.execJson('GET', this.makePath_(path), this.itemFilter_());
+			item = await this.api_.execJson('GET', this.makePath_(path), this.itemFilter_());
 		} catch (error) {
 			if (error.error.code == 'itemNotFound') return null;
 			throw error;
@@ -64,8 +66,9 @@ class FileApiDriverOneDrive {
 	}
 
 	async get(path) {
+		let content = null;
 		try {
-			let content = await this.api_.execText('GET', this.makePath_(path) + ':/content');
+			content = await this.api_.execText('GET', this.makePath_(path) + ':/content');
 		} catch (error) {
 			if (error.error.code == 'itemNotFound') return null;
 			throw error;
@@ -73,8 +76,17 @@ class FileApiDriverOneDrive {
 		return content;
 	}
 
-	mkdir(path) {
-		throw new Error('Not implemented');
+	async mkdir(path) {
+		let item = await this.stat(path);
+		if (item) return item;
+
+		let parentPath = dirname(path);
+		item = await this.api_.execJson('POST', this.makePath_(parentPath) + ':/children', this.itemFilter_(), {
+			name: basename(path),
+			folder: {},
+		});
+
+		return this.makeItem_(item);
 	}
 
 	put(path, content) {
@@ -88,8 +100,16 @@ class FileApiDriverOneDrive {
 		return this.api_.exec('DELETE', this.makePath_(path));
 	}
 
-	move(oldPath, newPath) {
-		throw new Error('Not implemented');
+	async move(oldPath, newPath) {
+		let newDir = dirname(newPath);
+		let newName = basename(newPath);
+
+		let item = await this.api_.execJson('PATCH', this.makePath_(oldPath), this.itemFilter_(), {
+			name: newName,
+			parentReference: { path: newDir },
+		});
+
+		return this.makeItem_(item);
 	}
 
 	format() {

ReactNativeClient/src/file-api.js

@@ -1,14 +1,20 @@
 import { isHidden } from 'src/path-utils.js';
+import { Logger } from 'src/logger.js';
 
 class FileApi {
 
 	constructor(baseDir, driver) {
 		this.baseDir_ = baseDir;
 		this.driver_ = driver;
+		this.logger_ = new Logger();
 	}
 
-	dlog(s) {
-		console.info('FileApi: ' + s);
+	setLogger(l) {
+		this.logger_ = l;
+	}
+
+	logger() {
+		return this.logger_;
 	}
 
 	fullPath_(path) {
@@ -21,7 +27,7 @@ class FileApi {
 		if (!options) options = {};
 		if (!('includeHidden' in options)) options.includeHidden = false;
 
-		this.dlog('list');
+		this.logger().debug('list');
 		return this.driver_.list(this.baseDir_).then((items) => {
 			if (!options.includeHidden) {
 				let temp = [];
@@ -35,17 +41,17 @@ class FileApi {
 	}
 
 	setTimestamp(path, timestamp) {
-		this.dlog('setTimestamp ' + path);
+		this.logger().debug('setTimestamp ' + path);
 		return this.driver_.setTimestamp(this.fullPath_(path), timestamp);
 	}
 
 	mkdir(path) {
-		this.dlog('delete ' + path);
+		this.logger().debug('mkdir ' + path);
 		return this.driver_.mkdir(this.fullPath_(path));
 	}
 
 	stat(path) {
-		this.dlog('stat ' + path);
+		this.logger().debug('stat ' + path);
 		return this.driver_.stat(this.fullPath_(path)).then((output) => {
 			if (!output) return output;
 			output.path = path;
@@ -54,22 +60,22 @@ class FileApi {
 	}
 
 	get(path) {
-		this.dlog('get ' + path);
+		this.logger().debug('get ' + path);
 		return this.driver_.get(this.fullPath_(path));
 	}
 
 	put(path, content) {
-		this.dlog('put ' + path);
+		this.logger().debug('put ' + path);
 		return this.driver_.put(this.fullPath_(path), content);
 	}
 
 	delete(path) {
-		this.dlog('delete ' + path);
+		this.logger().debug('delete ' + path);
 		return this.driver_.delete(this.fullPath_(path));
 	}
 
 	move(oldPath, newPath) {
-		this.dlog('move ' + oldPath + ' => ' + newPath);
+		this.logger().debug('move ' + oldPath + ' => ' + newPath);
 		return this.driver_.move(this.fullPath_(oldPath), this.fullPath_(newPath));
 	}
 

ReactNativeClient/src/logger.js

@@ -0,0 +1,76 @@
+import moment from 'moment';
+import fs from 'fs-extra';
+
+class Logger {
+
+	constructor() {
+		this.targets_ = [];
+		this.level_ = Logger.LEVEL_ERROR;
+	}
+
+	setLevel(level) {
+		this.level_ = level;
+	}
+
+	level() {
+		return this.level_;
+	}
+
+	clearTargets() {
+		this.targets_.clear();
+	}
+
+	addTarget(type, options = null) {
+		let target = { type: type };
+		for (let n in options) {
+			if (!options.hasOwnProperty(n)) continue;
+			target[n] = options[n];
+		}
+
+		this.targets_.push(target);
+	}
+
+	log(level, object) {
+		if (this.level() < level || !this.targets_.length) return;
+
+		let levelString = '';
+		if (this.level() == Logger.LEVEL_INFO) levelString = '[info] ';
+		if (this.level() == Logger.LEVEL_WARN) levelString = '[warn] ';
+		if (this.level() == Logger.LEVEL_ERROR) levelString = '[error] ';
+		let line = moment().format('YYYY-MM-DD HH:mm:ss') + ': ' + levelString;
+
+		for (let i = 0; i < this.targets_.length; i++) {
+			let t = this.targets_[i];
+			if (t.type == 'console') {
+				let fn = 'debug';
+				if (level = Logger.LEVEL_ERROR) fn = 'error';
+				if (level = Logger.LEVEL_WARN) fn = 'warn';
+				if (level = Logger.LEVEL_INFO) fn = 'info';
+				if (typeof object === 'object') {
+					console[fn](line, object);
+				} else {
+					console[fn](line + object);
+				}
+			} else if (t.type == 'file') {
+				if (typeof object === 'object') object = JSON.stringify(object);
+				fs.appendFile(t.path, line + object + "\n", (error) => {
+					if (error) throw error;
+				});
+			}
+		}
+	}
+
+	error(object) { return this.log(Logger.LEVEL_ERROR, object); }
+	warn(object)  { return this.log(Logger.LEVEL_WARN, object); }
+	info(object)  { return this.log(Logger.LEVEL_INFO, object); }
+	debug(object) { return this.log(Logger.LEVEL_DEBUG, object); }
+
+}
+
+Logger.LEVEL_NONE = 0;
+Logger.LEVEL_ERROR = 10;
+Logger.LEVEL_WARN = 20;
+Logger.LEVEL_INFO = 30;
+Logger.LEVEL_DEBUG = 40;
+
+export { Logger };

ReactNativeClient/src/models/note.js

@@ -44,11 +44,11 @@ class Note extends BaseItem {
 	}
 
 	static previews(parentId) {
-		return this.modelSelectAll('SELECT ' + this.previewFieldsSql() + ' FROM is_conflict = 0 AND notes WHERE parent_id = ?', [parentId]);
+		return this.modelSelectAll('SELECT ' + this.previewFieldsSql() + ' FROM notes WHERE is_conflict = 0 AND parent_id = ?', [parentId]);
 	}
 
 	static preview(noteId) {
-		return this.modelSelectOne('SELECT ' + this.previewFieldsSql() + ' FROM is_conflict = 0 AND notes WHERE id = ?', [noteId]);
+		return this.modelSelectOne('SELECT ' + this.previewFieldsSql() + ' FROM notes WHERE is_conflict = 0 AND id = ?', [noteId]);
 	}
 
 	static conflictedNotes() {

ReactNativeClient/src/onedrive-api.js

@@ -77,7 +77,7 @@ class OneDriveApi {
 			options.method = method;
 		}
 
-		if (method == 'PATCH') {
+		if (method == 'PATCH' || method == 'POST') {
 			options.headers['Content-Type'] = 'application/json';
 			if (data) data = JSON.stringify(data);
 		}
@@ -88,8 +88,8 @@ class OneDriveApi {
 
 		if (data) options.body = data;
 
-		console.info(method + ' ' + url);
-		console.info(data);
+		// console.info(method + ' ' + url);
+		// console.info(data);
 
 		for (let i = 0; i < 5; i++) {
 			options.headers['Authorization'] = 'bearer ' + this.token();
@@ -98,8 +98,6 @@ class OneDriveApi {
 			if (!response.ok) {
 				let error = await response.json();
 
-				console.info(error);
-
 				if (error && error.error && error.error.code == 'InvalidAuthenticationToken') {
 					await this.refreshAccessToken();
 					continue;

ReactNativeClient/src/path-utils.js

@@ -1,3 +1,10 @@
+function dirname(path) {
+	if (!path) throw new Error('Path is empty');
+	let s = path.split('/');
+	s.pop();
+	return s.join('/');
+}
+
 function basename(path) {
 	if (!path) throw new Error('Path is empty');
 	let s = path.split('/');
@@ -10,4 +17,4 @@ function isHidden(path) {
 	return b[0] === '.';
 }
 
-export { basename, isHidden };
+export { basename, dirname, isHidden };

ReactNativeClient/src/synchronizer.js

@@ -6,7 +6,8 @@ import { Note } from 'src/models/note.js';
 import { BaseModel } from 'src/base-model.js';
 import { sprintf } from 'sprintf-js';
 import { time } from 'src/time-utils.js';
-import { Log } from 'src/log.js'
+import { Logger } from 'src/logger.js'
+import moment from 'moment';
 
 class Synchronizer {
 
@@ -14,6 +15,7 @@ class Synchronizer {
 		this.db_ = db;
 		this.api_ = api;
 		this.syncDirName_ = '.sync';
+		this.logger_ = new Logger();
 	}
 
 	db() {
@@ -24,6 +26,14 @@ class Synchronizer {
 		return this.api_;
 	}
 
+	setLogger(l) {
+		this.logger_ = l;
+	}
+
+	logger() {
+		return this.logger_;
+	}
+
 	async createWorkDir() {
 		if (this.syncWorkDir_) return this.syncWorkDir_;
 		let dir = await this.api().mkdir(this.syncDirName_);
@@ -36,6 +46,8 @@ class Synchronizer {
 		// last sync and apply the changes to remote.
 		// ------------------------------------------------------------------------
 
+		this.logger().info('Starting synchronization...');
+
 		await this.createWorkDir();
 
 		let donePaths = [];
@@ -74,7 +86,7 @@ class Synchronizer {
 					}
 				}
 
-				console.info('Sync action (1): ' + action);
+				this.logger().debug('Sync action (1): ' + action);
 
 				if (action == 'createRemote' || action == 'updateRemote') {
 
@@ -132,7 +144,7 @@ class Synchronizer {
 		for (let i = 0; i < deletedItems.length; i++) {
 			let item = deletedItems[i];
 			let path = BaseItem.systemPath(item.item_id)
-			console.info('Sync action (2): deleteRemote');
+			this.logger().debug('Sync action (2): deleteRemote');
 			await this.api().delete(path);
 			await BaseModel.remoteDeletedItem(item.item_id);
 		}
@@ -155,23 +167,27 @@ class Synchronizer {
 			if (donePaths.indexOf(path) > 0) continue;
 
 			let action = null;
+			let reason = '';
 			let local = await BaseItem.loadItemByPath(path);
 			if (!local) {
 				action = 'createLocal';
+				reason = 'Local exists but remote does not';
 			} else {
 				if (remote.updated_time > local.updated_time) {
 					action = 'updateLocal';
+					reason = sprintf('Remote (%s) is more recent than local (%s)', time.unixMsToIso(remote.updated_time), time.unixMsToIso(local.updated_time));
 				}
 			}
 
 			if (!action) continue;
 
-			console.info('Sync action (3): ' + action);
+			this.logger().debug('Sync action (3): ' + action);
+			this.logger().debug('Reason: ' + reason);
 
 			if (action == 'createLocal' || action == 'updateLocal') {
 				let content = await this.api().get(path);
 				if (!content) {
-					Log.warn('Remote item has been deleted between now and the list() call? In that case it will handled during the next sync: ' + path);
+					this.logger().warn('Remote item has been deleted between now and the list() call? In that case it will handled during the next sync: ' + path);
 					continue;
 				}
 				content = BaseItem.unserialize(content);
@@ -192,11 +208,14 @@ class Synchronizer {
 		let noteIds = await Folder.syncedNoteIds();
 		for (let i = 0; i < noteIds.length; i++) {
 			if (remoteIds.indexOf(noteIds[i]) < 0) {
-				console.info('Sync action (4): deleteLocal: ' + noteIds[i]);
+				this.logger().debug('Sync action (4): deleteLocal: ' + noteIds[i]);
 				await Note.delete(noteIds[i], { trackDeleted: false });
 			}
 		}
 
+		// Number of sync items (Created, updated, deleted Local/Remote)
+		// Total number of items
+
 		return Promise.resolve();
 	}
 

ReactNativeClient/src/time-utils.js

@@ -1,3 +1,5 @@
+import moment from 'moment';
+
 let time = {
 
 	unix() {
@@ -10,7 +12,11 @@ let time = {
 
 	unixMsToS(ms) {
 		return Math.floor(ms / 1000);
-	}
+	},
+
+	unixMsToIso(ms) {
+		return moment.unix(ms / 1000).utc().format('YYYY-MM-DDTHH:mm:ss.SSS') + 'Z';
+	},
 
 }