Bugzilla

Updated

•

12 years ago

blocking-fennec1.0: --- → ?

Assignee

Comment 1

•

12 years ago

The issue here is that the Sync 1.1 spec checks X-I-U-S against the collection timestamp, not the resource timestamp. Sync 2.0 is sane in this regard (Bug 735458).

The fix will be to track and use the modified time of the collection, not the individual record. On the plus side, this means we can just use POST for everything.

Massive TODO for the 2.0 transition, please!

James Bonacci [:jbonacci]

Assignee

Comment 2

•

12 years ago

This will affect all clients with more than one device... which is to say, all of them.

It'll appear as soon as some other device uploads a client record after the Android device does, which will be about a week after you set up Sync on your phone.

It'll go away for a week if you send a command to the phone, such as Reset Sync or Send Tab To Device.

If the upload fails, the sync will abort. I call that a beta blocker :D

Easy fix.

Status: NEW → ASSIGNED

Updated

•

12 years ago

Whiteboard: [qa+]

Brad Lassey [:blassey] (use needinfo?)

Comment 3

•

12 years ago

investigation to determine if this is a server issue froma  recent deploy is ongoing

Updated

•

12 years ago

blocking-fennec1.0: ? → beta+

Nick Alexander :nalexander [he/him]

Updated

•

12 years ago

Assignee: nalexander → ally

Assignee

Comment 4

•

12 years ago

Taking this, because I have Marina's pull req in my review queue.

Assignee: ally → rnewman

Updated

•

12 years ago

Whiteboard: [qa+] → [qa+][work started]

Assignee

Comment 5

•

12 years ago

https://github.com/mozilla-services/android-sync/pull/173

This is done and passes tests. Has had first review; will land after QA.

Whiteboard: [qa+][work started] → [qa+][needs review]

Assignee

Comment 6

•

12 years ago

QA:

This bug arises when Android Sync decides that it should upload its record, but uses the timestamp from its last upload, not the collection timestamp, as the value for X-If-Unmodified-Since.

If no other client has uploaded a record in the mean time, this will work fine.

Sync 1.1 uses the collection timestamp for validation even on PUTs, not the object being replaced. (2.0 does not.)

As a result, the same error arises as would appear if two clients were racing to update a record.


This patch changes the client logic here, using the last retrieved timestamp for X-I-U-S, and using POST besides (to avoid Bug 740170).


In order to test this, it's necessary to provoke three conditions:

* Android Sync needs to upload its record
* The timestamp it is tracking is non-zero (so we can't just delete the record from the server)
* Another record in the collection is newer.

Some steps that *should* provoke this situation:

* Send a command to the Android device.
* Upload another device's record (thus making that record newer).
* Sync the Android device.


Concrete STR (not tested myself):

* Set up Sync on a desktop with a brand new account. (This is to ensure only two client records exist.)
* Pair an Android device.
* Sync both devices.
* On desktop, open a privileged error console.
* Evaluate the following:

  /********************/
  Components.utils.import("resource://services-sync/resource.js");
  Components.utils.import("resource://services-sync/service.js");
  Components.utils.import("resource://services-sync/engines/clients.js");

  // Send a command to other clients.
  for (let id in Clients._store._remoteClients) {
    Clients._sendCommandToClient("nothing", [], id);
  }

  // Force a sync to upload it.
  Service.sync();

  // Our client ID.
  let us = Clients.localID;

  // Now bump our client record after a brief time.
  function bump() {
    let r = new Resource(Service.storageURL + "clients/" + us);
    let g = r.get();
    r.put(g);
  }

  setTimeout(bump, 300);
  /********************/

* Now sync on the Android device. You should see messages about 'Command "nothing" not registered and will not be processed.', followed by an attempt to upload the device's client record.
* Without this change, you should see a 412 Precondition Failed. With this change, the upload should succeed.

If you do *not* see a 412 when trying these steps with, say, a current Nightly, then I'll need to come up with STR that provoke the problem.

If you *do*, and you still see a 412 with http://people.mozilla.com/~rnewman/fennec.apk, then something else needs to happen :D

Thanks!

Whiteboard: [qa+][needs review] → [qa+][needs review][STR in Comment 6]

Comment 7

•

12 years ago

Attached file my sync log — Details

i followed the concrete STRs as best as i could in comment 6, but did not see anything in my logs mentioning "'Command "nothing" not registered and will not be processed."  Neither did i see any 412's. 

privileged console evaluation showed the set of bookmark numbers i was incrementing and decrementing correctly.  

Anyone else get the output that rnewman was asking for?

Naoki Hirata :nhirata (please use needinfo instead of cc)

Comment 8

•

12 years ago

(In reply to Tony Chung [:tchung] from comment #7)
> Anyone else get the output that rnewman was asking for?

Oh, tested on rnewman's build, HTC Incredible S, Android 2.3.4

Comment 9

•

12 years ago

Received several errors:

Mozilla Pastebin - collaborative debugging tool View Help
Posted by Anonymous on Tue 24th Apr 08:45 (modification of post by view diff)
download | new post

    04-24 08:53:56.056: E/ProfileMigrator(4135): [ProfileMigrator.java:485:run()] Profile has incomplete Sync config. Not migrating.
    04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.account]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768"  data: no]
    04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.client.name]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768"  data: no]
    04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.client.GUID]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768"  data: no]
    04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.serverURL]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768"  data: no]
    04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.clusterURL]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768"  data: no] 

