756385 - Add-on sync claims "add-on not found in add-on repository"

Status: UNCONFIRMED

(Firefox :: Sync, defect)

Description

[Sebastian Schuberth]

Attachment: Success log with Sync.Store.Bookmarks lines stripped for simplicity

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:12.0) Gecko/20100101 Firefox/12.0
Build ID: 20120423122928

Steps to reproduce:

I'm running my own sync server. After some sync problems I've set up sync from scratch. I started by restoring my Firefox profile on machine A (running Win XP 32-bit and FF 12) using MozBackup. Then I've set up sync and synced add-ons, bookmarks and preferences to my server (without any errors). Then I've set up sync on machine B (running Win 7 64-bit and FF 11) and chose to overwrite any local sync data.


Actual results:

Syncing bookmarks (and prefs, for what I can tell) worked fine, but add-ons did not sync. There was no error-*.txt log, but a success-*.txt log with a lot of entries like

1337287234824	Sync.Store.Addons	DEBUG	showParentFolder@alice not syncable: add-on not found in add-on repository.

Obviously, the "Show Parent Folder" add-on *IS* in the public add-on repository, see:
https://addons.mozilla.org/en-US/firefox/addon/show-parent-folder/


Expected results:

I would have expected the add-ons to sync.

Comment 1

[Gregory Szorc [:gps]]

Relevant line from log:

1337287234824	Sync.Store.Addons	DEBUG	goParentFolder@alice not syncable: add-on not found in add-on repository.

Can you please set extensions.logging.enabled to true in about:config and paste the logs it generates to the Error Console/terminal? You may want to create a fresh profile (start firefox with -ProfileManager -no-remote) and use the "Reset Sync" feature to use remote data to force Sync to try to install the extensions again.

Comment 2

[Sebastian Schuberth]

Just out of curiosity, out of all the add-ons not syncing, why is goParentFolder@alice the relevant line?

I'm currently an another machine (machine C) where I cannot reproduce the "add-on not found in add-on repository" messages anymore. I guess I first have to force-upload the add-ons form machine A again before I see the messages again.

Comment 3

[Gregory Szorc [:gps]]

Well, I just called out [e-mail] because that is the one you mentioned in the initial comment. If you look at the log, there are many similar lines for "add-on not found in add-on repository."

If you can't reproduce on another machine, I wonder if your preferences have been changed on the machine that is failing.

What do extensions.getAddons.search.url and extensions.getAddons.get.url preferences point to? If it is something other than https://services.addons.mozilla.org/, we have probably identified the problem.

Comment 4

[Sebastian Schuberth]

I'm slightly confused, I've mentioned "showParentFolder@alice" (just as an example) in my initial comment, not "goParentFolder@alice".

I'll check extensions.getAddons.*.url on the failing machine (machine B) tonight.

Comment 5

[Sebastian Schuberth]

On the failing machine extensions.getAddons.search.url is:
https://services.addons.mozilla.org/%LOCALE%/firefox/api/%API_VERSION%/search/%TERMS%/all/%MAX_RESULTS%/%OS%/%VERSION%/%COMPATIBILITY_MODE%?src=firefox

And extensions.getAddons.get.url is:
https://services.addons.mozilla.org/%LOCALE%/firefox/api/%API_VERSION%/search/guid:%IDS%?src=firefox&appOS=%OS%&appVersion=%VERSION%

I've enabled extensions.logging.enabled, but the only two entries that show up in the error console after syncing are:

1337369009037	Sync.Engine.Bookmarks	WARN	DATA LOSS: Both local and remote changes to record: menu
1337369009039	Sync.Engine.Bookmarks	WARN	DATA LOSS: Both local and remote changes to record: toolbar

Comment 6

[Gregory Szorc [:gps]]

Those prefs values are OK.

When you enable extensions logging, you should see messages in the error console like:

LOG addons.repository: Requesting https://services.addons.mozilla.org/en-US/firefox/api/1.5/search/guid:%7BDDC359D1-844A-42a7-9AA1-88A850A938A8%7D?src=firefox&appOS=Darwin&appVersion=15.0a1

You don't need to do a restart or anything. If you aren't seeing these messages, then either:

1) You aren't performing any operations that speak to the add-on manager (try doing a sync from a fresh profile or resetting sync from remote data. If the later, watch out for bug 756366).
2) Something is seriously messed up.

Ideally I would see error console output with both the Sync and addons logs interleaved so I could get an idea what's going on (sadly, Firefox doesn't have a unified logging bus for all these different components, so the error console is the best we have).

Comment 7

[Sebastian Schuberth]

I've now managed to get this message in the error console on machine B:

1337458093554	Sync.Store.Addons	WARN	Requested to update record but add-on not found: historyblock@kain

What I did was: Install the HistoryBlock add-on for testing on machine A, overwrite sync data with data from machine A, then overwrite local data on machine B with sync data.

