958405 - Sync broken on my Nightly Windows builds

Status: RESOLVED INVALID

(Firefox :: Sync, defect)

Description

[Judah Richardson]

Attachment: error-1389304864016.txt

User Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64; rv:29.0) Gecko/20100101 Firefox/29.0 (Beta/Release)
Build ID: 20140109030203

Steps to reproduce:

Got notification that Sync had failed. Forced a sync via Tools -> Sync Now. Nothing happened. Went to Sync tab in Options and unpaired all device. Trying to re-pair it failed.* Removing the other device and trying to start Sync afresh failed also.

*quiet fail with no error message. Simply put: nothing happened.


Actual results:

Sync failed silently.


Expected results:

Sync should have successfully completed.

Comment 1

[Gregory Szorc [:gps]]

The log show Sync is hanging then aborting at application termination. Hang appears to be in history sync.

My first guess is a corrupted history database. Try repairing the database with https://addons.mozilla.org/en-US/firefox/addon/places-maintenance/ and report back.

Comment 2

[Judah Richardson]

Attachment: error-1389376123429.txt

Sync Log #2

Comment 3

[Judah Richardson]

Attachment: PlacesMaintenance.txt

Places Maintenance log

Comment 4

[Judah Richardson]

Running Places Maintenance on both devices allowed me to set Sync up again on both of them, but nothing seems to be syncing at all. I've attached the latest Sync error log as well as the log of messages from Places Maintenance.

Comment 5

[Gregory Szorc [:gps]]

OK, maybe it wasn't a corrupted database.

There is still an issue with a hang:

1389376103199	Sync.Tracker.Bookmarks	DEBUG	Saving changed IDs to bookmarks
1389376123401	Sync.Status	DEBUG	Status for engine bookmarks: error.engine.reason.unknown_fail
1389376123401	Sync.Status	DEBUG	Status.service: success.status_ok => error.sync.failed_partial
1389376123402	Sync.ErrorHandler	DEBUG	bookmarks failed: App. Quitting Stack trace: checkAppReady/onQuitApplication/Async.checkAppReady()@resource://services-common/async.js:123 < waitForSyncCallback()@resource://services-common/async.js:98 < makeSpinningCallback/callback.wait()@resource://services-common/async.js:141 < _syncStart()@resource://gre/modules/services-sync/engines/bookmarks.js:376 < SyncEngine.prototype._sync()@resource://services-sync/engines.js:1417 < wrappedSync()@resource://gre/modules/services-sync/engines/bookmarks.js:214 < _sync()@resource://gre/modules/services-sync/engines/bookmarks.js:220 < WrappedNotify()@resource://services-sync/util.js:143 < Engine.prototype.sync()@resource://services-sync/engines.js:594 < _syncEngine()@resource://services-sync/stages/enginesync.js:192 < sync()@resource://services-sync/stages/enginesync.js:147 < onNotify()@resource://gre/modules/services-sync/service.js:1197 < WrappedNotify()@resource://services-sync/util.js:143 < WrappedLock()@resource://services-sync/util.js:98 < _lockedSync()@resource://gre/modules/services-sync/service.js:1191 < sync/<()@resource://gre/modules/services-sync/service.js:1182 < WrappedCatch()@resource://services-sync/util.js:72 < sync()@resource://gre/modules/services-sync/service.js:1170 < <file:unknown>

(Notice the 20s between the first 2 entries.)

There are a bunch of services.sync.log.logger.* prefs that are likely set to Debug. Crank them up to "Trace" then restart and submit a new log. Hopefully that will shed some light.

Watch out for personal data leaking into the logs when things are logged with Trace!

Comment 6

[Judah Richardson]

Attachment: error-1389460194719.txt

Sync Log 3

Comment 7

[Judah Richardson]