as well as :

Submit a correction or amendment below (click here to make a fresh posting)
After submitting an amendment, you'll be able to view the differences between the old and new posts easily.

Syntax highlighting:

To highlight particular lines, prefix each line with ~~
04-24 08:53:56.056: E/ProfileMigrator(4135): [ProfileMigrator.java:485:run()] Profile has incomplete Sync config. Not migrating. 04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.account]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]" nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)" location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768" data: no] 04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.client.name]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]" nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)" location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768" data: no] 04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.client.GUID]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]" nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)" location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768" data: no] 04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.serverURL]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]" nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)" location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768" data: no] 04-24 08:53:56.306: E/GeckoConsole(4135): Error reading pref [services.sync.clusterURL]: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getCharPref]" nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)" location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 768" data: no]
Your Name

Remember me
How long should your post be retained?
a day a month forever
Good for IRC or IM conversations
Mozilla systems and collaborative tools are intended for use by the Mozilla community for Mozilla related work and subject to web site terms and conditions at Legal Notices.



04-24 09:05:33.006: V/PowerManagerService(208): [PowerManagerService.java:1598:AdjustPowerStateForHdmi()] AdjustPowerStateForHdmi in=3 out=3
04-24 09:05:33.036: W/ResourceType(330): No known package when getting value for resource number 0xffffffff
04-24 09:05:33.036: W/ResourceType(330): No known package when getting value for resource number 0xffffffff
04-24 09:05:33.076: I/#LGIME(313): [Glog.java:35:i()] ### onFinishInput
04-24 09:05:33.076: I/#LGIME(313): [Glog.java:35:i()] #### onStartInput restarting : false / inputType : 0
04-24 09:05:33.126: I/dun_service(133): process rmnet event
04-24 09:05:33.126: I/dun_service(133):  rstate == DUN_RMNETSTATE_ERROR in dun_monitor_kevents
04-24 09:05:33.599: I/dun_service(133): process rmnet event
04-24 09:05:33.599: I/dun_service(133):  rstate == DUN_RMNETSTATE_ERROR in dun_monitor_kevents
04-24 09:05:34.096: D/PowerManagerService(208): [PowerManagerService.java:715:acquireWakeLock()] acquireWakelock KeyInputQueuefrom uid=1000 pid=208
04-24 09:05:34.096: V/PowerManagerService(208): [PowerManagerService.java:1598:AdjustPowerStateForHdmi()] AdjustPowerStateForHdmi in=3 out=3
04-24 09:05:34.106: D/PowerManagerService(208): [PowerManagerService.java:715:acquireWakeLock()] acquireWakelock KeyInputQueuefrom uid=1000 pid=208
04-24 09:05:34.116: D/PowerManagerService(208): [PowerManagerService.java:715:acquireWakeLock()] acquireWakelock KeyInputQueuefrom uid=1000 pid=208
04-24 09:05:34.146: D/PowerManagerService(208): [PowerManagerService.java:715:acquireWakeLock()] acquireWakelock KeyInputQueuefrom uid=1000 pid=208
04-24 09:05:34.196: D/PowerManagerService(208): [PowerManagerService.java:715:acquireWakeLock()] acquireWakelock KeyInputQueuefrom uid=1000 pid=208
04-24 09:05:34.206: D/PowerManagerService(208): [PowerManagerService.java:715:acquireWakeLock()] acquireWakelock KeyInputQueuefrom uid=1000 pid=208
04-24 09:05:34.206: V/PowerManagerService(208): [PowerManagerService.java:1598:AdjustPowerStateForHdmi()] AdjustPowerStateForHdmi in=3 out=3

Assignee

Comment 10

•

12 years ago

