unify logging routines, log via the component. Log to a file. Add a couple of crappy attempts at nicer logging output

This commit is contained in:
Dan Mills 2007-09-26 15:28:01 -07:00
parent d4c815234e
commit 53ae8e84c5
3 changed files with 186 additions and 81 deletions

View File

@ -11,7 +11,7 @@
* for the specific language governing rights and limitations under the
* License.
*
* The Original Code is Places.
* The Original Code is Bookmarks Sync.
*
* The Initial Developer of the Original Code is Mozilla.
* Portions created by the Initial Developer are Copyright (C) 2007
@ -85,6 +85,25 @@ BookmarksSyncService.prototype = {
return this.__os;
},
__console: null,
get _console() {
if (!this.__console)
this.__console = Cc["@mozilla.org/consoleservice;1"]
.getService(Ci.nsIConsoleService);
return this.__console;
},
__dirSvc: null,
get _dirSvc() {
if (!this.__dirSvc)
this.__dirSvc = Cc["@mozilla.org/file/directory_service;1"].
getService(Ci.nsIProperties);
return this.__dirSvc;
},
// File output stream to a log file
_log: null,
// Timer object for yielding to the main loop
_timer: null,
@ -101,6 +120,7 @@ BookmarksSyncService.prototype = {
},
_init: function BSS__init() {
this._initLog();
let serverURL = 'https://dotmoz.mozilla.org/';
try {
let branch = Cc["@mozilla.org/preferences-service;1"].
@ -108,11 +128,33 @@ BookmarksSyncService.prototype = {
serverURL = branch.getCharPref("browser.places.sync.serverURL");
}
catch (ex) { /* use defaults */ }
LOG("Bookmarks login server: " + serverURL);
this.notice("Bookmarks login server: " + serverURL);
this._dav = new DAVCollection(serverURL);
this._readSnapshot();
},
_initLog: function BSS__initLog() {
let dirSvc = Cc["@mozilla.org/file/directory_service;1"].
getService(Ci.nsIProperties);
let file = dirSvc.get("ProfD", Ci.nsIFile);
file.append("bm-sync.log");
file.QueryInterface(Ci.nsILocalFile);
if (file.exists())
file.remove(false);
file.create(file.NORMAL_FILE_TYPE, PERMS_FILE);
this._log = Cc["@mozilla.org/network/file-output-stream;1"]
.createInstance(Ci.nsIFileOutputStream);
let flags = MODE_WRONLY | MODE_CREATE | MODE_APPEND;
this._log.init(file, flags, PERMS_FILE, 0);
let str = "Bookmarks Sync Log\n------------------\n\n";
this._log.write(str, str.length);
this._log.flush();
},
_saveSnapshot: function BSS__saveSnapshot() {
let dirSvc = Cc["@mozilla.org/file/directory_service;1"].
getService(Ci.nsIProperties);
@ -132,7 +174,6 @@ BookmarksSyncService.prototype = {
let out = {version: this._snapshotVersion, snapshot: this._snapshot};
out = uneval(out);
fos.write(out, out.length);
fos.flush();
fos.close();
},
@ -221,7 +262,7 @@ BookmarksSyncService.prototype = {
},
_nodeParentsInt: function BSS__nodeParentsInt(guid, tree, parents) {
if (!tree[guid] || tree[guid].parentGuid == null)
if (tree[guid] && tree[guid].parentGuid == null)
return parents;
parents.push(tree[guid].parentGuid);
return this._nodeParentsInt(tree[guid].parentGuid, tree, parents);
@ -313,7 +354,7 @@ BookmarksSyncService.prototype = {
return true;
return false;
default:
LOG("_commandLike: Unknown item type: " + uneval(a));
this.notice("_commandLike: Unknown item type: " + uneval(a));
return false;
}
},
@ -438,12 +479,12 @@ BookmarksSyncService.prototype = {
// shutdown protocol
let cookie = yield;
if (cookie != "generator shutdown")
LOG("_reconcile: Error: generator not properly shut down.")
this.notice("_reconcile: Error: generator not properly shut down.")
},
_applyCommandsToObj: function BSS__applyCommandsToObj(commands, obj) {
for (let i = 0; i < commands.length; i++) {
LOG("Applying cmd to obj: " + uneval(commands[i]));
this.notice("Applying cmd to obj: " + uneval(commands[i]));
switch (commands[i].action) {
case "create":
obj[commands[i].guid] = eval(uneval(commands[i].data));
@ -465,7 +506,7 @@ BookmarksSyncService.prototype = {
_applyCommands: function BSS__applyCommands(commandList) {
for (var i = 0; i < commandList.length; i++) {
var command = commandList[i];
LOG("Processing command: " + uneval(command));
this.notice("Processing command: " + uneval(command));
switch (command["action"]) {
case "create":
this._createCommand(command);
@ -477,7 +518,7 @@ BookmarksSyncService.prototype = {
this._editCommand(command);
break;
default:
LOG("unknown action in command: " + command["action"]);
this.notice("unknown action in command: " + command["action"]);
break;
}
}
@ -488,11 +529,11 @@ BookmarksSyncService.prototype = {
let parentId = this._bms.getItemIdForGUID(command.data.parentGuid);
if (parentId <= 0) {
LOG("Warning: creating node with unknown parent -> reparenting to root");
this.notice("Warning: creating node with unknown parent -> reparenting to root");
parentId = this._bms.bookmarksRoot;
}
LOG(" -> creating item");
this.notice(" -> creating item");
switch (command.data.type) {
case 0:
@ -510,7 +551,7 @@ BookmarksSyncService.prototype = {
newId = this._bms.insertSeparator(parentId, command.data.index);
break;
default:
LOG("_createCommand: Unknown item type: " + command.data.type);
this.notice("_createCommand: Unknown item type: " + command.data.type);
break;
}
if (newId)
@ -524,19 +565,19 @@ BookmarksSyncService.prototype = {
switch (type) {
case this._bms.TYPE_BOOKMARK:
// FIXME: check it's an actual bookmark?
LOG(" -> removing bookmark " + command.guid);
this.notice(" -> removing bookmark " + command.guid);
this._bms.removeItem(itemId);
break;
case this._bms.TYPE_FOLDER:
LOG(" -> removing folder " + command.guid);
this.notice(" -> removing folder " + command.guid);
this._bms.removeFolder(itemId);
break;
case this._bms.TYPE_SEPARATOR:
LOG(" -> removing separator " + command.guid);
this.notice(" -> removing separator " + command.guid);
this._bms.removeItem(itemId);
break;
default:
LOG("removeCommand: Unknown item type: " + type);
this.notice("removeCommand: Unknown item type: " + type);
break;
}
},
@ -544,7 +585,7 @@ BookmarksSyncService.prototype = {
_editCommand: function BSS__editCommand(command) {
var itemId = this._bms.getItemIdForGUID(command.guid);
if (itemId == -1) {
LOG("Warning: item for guid " + command.guid + " not found. Skipping.");
this.notice("Warning: item for guid " + command.guid + " not found. Skipping.");
return;
}
@ -557,7 +598,7 @@ BookmarksSyncService.prototype = {
if (existing == -1)
this._bms.setItemGUID(itemId, command.data.guid);
else
LOG("Warning: can't change guid " + command.guid +
this.notice("Warning: can't change guid " + command.guid +
" to " + command.data.guid + ": guid already exists.");
break;
case "title":
@ -575,7 +616,7 @@ BookmarksSyncService.prototype = {
itemId, this._bms.getItemIdForGUID(command.data.parentGuid), -1);
break;
default:
LOG("Warning: Can't change item property: " + key);
this.notice("Warning: Can't change item property: " + key);
break;
}
}
@ -589,6 +630,57 @@ BookmarksSyncService.prototype = {
return this._hsvc.executeQuery(query, this._hsvc.getNewQueryOptions()).root;
},
// FIXME: these print functions need some love...
_mungeJSON: function BSS__mungeJSON(json) {
json.replace(":{type", ":\n\t{type");
json.replace(", ", ",\n\t");
return json;
},
_printNodes: function BSS__printNodes(nodes) {
let nodeList = [];
for (let guid in nodes) {
switch (nodes[guid].type) {
case 0:
nodeList.push(nodes[guid].parentGuid + " b " + guid + "\n\t" +
nodes[guid].title + nodes[guid].uri);
break;
case 6:
nodeList.push(nodes[guid].parentGuid + " f " + guid + "\n\t" +
nodes[guid].title);
break;
case 7:
nodeList.push(nodes[guid].parentGuid + " s " + guid);
break;
default:
nodeList.push("error: unknown item type!\n" + uneval(nodes[guid]));
break;
}
}
nodeList.sort();
return nodeList.join("\n");
},
_printCommands: function BSS__printCommands(commands) {
let ret = [];
for (let i = 0; i < commands.length; i++) {
switch (commands[i].action) {
case "create":
ret.push("create");
break;
case "edit":
ret.push();
break;
case "remove":
ret.push();
break;
default:
ret.push("error: unknown command action!\n" + uneval(commands[i]));
break;
}
}
},
// 1) Fetch server deltas
// 1.1) Construct current server status from snapshot + server deltas
// 1.2) Generate single delta from snapshot -> current server status
@ -602,7 +694,7 @@ BookmarksSyncService.prototype = {
var handlers = this._handlersForGenerator(generator);
this._os.notifyObservers(null, "bookmarks-sync:start", "");
LOG("Beginning sync");
this.notice("Beginning sync");
try {
//this._dav.lock(handlers);
@ -611,7 +703,7 @@ BookmarksSyncService.prototype = {
var localBookmarks = this._getBookmarks();
var localJson = this._wrapNode(localBookmarks);
LOG("local json: " + uneval(localJson));
this.notice("local json:\n" + this._mungeJSON(uneval(localJson)));
// 1) Fetch server deltas
let gsd_gen = this._getServerData(handlers['complete'], localJson);
@ -619,34 +711,34 @@ BookmarksSyncService.prototype = {
gsd_gen.send(gsd_gen);
let server = yield;
LOG("server: " + uneval(server));
this.notice("server: " + uneval(server));
if (server['status'] == 2) {
this._os.notifyObservers(null, "bookmarks-sync:end", "");
LOG("Sync complete");
this.notice("Sync complete");
return;
} else if (server['status'] != 0 && server['status'] != 1) {
this._os.notifyObservers(null, "bookmarks-sync:end", "");
LOG("Sync error");
this.notice("Sync error");
return;
}
LOG("Local snapshot version: " + this._snapshotVersion);
LOG("Latest server version: " + server['version']);
this.notice("Local snapshot version: " + this._snapshotVersion);
this.notice("Latest server version: " + server['version']);
// 2) Generate local deltas from snapshot -> current client status
LOG("Generating local updates");
this.notice("Generating local updates");
var localUpdates = this._detectUpdates(this._snapshot, localJson);
LOG("updates: " + uneval(localUpdates));
this.notice("updates: " + uneval(localUpdates));
if (!(server['status'] == 1 || localUpdates.length > 0)) {
this._os.notifyObservers(null, "bookmarks-sync:end", "");
LOG("Sync complete (1): no changes needed on client or server");
this.notice("Sync complete (1): no changes needed on client or server");
return;
}
// 3) Reconcile client/server deltas and generate new deltas for them.
LOG("Reconciling updates");
this.notice("Reconciling updates");
let callback = function(retval) { continueGenerator(generator, retval); };
let rec_gen = this._reconcile(callback, [localUpdates, server.updates]);
rec_gen.next(); // must initialize before sending
@ -670,15 +762,15 @@ BookmarksSyncService.prototype = {
if (ret.conflicts && ret.conflicts[1])
serverConflicts = ret.conflicts[1];
LOG("Changes for client: " + uneval(clientChanges));
LOG("Changes for server: " + uneval(serverChanges));
LOG("Client conflicts: " + uneval(clientConflicts));
LOG("Server conflicts: " + uneval(serverConflicts));
this.notice("Changes for client: " + uneval(clientChanges));
this.notice("Changes for server: " + uneval(serverChanges));
this.notice("Client conflicts: " + uneval(clientConflicts));
this.notice("Server conflicts: " + uneval(serverConflicts));
if (!(clientChanges.length || serverChanges.length ||
clientConflicts.length || serverConflicts.length)) {
this._os.notifyObservers(null, "bookmarks-sync:end", "");
LOG("Sync complete (2): no changes needed on client or server");
this.notice("Sync complete (2): no changes needed on client or server");
this._snapshot = this._wrapNode(localBookmarks);
this._snapshotVersion = server['version'];
this._saveSnapshot();
@ -686,12 +778,12 @@ BookmarksSyncService.prototype = {
}
if (clientConflicts.length || serverConflicts.length) {
LOG("\nWARNING: Conflicts found, but we don't resolve conflicts yet!\n");
this.notice("\nWARNING: Conflicts found, but we don't resolve conflicts yet!\n");
}
// 3.1) Apply server changes to local store
if (clientChanges.length) {
LOG("Applying changes locally");
this.notice("Applying changes locally");
// Note that we need to need to apply client changes to the
// current tree, not the saved snapshot
this._snapshot = this._applyCommandsToObj(clientChanges,
@ -706,7 +798,7 @@ BookmarksSyncService.prototype = {
// 3.2) Append server delta to the delta file and upload
if (serverChanges.length) {
LOG("Uploading changes to server");
this.notice("Uploading changes to server");
this._snapshot = this._wrapNode(localBookmarks);
this._snapshotVersion = server['version'] + 1;
server['deltas'][this._snapshotVersion] = serverChanges;
@ -714,15 +806,15 @@ BookmarksSyncService.prototype = {
data = yield;
if (data.target.status >= 200 || data.target.status < 300) {
LOG("Successfully updated deltas on server");
this.notice("Successfully updated deltas on server");
this._saveSnapshot();
} else {
// FIXME: revert snapshot here?
LOG("Error: could not update deltas on server");
this.notice("Error: could not update deltas on server");
}
}
this._os.notifyObservers(null, "bookmarks-sync:end", "");
LOG("Sync complete");
this.notice("Sync complete");
} finally {
//this._dav.unlock(handlers);
//data = yield;
@ -752,27 +844,27 @@ BookmarksSyncService.prototype = {
var ret = {status: -1, version: -1, deltas: null, updates: null};
LOG("Getting bookmarks delta from server");
this.notice("Getting bookmarks delta from server");
this._dav.GET("bookmarks.delta", handlers);
var data = yield;
switch (data.target.status) {
case 200:
LOG("Got bookmarks delta from server");
this.notice("Got bookmarks delta from server");
ret.deltas = eval(data.target.responseText);
var tmp = eval(uneval(this._snapshot)); // fixme hack hack hack
// FIXME: debug here for conditional below...
LOG("[sync bowels] local version: " + this._snapshotVersion);
this.notice("[sync bowels] local version: " + this._snapshotVersion);
for (var z in ret.deltas) {
LOG("[sync bowels] remote version: " + z);
this.notice("[sync bowels] remote version: " + z);
}
LOG("foo: " + uneval(ret.deltas[this._snapshotVersion + 1]));
this.notice("foo: " + uneval(ret.deltas[this._snapshotVersion + 1]));
if (ret.deltas[this._snapshotVersion + 1])
LOG("-> is true");
this.notice("-> is true");
else
LOG("-> is false");
this.notice("-> is false");
if (ret.deltas[this._snapshotVersion + 1]) {
// Merge the matching deltas into one, find highest version
@ -784,22 +876,22 @@ BookmarksSyncService.prototype = {
ret.version = v;
}
keys = keys.sort();
LOG("TMP: " + uneval(tmp));
this.notice("TMP: " + uneval(tmp));
for (var i = 0; i < keys.length; i++) {
tmp = this._applyCommandsToObj(ret.deltas[keys[i]], tmp);
LOG("TMP: " + uneval(tmp));
this.notice("TMP: " + uneval(tmp));
}
ret.status = 1;
ret["updates"] = this._detectUpdates(this._snapshot, tmp);
} else if (ret.deltas[this._snapshotVersion]) {
LOG("No changes from server");
this.notice("No changes from server");
ret.status = 0;
ret.version = this._snapshotVersion;
ret.updates = [];
} else {
LOG("Server delta can't update from our snapshot version, getting full file");
this.notice("Server delta can't update from our snapshot version, getting full file");
// generate updates from full local->remote snapshot diff
let gsdf_gen = this._getServerUpdatesFull(handlers['complete'],
localJson);
@ -809,7 +901,7 @@ BookmarksSyncService.prototype = {
if (data.status == 2) {
// we have a delta file but no snapshot on the server. bad.
// fixme?
LOG("Error: Delta file on server, but snapshot file missing. " +
this.notice("Error: Delta file on server, but snapshot file missing. " +
"New snapshot uploaded, may be inconsistent with deltas!");
}
@ -840,7 +932,7 @@ BookmarksSyncService.prototype = {
}
break;
case 404:
LOG("Server has no delta file. Getting full bookmarks file from server");
this.notice("Server has no delta file. Getting full bookmarks file from server");
// generate updates from full local->remote snapshot diff
let gsdf_gen = this._getServerUpdatesFull(handlers['complete'], localJson);
gsdf_gen.next(); // must initialize before sending
@ -849,7 +941,7 @@ BookmarksSyncService.prototype = {
ret.deltas = {};
break;
default:
LOG("Could not get bookmarks.delta: unknown HTTP status code " + data.target.status);
this.notice("Could not get bookmarks.delta: unknown HTTP status code " + data.target.status);
break;
}
this._generatorDone(onComplete, ret)
@ -866,14 +958,14 @@ BookmarksSyncService.prototype = {
switch (data.target.status) {
case 200:
LOG("Got full bookmarks file from server");
this.notice("Got full bookmarks file from server");
var tmp = eval(data.target.responseText);
ret.status = 1;
ret.updates = this._detectUpdates(this._snapshot, tmp.snapshot);
ret.version = tmp.version;
break;
case 404:
LOG("No bookmarks on server. Starting initial sync to server");
this.notice("No bookmarks on server. Starting initial sync to server");
this._snapshot = localJson;
this._snapshotVersion = 1;
@ -881,14 +973,14 @@ BookmarksSyncService.prototype = {
data = yield;
if (data.target.status >= 200 || data.target.status < 300) {
LOG("Initial sync to server successful");
this.notice("Initial sync to server successful");
ret.status = 2;
} else {
LOG("Initial sync to server failed");
this.notice("Initial sync to server failed");
}
break;
default:
LOG("Could not get bookmarks.json: unknown HTTP status code " + data.target.status);
this.notice("Could not get bookmarks.json: unknown HTTP status code " + data.target.status);
break;
}
this._generatorDone(onComplete, ret);
@ -896,7 +988,7 @@ BookmarksSyncService.prototype = {
_handlersForGenerator: function BSS__handlersForGenerator(generator) {
var h = {load: bind2(this, function(data) { continueGenerator(generator, data); }),
error: bind2(this, function(data) { LOG("Request failed: " + uneval(data)); })};
error: bind2(this, function(data) { this.notice("Request failed: " + uneval(data)); })};
h['complete'] = h['load'];
return h;
},
@ -922,7 +1014,7 @@ BookmarksSyncService.prototype = {
},
_onLogin: function BSS__onLogin(event) {
LOG("Bookmarks sync server: " + this._dav.baseURL);
this.notice("Bookmarks sync server: " + this._dav.baseURL);
this._os.notifyObservers(null, "bookmarks-sync:login", "");
},
@ -957,6 +1049,20 @@ BookmarksSyncService.prototype = {
logout: function BSS_logout() {
this._dav.logout();
this._os.notifyObservers(null, "bookmarks-sync:logout", "");
},
log: function BSS_log(line) {
},
notice: function BSS_notice(line) {
let fullLine = line + "\n";
dump(fullLine);
this._console.logStringMessage(line);
this._log.write(fullLine, fullLine.length);
this._log.flush();
},
error: function BSS_error(line) {
}
};
@ -972,23 +1078,14 @@ function makeURI(uriString) {
return ioservice.newURI(uriString, null, null);
}
function LOG(aText) {
dump(aText + "\n");
var consoleService = Cc["@mozilla.org/consoleservice;1"].
getService(Ci.nsIConsoleService);
consoleService.logStringMessage(aText);
}
function bind2(object, method) {
return function innerBind() { return method.apply(object, arguments); }
}
function continueGenerator(generator, data) {
try { generator.send(data); }
catch (e) {
LOG("continueGenerator exception! - " + e);
//notice("continueGenerator exception! - " + e);
if (e instanceof StopIteration)
generator = null;
else
@ -1118,7 +1215,7 @@ DAVCollection.prototype = {
let lm = Cc["@mozilla.org/login-manager;1"].getService(Ci.nsILoginManager);
let logins = lm.findLogins({}, uri.hostPort, null,
'Use your ldap username/password - dotmoz');
LOG("Found " + logins.length + " logins");
//notice("Found " + logins.length + " logins");
for (let i = 0; i < logins.length; i++) {
if (logins[i].username == username) {
@ -1145,7 +1242,7 @@ DAVCollection.prototype = {
},
_onLogin: function DC__onLogin(event) {
//LOG("logged in (" + event.target.status + "):\n" +
//notice("logged in (" + event.target.status + "):\n" +
// event.target.responseText + "\n");
if (this._authProvider._authFailed || event.target.status >= 400) {
@ -1168,8 +1265,8 @@ DAVCollection.prototype = {
this._loginHandlers.load(event);
},
_onLoginError: function DC__onLoginError(event) {
LOG("login failed (" + event.target.status + "):\n" +
event.target.responseText + "\n");
//notice("login failed (" + event.target.status + "):\n" +
// event.target.responseText + "\n");
this._loggedIn = false;
@ -1204,25 +1301,25 @@ DAVCollection.prototype = {
},
_onLock: function DC__onLock(event) {
LOG("acquired lock (" + event.target.status + "):\n" + event.target.responseText + "\n");
//notice("acquired lock (" + event.target.status + "):\n" + event.target.responseText + "\n");
this._token = "woo";
if (this._lockHandlers && this._lockHandlers.load)
this._lockHandlers.load(event);
},
_onLockError: function DC__onLockError(event) {
LOG("lock failed (" + event.target.status + "):\n" + event.target.responseText + "\n");
//notice("lock failed (" + event.target.status + "):\n" + event.target.responseText + "\n");
if (this._lockHandlers && this._lockHandlers.error)
this._lockHandlers.error(event);
},
_onUnlock: function DC__onUnlock(event) {
LOG("removed lock (" + event.target.status + "):\n" + event.target.responseText + "\n");
//notice("removed lock (" + event.target.status + "):\n" + event.target.responseText + "\n");
this._token = null;
if (this._lockHandlers && this._lockHandlers.load)
this._lockHandlers.load(event);
},
_onUnlockError: function DC__onUnlockError(event) {
LOG("unlock failed (" + event.target.status + "):\n" + event.target.responseText + "\n");
//notice("unlock failed (" + event.target.status + "):\n" + event.target.responseText + "\n");
if (this._lockHandlers && this._lockHandlers.error)
this._lockHandlers.error(event);
}

View File

@ -38,7 +38,7 @@
#include "nsISupports.idl"
[scriptable, uuid(b3e52c09-5c33-4d07-a3e6-7c453d0c4be8)]
[scriptable, uuid(0a1eed46-f832-495c-bce7-cb308ccfd599)]
interface nsIBookmarksSyncService : nsISupports
{
/**
@ -60,4 +60,12 @@ interface nsIBookmarksSyncService : nsISupports
* Initiate a sync operation.
*/
void sync();
/**
* Write a notice to the logfile
*
* @param line
* The line of text to print to the logfile
*/
void notice(in AString line);
};