(In reply to Gregory Szorc [:gps] from comment #5)
> There are a bunch of services.sync.log.logger.* prefs that are likely set to
> Debug. Crank them up to "Trace" then restart and submit a new log. Hopefully
> that will shed some light.
> 
> Watch out for personal data leaking into the logs when things are logged
> with Trace!

Done, new Sync log uploaded. Any clearer now?

Comment 8

[Gregory Szorc [:gps]]

There is no new data in the log to help track this down :(

rnewman: you have any ideas?

Comment 9

[Richard Newman [:rnewman]]

Hypotheses:

1. It's hanging while making a Places backup at the start of a first sync. Try setting `services.sync.bookmarks.lastSync` to `1`, see if this gets you any further.
2. Somebody just changed the internal promises implementation, and it's causing a hang/throw somewhere. Check the Error Console, see if an uncaught exception is being recorded.
3. There's an error in the constructor for BookmarksStore. This is unlikely.

We can also directly test my first hypothesis.

1. Open a Browser Console. <https://developer.mozilla.org/en-US/docs/Tools/Browser_Console>
2. Run this:

Cu.import("resource://gre/modules/PlacesBackups.jsm");
Cu.import("resource://services-common/async.js");
Cu.import("resource://gre/modules/Task.jsm");

let cb = Async.makeSpinningCallback();
Task.spawn(function() {
  yield PlacesBackups.create(null, true);
  cb("foo");
});
console.log(cb.wait());


3. You should see "foo" printed. If you see anything other than two deprecation warnings (filed Bug 959030), or don't see "foo", then that's the culprit.

I get a warning:

_appendConvertedComplexNode error: Unable to find node

but things seem to proceed fine.

Comment 10

[Judah Richardson]

(In reply to Richard Newman [:rnewman] from comment #9)
> Hypotheses:
> 
> 1. It's hanging while making a Places backup at the start of a first sync.
> Try setting `services.sync.bookmarks.lastSync` to `1`, see if this gets you
> any further.
That doesn't produce any new error logs, even when I force a Sync.

> 2. Somebody just changed the internal promises implementation, and it's
> causing a hang/throw somewhere. Check the Error Console, see if an uncaught
> exception is being recorded.
Per https://developer.mozilla.org/en-US/docs/Error_Console, the Error Console is deprecated. See WebConsole1.txt for what I get in the Web Console upon startup.

> 3. There's an error in the constructor for BookmarksStore. This is unlikely.
> 
> We can also directly test my first hypothesis.
> 
> 1. Open a Browser Console.
> <https://developer.mozilla.org/en-US/docs/Tools/Browser_Console>
> 2. Run this:
> 
> Cu.import("resource://gre/modules/PlacesBackups.jsm");
> Cu.import("resource://services-common/async.js");
> Cu.import("resource://gre/modules/Task.jsm");
> 
> let cb = Async.makeSpinningCallback();
> Task.spawn(function() {
>   yield PlacesBackups.create(null, true);
>   cb("foo");
> });
> console.log(cb.wait());
> 
> 
> 3. You should see "foo" printed. If you see anything other than two
> deprecation warnings (filed Bug 959030), or don't see "foo", then that's the
> culprit.
> 
> I get a warning:
> 
> _appendConvertedComplexNode error: Unable to find node
> 
> but things seem to proceed fine.

Here's what I get:

Cu.import("resource://gre/modules/PlacesBackups.jsm"); Cu.import("resource://services-common/async.js"); Cu.import("resource://gre/modules/Task.jsm"); let cb = Async.makeSpinningCallback(); Task.spawn(function() { yield PlacesBackups.create(null, true); cb("foo"); }); console.log(cb.wait());

_appendConvertedComplexNode error: Unable to find node BookmarkJSONUtils.jsm:796
DEPRECATION WARNING: PlacesBackups.entries is deprecated and will be removed in a future version
You may find more details about this deprecation at: https://bugzilla.mozilla.org/show_bug.cgi?id=859695
resource://gre/modules/PlacesBackups.jsm 86 this.PlacesBackups.entries
resource://gre/modules/PlacesBackups.jsm 245 PB_saveBookmarksToJSONFile/<
resource://gre/modules/Task.jsm 233 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 153 then
resource://gre/modules/Task.jsm 269 TaskImpl_handleResultValue
resource://gre/modules/Task.jsm 235 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 185 resolve
resource://gre/modules/Task.jsm 239 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 185 resolve
resource://gre/modules/Task.jsm 239 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 185 resolve
resource://gre/modules/Task.jsm 239 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 185 resolve
resource://gre/modules/Sqlite.jsm 347 OpenedConnection.prototype<._finalize/<.complete<
null 0 null
 Deprecated.jsm:79
DEPRECATION WARNING: PlacesBackups.folder is deprecated and will be removed in a future version
You may find more details about this deprecation at: https://bugzilla.mozilla.org/show_bug.cgi?id=859695
resource://gre/modules/PlacesBackups.jsm 42 this.PlacesBackups.folder
resource://gre/modules/PlacesBackups.jsm 90 this.PlacesBackups.entries
resource://gre/modules/PlacesBackups.jsm 245 PB_saveBookmarksToJSONFile/<
resource://gre/modules/Task.jsm 233 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 153 then
resource://gre/modules/Task.jsm 269 TaskImpl_handleResultValue
resource://gre/modules/Task.jsm 235 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 185 resolve
resource://gre/modules/Task.jsm 239 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 185 resolve
resource://gre/modules/Task.jsm 239 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 185 resolve
resource://gre/modules/Task.jsm 239 TaskImpl_run
resource://gre/modules/commonjs/sdk/core/promise.js 118 resolve
resource://gre/modules/commonjs/sdk/core/promise.js 43 then
resource://gre/modules/commonjs/sdk/core/promise.js 185 resolve
resource://gre/modules/Sqlite.jsm 347 OpenedConnection.prototype<._finalize/<.complete<
null 0 null
 Deprecated.jsm:79
GET https://talkgadget.google.com/u/0/talkgadget/_/channel/bind [HTTP/1.1 200 OK]
POST https://mail.google.com/mail/u/0/

Does that help any?

Comment 11

[Judah Richardson]

Attachment: WebConsole1.txt

Comment 12

[Richard Newman [:rnewman]]

Comment on attachment 8359306 [details]
WebConsole1.txt

Do you have an add-on installed to mess with bookmark favicons?

chrome://bookmarkfaviconchanger/content/module.jsm 139 bookmarkfaviconchangerModule.init
chrome://bookmarkfaviconchanger/content/placesContext.js 659 bookmarkfaviconchangerPlacesContext.onload
chrome://bookmarkfaviconchanger/content/placesContext.js 680 null

Comment 13

[Judah Richardson]

(In reply to Richard Newman [:rnewman] from comment #12)
> Comment on attachment 8359306 [details]
> WebConsole1.txt
> 
> Do you have an add-on installed to mess with bookmark favicons?
> 
> chrome://bookmarkfaviconchanger/content/module.jsm 139
> bookmarkfaviconchangerModule.init
> chrome://bookmarkfaviconchanger/content/placesContext.js 659
> bookmarkfaviconchangerPlacesContext.onload
> chrome://bookmarkfaviconchanger/content/placesContext.js 680 null

I use Bookmark Favicon Changer to add favicons to bookmarklets that have none.

Comment 14

[Richard Newman [:rnewman]]

(In reply to Judah Richardson from comment #13)

> I use Bookmark Favicon Changer to add favicons to bookmarklets that have
> none.

Try turning that off, see if it makes a difference.

Comment 15

[Judah Richardson]

(In reply to Richard Newman [:rnewman] from comment #14)
> (In reply to Judah Richardson from comment #13)
> 
> > I use Bookmark Favicon Changer to add favicons to bookmarklets that have
> > none.
> 
> Try turning that off, see if it makes a difference.

Actually, updating to the latest version of Bookmark Favicon Changer here https://sites.google.com/site/sonthakit/bookmarkfaviconchanger/version210 seems to have fixed the problem.

Should I switch all the about:config flags back to their previous states, or leave them as is?

Comment 16

[Richard Newman [:rnewman]]

(In reply to Judah Richardson from comment #15)

> Actually, updating to the latest version of Bookmark Favicon Changer here
> https://sites.google.com/site/sonthakit/bookmarkfaviconchanger/version210
> seems to have fixed the problem.

Good to know! Resolving this bug.

> Should I switch all the about:config flags back to their previous states, or
> leave them as is?

Switching them back will save some space and CPU time.

Comment 17

[Judah Richardson]

OK, thanks for your help :)