(In reply to Tony Chung [:tchung] from comment #7)
> Created attachment 617865 [details]
> my sync log
> 
> i followed the concrete STRs as best as i could in comment 6, but did not
> see anything in my logs mentioning "'Command "nothing" not registered and
> will not be processed."  Neither did i see any 412's. 

You might need to bump log levels:

  adb shell
  setprop log.tag.Command VERBOSE
  setprop log.tag.SyncClientsEngineStage VERBOSE

quit Fennec, repeat steps starting from the Web Console.


> privileged console evaluation showed the set of bookmark numbers i was
> incrementing and decrementing correctly.  

Can you clarify this? We're not doing anything with bookmarks here.

Updated

•

12 years ago

Whiteboard: [qa+][needs review][STR in Comment 6] → [qa+][in testing][STR in Comment 6]

Comment 11

•

12 years ago

Attached file 2nd attempt logcat — Details

here's a logcat running the same steps from before, with verbose added (i think)

I still yet to see the command: nothing strings.

what concerns me most is the initial sync errors, going from desktop->fennec.  Anything corrupted here?

04-24 14:09:40.680: VERBOSE/SyncManager(1491): runstateidle: nonHTCActiveCount++ :1
04-24 14:09:40.690: DEBUG/SyncAdapter(12655): AccountManager.get(org.mozilla.gecko.GeckoApplication@4053b688)
04-24 14:09:40.700: WARN/SyncManager(1491): setActiveSync called with existing active sync!
04-24 14:09:40.730: INFO/SyncAdapter(12655): Got onPerformSync. Extras bundle is Bundle[{}]
04-24 14:09:40.740: INFO/SyncAdapter(12655): Account name: meme@me.com
04-24 14:09:40.740: DEBUG/SyncAdapter(12655): Invalidating auth token.
04-24 14:09:40.740: WARN/AccountSettings(10732): No label for account type , type org.mozilla.firefox_sync
04-24 14:09:40.740: WARN/AccountSettings(10732): android.content.pm.PackageManager$NameNotFoundException: Application package org.mozilla.fennec not found
04-24 14:09:40.740: WARN/AccountSettings(10732):     at android.app.ContextImpl.createPackageContext(ContextImpl.java:1607)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at android.content.ContextWrapper.createPackageContext(ContextWrapper.java:460)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at com.htc.settings.accountsync.AccountPreferenceBase.getLabelForType(AccountPreferenceBase.java:166)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at com.htc.settings.accountsync.ManageAccountsSettings.onAccountsUpdated(ManageAccountsSettings.java:453)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at android.accounts.AccountManager$11.run(AccountManager.java:1171)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at android.os.Handler.handleCallback(Handler.java:587)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at android.os.Handler.dispatchMessage(Handler.java:92)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at android.os.Looper.loop(Looper.java:150)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at android.app.ActivityThread.main(ActivityThread.java:4293)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at java.lang.reflect.Method.invokeNative(Native Method)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at java.lang.reflect.Method.invoke(Method.java:507)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:839)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:597)
04-24 14:09:40.740: WARN/AccountSettings(10732):     at dalvik.system.NativeStart.main(Native Method)
04-24 14:09:40.760: INFO/SyncAuthService(12655): AccountManager.get(org.mozilla.gecko.sync.setup.SyncAuthenticatorService@405936a0)
04-24 14:09:40.760: INFO/SyncAuthService(12655): Setting username. Null? false
04-24 14:09:40.760: INFO/SyncAuthService(12655): Setting Sync Key. Null? false

Assignee

Comment 12

•

12 years ago

Just verified this myself:

04-24 11:30:08.130 I/SyncClientsEngineStage( 8484): Local client GUID exists on server and was downloaded
04-24 11:30:08.150 D/Command ( 8484): Command "nothing" not registered and will not be processed.
04-24 11:30:08.260 D/SyncClientsEngineStage( 8484): Database contains 3 clients.
04-24 11:30:08.260 D/SyncClientsEngineStage( 8484): Server response asserts 3 records.
04-24 11:30:08.330 D/SyncClientsEngineStage( 8484): Uploading client record iy-PEV9q_-WL
04-24 11:30:08.570 I/SyncAdapter( 8484): Stage completed: syncClientsEngine

Assignee

Comment 13

•

12 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/1142c9551333

