Closed Bug 1368715 Opened 2 years ago Closed 2 years ago

Constant sync errors in bookmarks engine: "Error: Invalid value for property 'modified': -9223372036854.775"

Categories

(Firefox :: Sync, defect, P1)

35 Branch
defect

Tracking

()

RESOLVED FIXED
Firefox 55
Tracking Status
firefox55 --- fixed

People

(Reporter: whimboo, Assigned: lina)

References

Details

Attachments

(1 file)

The sync process is failing a lot on my machine. From the log it looks like that this is related to the bookmarks engine:

1496156201058	Sync.Telemetry	TRACE	observed weave:engine:sync:uploaded bookmarks
1496156201090	Sync.Status	DEBUG	Status for engine bookmarks: error.engine.reason.unknown_fail
1496156201090	Sync.Status	DEBUG	Status.service: success.status_ok => error.sync.failed_partial
1496156201090	Sync.ErrorHandler	DEBUG	bookmarks failed: Error: Invalid value for property 'modified': -9223372036854.775 (resource://gre/modules/PlacesUtils.jsm:573:17) JS Stack trace: validateItemProperties@PlacesUtils.jsm:573:17 < validateChangeRecord@PlacesSyncUtils.jsm:847:10 < pushChanges/<@PlacesSyncUtils.jsm:359:30 < executeBeforeShutdown@Sqlite.jsm:373:25 < executeBeforeShutdown@Sqlite.jsm:1251:12 < withConnectionWrapper/<@PlacesUtils.jsm:1546:14 < waitForSyncCallback@async.js:98:7 < makeSpinningCallback/callback.wait@async.js:168:27 < promiseSpinningly@async.js:234:12 < trackRemainingChanges@bookmarks.js:610:5 < _syncCleanup@engines.js:1788:7 < _syncCleanup@bookmarks.js:532:5 < _sync@engines.js:1803:7 < WrappedNotify@util.js:161:21 < sync@engines.js:723:5 < _syncEngine@enginesync.js:219:7 < sync@enginesync.js:166:15 < onNotify@service.js:1080:7 < WrappedNotify@util.js:161:21 < WrappedLock@util.js:117:16 < _lockedSync@service.js:1070:12 < sync/<@service.js:1062:7 < WrappedCatch@util.js:92:16 < sync@service.js:1051:5
:markh, can you tell from the above if this timestamp is being returned from the server or originating in the client?  Also, what's the procedure for finding out what storage node Henrik is assigned to, I used to know how to look this up in about:config but last time I tried to do so I couldn't find it.

(Specifically, we need to know whether he's on the python server or the go server...)
Flags: needinfo?(markh)
(In reply to Ryan Kelly [:rfkelly] from comment #1)
> :markh, can you tell from the above if this timestamp is being returned from
> the server or originating in the client?

It is originating in the client. I can reproduce this by manually adjusting the lsatModified time of a bookmark to a negative value.

>  Also, what's the procedure for
> finding out what storage node Henrik is assigned to, I used to know how to
> look this up in about:config but last time I tried to do so I couldn't find
> it.
> 
> (Specifically, we need to know whether he's on the python server or the go
> server...)

Unfortunately it involves looking in the logs - none of this stuff is stored in preferences (but I expect that's moot given the above)

Kit, what should we do here?
Flags: needinfo?(markh) → needinfo?(kit)
FWIW:

+++ b/toolkit/components/places/PlacesSyncUtils.jsm
@@ -1694,6 +1694,12 @@ var fetchQueryItem = async function(bookmarkItem) {
 function addRowToChangeRecords(row, changeRecords) {
   let syncId = BookmarkSyncUtils.guidToSyncId(row.getResultByName("guid"));
   let modified = row.getResultByName("modified") / MICROSECONDS_PER_SECOND;
+  if (modified <= 0) {
+    // convert invalid modified values to 0, so they are less likely to win
+    // any reconcilliation logic.
+    BookmarkSyncLog.warn(`record ${syncId} has invalid modified of ${modified} - resetting`);
+    modified = 0;
+  }


gets us past this error. I'm not sure it is the best approach though - it could be argued that the validation check for |modified| is misguided, seeing the values we are using came directly from places in the first place.
In case it helps here the storage info I can find in the log:

1496300017462	Sync.Collection	DEBUG	mesg: GET success 200 https://sync-432-us-west-2.sync.services.mozilla.com/1.5/63182180/storage/clients?full=1&limit=1000

Not sure if we clean-up local log files after some days, but the first occurrence of this failure I got on May 22nd at 08:56:25 GMT+2.

Since then I had only one single successful sync which was on May 30th because it didn't include the bookmarks.
That timestamp looks suspiciously close to -2^63 (-9223372036854775808, except JS can't represent numbers below -2^53 + 1). I wonder if it's possible the modified date wrapped around somehow, maybe when the bookmark was inserted or updated via a C++ method? This might be something we can detect and fix in the Places Maintenance add-on, too.

Henrik, if you have the About Sync add-on (or SQLite Manager) installed, you could run this SQL query against Places to see which bookmarks are causing the problem. Do you remember anything unusual about them? I'd also be curious to know what the "syncStatus" (0 = unknown, 1 = new, 2 = normal) and "syncChangeCounter" values are.

select b.guid, b.title, h.url, b.syncStatus, b.syncChangeCounter, b.lastModified / 1000 as lms, b.dateAdded / 1000 as dms
from moz_bookmarks b
join moz_places h on h.id = b.fk
where lms <= -(1 << 53) or lms >= (1 << 53) or dms <= -(1 << 53) or dms >= (1 << 53)

Mark, I think you're right; validating our own records seems misguided. Defaulting to 0 (or maybe trying `dateAdded` as a fallback, assuming it also isn't borked) seems like a good approach, too, since we didn't record the correct timestamp.
Flags: needinfo?(kit) → needinfo?(hskupin)
The SQLite Manager extension is no langer usable with Nightly because it doesn't support multi-process. So lets see how about sync works...

When I execute the above SQL statement in the bookmarks section I don't get any results returned. But under client records I have found two entries with such a timestamp. Both are actually of type separator, so no real bookmarks. This might explain, why the SQL query didn't find a result. The sync status is 2 and the counter 1 for both.

The separators are in bookmark folders which I haven't touched for a very long time:

{guid: "mXAp4a3rBIYT", title: "%TITLE%", index: 24, dateAdded: 1217730249878000, lastModified: 1488835314347000…}
{guid: "fRYiHUnbnors", title: "%TITLE%", index: 1, dateAdded: 1065271629000000, lastModified: 1488835313824000…}

(Note that I put placeholders for the real title)

Here the separator data:

{guid: "6anzvfR_DAvm", index: 0, dateAdded: 1207864568527000, lastModified: -9223372036854775000, id: "6anzvfR_DAvm"…}
{guid: "JIHsSFwEwtTz", index: 1, dateAdded: 1204672646284000, lastModified: -9223372036854775000, id: "JIHsSFwEwtTz"…}
Flags: needinfo?(hskupin)
Priority: -- → P1
Assignee: nobody → kit
Comment on attachment 8875392 [details]
Bug 1368715 - Ignore and report invalid modified dates in synced bookmark changesets.

https://reviewboard.mozilla.org/r/146832/#review151010

::: toolkit/components/places/PlacesSyncUtils.jsm:1699
(Diff revision 1)
>  function addRowToChangeRecords(row, changeRecords) {
>    let syncId = BookmarkSyncUtils.guidToSyncId(row.getResultByName("guid"));
> -  let modified = row.getResultByName("modified") / MICROSECONDS_PER_SECOND;
> +  let modifiedAsPRTime = row.getResultByName("modified");
> +  let modified = modifiedAsPRTime / MICROSECONDS_PER_SECOND;
> +  if (Number.isNaN(modified) || modified <= 0) {
> +    BookmarkSyncLog.error("addRowToChangeRecords: Invalid modified date for " +

TBH I'm not sure an error log makes sense here - it seems a user in this state is likely to see sync error logs forever. IMO it would make sense if we actually *changed* the bookmark so the error appeared once. How about a .warn?
Attachment #8875392 - Flags: review?(markh) → review+
Comment on attachment 8875392 [details]
Bug 1368715 - Ignore and report invalid modified dates in synced bookmark changesets.

https://reviewboard.mozilla.org/r/146832/#review151010

> TBH I'm not sure an error log makes sense here - it seems a user in this state is likely to see sync error logs forever. IMO it would make sense if we actually *changed* the bookmark so the error appeared once. How about a .warn?

I'm not sure it will. Once the bookmark is uploaded, its change counter will reset to 0, so we won't sync it until it's changed again, (hopefully) with the correct modified date. If it's updated on the server, `PlacesSyncUtils.bookmarks.update` will also change the modified date. Does that sound right? If not, and there's a risk of us writing error logs forever, I'll use warn instead.
Yeah, I think you are correct. I'm still not sure it's worth an error log given there's nothing we can do about it, but I'm happy to defer to your judgement.
(In reply to Mark Hammond [:markh] from comment #10)
> Yeah, I think you are correct. I'm still not sure it's worth an error log
> given there's nothing we can do about it, but I'm happy to defer to your
> judgement.

Cool. I think it could be useful for cases where this manifests as Sync throwing away local changes, so I'd prefer to leave the error log. Thanks!
Pushed by kcambridge@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1961976dc596
Ignore and report invalid modified dates in synced bookmark changesets. r=markh
https://hg.mozilla.org/mozilla-central/rev/1961976dc596
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
See Also: → 1407922
You need to log in before you can comment on or make changes to this bug.