And here comes the funny part: I overwrote sync data with the data from machine A, which has the HistoryBlock extension installed. But if I choose to overwrite local data on machine A with sync data immediately afterwards, the HistoryBlock add-on gets removed!

On machine A, I now get the following messages in the error console:

1337458485823	Sync.Engine.Addons	WARN	DATA LOSS: Both local and remote changes to record: 1sx3SkkhTJX2

Timestamp: 2012.05.19 22:14:46
Error: uncaught exception: [Exception... "Could not convert Native argument arg 3 [nsIDOMJSWindow.openDialog]"  nsresult: "0x8057000a (NS_ERROR_XPC_BAD_CONVERT_NATIVE)"  location: "JS frame :: chrome://browser/content/utilityOverlay.js :: openPreferences :: line 450"  data: no]

Comment 8

[Sebastian Schuberth]

I now managed to see these messages in the error log, does that ring a bell?

versioncheck.addons.mozilla.org : server does not support RFC 5746, see CVE-2009-3555
1337814297756   Sync.Store.Addons       WARN    Requested to update record but add-on not found: [e-mail]
1337814297762   Sync.Store.Addons       WARN    Requested to update record but add-on not found: [e-mail]
1337814297788   Sync.Store.Addons       WARN    Requested to update record but add-on not found: [e-mail]

Comment 9

[Dave Townsend [:mossop]]

(In reply to Sebastian Schuberth from comment #5)
> I've enabled extensions.logging.enabled, but the only two entries that show
> up in the error console after syncing are:
> 
> 1337369009037	Sync.Engine.Bookmarks	WARN	DATA LOSS: Both local and remote
> changes to record: menu
> 1337369009039	Sync.Engine.Bookmarks	WARN	DATA LOSS: Both local and remote
> changes to record: toolbar

Are you sure you're looking in the right error console, these messages look like those found in the sync log. The add-ons manager logging appears in the error console found under Firefox -> web developer -> error console.

Comment 10

[Sebastian Schuberth]

Yes, I'm sure to look at the right place. The "data loss" messages actually appear in both the sync-log and error console.

Comment 11

[Gregory Szorc [:gps]]

(In reply to Dave Townsend (:Mossop) from comment #9)
> (In reply to Sebastian Schuberth from comment #5)
> > I've enabled extensions.logging.enabled, but the only two entries that show
> > up in the error console after syncing are:
> > 
> > 1337369009037	Sync.Engine.Bookmarks	WARN	DATA LOSS: Both local and remote
> > changes to record: menu
> > 1337369009039	Sync.Engine.Bookmarks	WARN	DATA LOSS: Both local and remote
> > changes to record: toolbar
> 
> Are you sure you're looking in the right error console, these messages look
> like those found in the sync log. The add-ons manager logging appears in the
> error console found under Firefox -> web developer -> error console.

Sync's log messages get distributed to Sync logs, stderr, and the Error Console. If services.sync.log.appender.console is cranked up, the Error Console will effectively be equivalent to the sync logs. The main difference is the Sync logs are buffered until the end of a sync and the error console logs are instantaneous.

Comment 12

[Sebastian Schuberth]

I'm adding some more info from the mailing list here:

From the source code I've learned that there is a
"addons.ignoreRepositoryChecking" setting, which I've set to "true"
for testing. With that, for an add-on that before triggered "add-on
not found in add-on repository", I now get:

1339053040575   Sync.Engine.Addons      WARN    DATA LOSS: Both local and remote
changes to record: Gk6e5dkffChG
1339053040576   Sync.Store.Addons       WARN    Requested to update record but
add-on not found: {D4DD63FA-01E4-46a7-B6B1-EDAB7D6AD389}

And add-ons are still not synchronized.

Comment 13

[Sebastian Schuberth]

I've set "services.sync.log.logger.engine.addons" to "Trace" now, which strangely made the line

    DATA LOSS: Both local and remote changes to record: Gk6e5dkffChG

disappear from the log. The only other line containing "Gk6e5dkffChG" is

    Ignoring add-on because it couldn't be obtained: Gk6e5dkffChG

But that line was already present with "Debug" instead of "Trace".

Comment 14

[Gregory Szorc [:gps]]

If you create a new profile and set up Sync to connect to your existing Sync account, you should see more information. Keep in mind you'll need to modify the preferences on the new profile *before* you set up Sync.

Alternatively, you can go to the Sync options and reset Sync to replace all local data with your remote Sync data. You *may* lose data if you do this, especially if you are having general Sync problems. So, you may want to back up your profile first.

Comment 15

[Tracy Walker [:tracy]]

based on comment 7 doing a double reset. I filed bug 792972

Comment 16

[Sebastian Schuberth]

FYI, I've now both switched PCs and from my own sync server (on Gentoo and Lighttpd) to the official Mozilla one, and I cannot reproduce this issue anymore myself. Fell free to close it.