(Sorry, inbound sheriff. We've been asked to be more verbose in whiteboard comments.)

Whiteboard: [qa+][in testing][STR in Comment 6] → [qa+][inbound]

Target Milestone: --- → mozilla15

Assignee

Comment 14

•

12 years ago

Attached patch Patch. v1 — Details — Splinter Review

Beta blocker. Landed on m-i, covered by unit tests and manual QA.

Attachment #617976 - Flags: review+

Attachment #617976 - Flags: approval-mozilla-aurora?

Comment 15

•

12 years ago

Attached file logcat 3 — Details

I've confirmed the record.

04-24 15:01:04.629: INFO/SyncClientsEngineStage(13294): Local client GUID exists on server and was downloaded
04-24 15:01:04.699: DEBUG/Database(13294): dbclose(): path = /data/data/org.mozilla.fennec_rnewman/databases/clients_database, handle = 0x65fc98
04-24 15:01:04.699: DEBUG/SyncClientsEngineStage(13294): Database contains 2 clients.
04-24 15:01:04.699: DEBUG/SyncClientsEngineStage(13294): Server response asserts 2 records.
04-24 15:01:04.749: DEBUG/dalvikvm(13294): GC_FOR_MALLOC freed 343K, 41% free 4203K/7111K, external 206K/521K, paused 29ms
04-24 15:01:04.749: DEBUG/SyncClientsEngineStage(13294): Not uploading client record.
04-24 15:01:04.749: INFO/SyncAdapter(13294): Stage completed: syncClientsEngine
---------------------------
And on desktop console:

[14:59:06.011] 
  /********************/
  Components.utils.import("resource://services-sync/resource.js");
  Components.utils.import("resource://services-sync/service.js");
  Components.utils.import("resource://services-sync/engines/clients.js");

  // Send a command to other clients.
  for (let id in Clients._store._remoteClients) {
    Clients._sendCommandToClient("nothing", [], id);
  }

  // Force a sync to upload it.
  Service.sync();

  // Our client ID.
  let us = Clients.localID;

  // Now bump our client record after a brief time.
  function bump() {
    let r = new Resource(Service.storageURL + "clients/" + us);
    let g = r.get();
    r.put(g);
  }

  setTimeout(bump, 300);
  /********************/
[14:59:07.215] 2

Naoki Hirata :nhirata (please use needinfo instead of cc)

Comment 16

•

12 years ago

missing the command line, so i reran the test.   looks good, will recheck on m-c landing.


04-24 15:11:47.896 I/SyncAdapter(13294): Stage completed: ensureKeysStage
04-24 15:11:47.896 I/GlobalSession(13294): Running next stage syncClientsEngine (org.mozilla.gecko.sync.stage.SyncClientsEngineStage@405c48a8)...
04-24 15:11:47.896 V/SyncClientsEngineStage(13294): Downloading client records.
04-24 15:11:50.399 D/Database(13294): dbopen(): path = /data/data/org.mozilla.fennec_rnewman/databases/clients_database, flag = 6, file size = 5120
04-24 15:11:50.409 D/Database(13294): dbopen(): path = /data/data/org.mozilla.fennec_rnewman/databases/clients_database, mode: wal, disk free size: 1030 M, handle: 0x4d43e0
04-24 15:11:50.549 D/dalvikvm(13294): GC_CONCURRENT freed 340K, 43% free 4190K/7239K, external 174K/521K, paused 3ms+3ms
04-24 15:11:50.559 I/SyncClientsEngineStage(13294): Local client GUID exists on server and was downloaded
04-24 15:11:50.589 D/Command (13294): Command "nothing" not registered and will not be processed.
04-24 15:11:50.639 D/Database(13294): dbclose(): path = /data/data/org.mozilla.fennec_rnewman/databases/clients_database, handle = 0x4d43e0
04-24 15:11:50.649 D/SyncClientsEngineStage(13294): Database contains 2 clients.
04-24 15:11:50.649 D/SyncClientsEngineStage(13294): Server response asserts 2 records.
04-24 15:11:50.669 D/SyncClientsEngineStage(13294): Uploading client record DvO-OzEc4WMR
04-24 15:11:50.879 I/SyncAdapter(13294): Stage completed: syncClientsEngine

(no longer active)

Comment 17

•

12 years ago

https://hg.mozilla.org/mozilla-central/rev/1142c9551333

Status: ASSIGNED → RESOLVED

Closed: 12 years ago

Resolution: --- → FIXED

Whiteboard: [qa+][inbound] → [qa+]

Comment 18

•

12 years ago

Having a hard time trying to even get the correct STRs.  Not sure how to verify without getting the case within a prior build first.

Tracy Walker [:tracy]

Comment 19

•

12 years ago

Naoki,  Tony told me yesterday that he would verify this one, as it is somewhat tricky to setup.

Alex Keybl [:akeybl]

Comment 20

•

12 years ago

Comment on attachment 617976 [details] [diff] [review]
Patch. v1

[Triage Comment]
Fennec blocker - approved for Aurora 14.

Attachment #617976 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+

Assignee

Comment 21

•

12 years ago

https://hg.mozilla.org/releases/mozilla-aurora/rev/f532880d43c5

status-firefox14: --- → fixed

Whiteboard: [qa+] → [qa+][landed in aurora]

Comment 22

•

12 years ago

(In reply to Tracy Walker [:tracy] from comment #19)
> Naoki,  Tony told me yesterday that he would verify this one, as it is
> somewhat tricky to setup.

yep, i'll verify this on tomorrow's nightly.