Closed Bug 577565 Opened 10 years ago Closed 9 years ago

Downgrade log message to trace: "Store.Forms: WARN: Ignoring form record update request!"

Categories

(Firefox :: Sync, defect, P2, trivial)

defect

Tracking

()

RESOLVED FIXED
mozilla5

People

(Reporter: mozilla-bugs, Assigned: rnewman)

Details

(Whiteboard: [verified in services])

Attachments

(1 file)

User-Agent:       Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre
Build Identifier: Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre

Just did a fresh sync (overwriting any local changes) on a new Firefox profile and got a lot (>600) of these warnings:

Store.Forms: WARN: Ignoring form record update request!

Then:
2010-07-09 00:16:59     Engine.Forms         WARN       Sync failed
2010-07-09 00:16:59     Engine.Forms         DEBUG      Total (ms): sync 476884, processIncoming 476509, syncStartup 375, findDupe 2002, createRecord 20, isEqual 21, deleteId 67, handleDupe 464795, reconcile 469010

I'm not sure it actually failed: form data appears to have been synced.

Also, there shouldn't be so much warnings (polluting the log).

Using the current experimental build (1.4.1b2)

Reproducible: Didn't try

Steps to Reproduce:
1. Setup a new profile
2. Sync using the second option (overwriting any local changes)

Actual Results:  
Got a bunch of warnings.


I'm using the minimal server, self-hosted.

The relevant server access log:
1.2.3.4 - - [09/Jul/2010:00:08:41 +0200] "GET /1.0/user/info/collections HTTP/1.0" 200 230 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:08:41 +0200] "GET /1.0/user/storage/keys/pubkey HTTP/1.0" 200 573 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:08:41 +0200] "GET /1.0/user/storage/keys/privkey HTTP/1.0" 200 1914 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:00 +0200] "GET /1.0/user/info/collections HTTP/1.0" 200 230 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:01 +0200] "GET /1.0/user/storage/meta/global HTTP/1.0" 200 490 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:01 +0200] "GET /1.0/user/storage/keys/pubkey HTTP/1.0" 200 573 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:01 +0200] "GET /1.0/user/storage/keys/privkey HTTP/1.0" 200 1914 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:01 +0200] "GET /1.0/user/storage/crypto/clients HTTP/1.0" 200 578 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:01 +0200] "GET /1.0/user/storage/clients?full=1&sort=index HTTP/1.0" 200 1163 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:02 +0200] "POST /1.0/user/storage/clients HTTP/1.0" 200 38 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:02 +0200] "GET /1.0/user/storage/crypto/bookmarks HTTP/1.0" 200 584 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:02 +0200] "GET /1.0/user/storage/crypto/forms HTTP/1.0" 200 583 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:09:03 +0200] "GET /1.0/user/storage/forms?full=1&sort=index HTTP/1.0" 200 502322 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:12 +0200] "GET /1.0/user/storage/crypto/history HTTP/1.0" 200 581 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:14 +0200] "GET /1.0/user/storage/history?full=1&sort=index HTTP/1.0" 200 2007040 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:24 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1351 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:27 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1325 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:31 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1377 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:35 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1325 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:39 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1325 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:44 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1377 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:48 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1351 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:52 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1325 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:17:57 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1325 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:18:01 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1351 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:18:05 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1325 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:18:11 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1325 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:18:16 +0200] "POST /1.0/user/storage/history HTTP/1.0" 200 1065 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:18:18 +0200] "DELETE /1.0/user/storage/history?ids=e9176630-cfea-4e3a-8b6b-b1e39047fd08 HTTP/1.0" 200 13 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:18:19 +0200] "GET /1.0/user/storage/crypto/passwords HTTP/1.0" 200 581 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:18:20 +0200] "GET /1.0/user/storage/passwords?full=1&sort=index HTTP/1.0" 200 192572 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:20:07 +0200] "DELETE /1.0/user/storage/passwords?ids={27f2bde4-f4b9-4839-b072-ef16343b4101},{e3002a03-8609-46cd-b038-6c81d10c6cc9} HTTP/1.0" 200 13 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:20:09 +0200] "GET /1.0/user/storage/crypto/prefs HTTP/1.0" 200 582 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:20:09 +0200] "GET /1.0/user/storage/prefs?full=1&sort=index HTTP/1.0" 200 9125 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:20:11 +0200] "POST /1.0/user/storage/prefs HTTP/1.0" 200 39 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:20:13 +0200] "GET /1.0/user/storage/crypto/tabs HTTP/1.0" 200 578 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:20:14 +0200] "GET /1.0/user/storage/tabs?full=1&sort=index HTTP/1.0" 200 16594 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
1.2.3.4 - - [09/Jul/2010:00:20:14 +0200] "POST /1.0/user/storage/tabs HTTP/1.0" 200 38 "-" "Mozilla/5.0 (X11; Linux i686; en-US; rv:2.0b2pre) Gecko/20100708 Minefield/4.0b2pre"
Somehow the client is getting records for things it already knows about. The form engine doesn't do updates because the guid is a hash of the field name and value, so there isn't much to update right now. Yeah the warning could be removed -- especially if we track other properties of form data down the line.
Status: UNCONFIRMED → NEW
Ever confirmed: true
This is the initial sync, so there should be no form data present already (unless it's duplicated in the data being sent by the server).

Is this the case? The server misbehaving (somehow)?
Can you still reproduce this?  I've only seen it with local data still present.  Perhaps there was an issue with the wipe, but i can't reproduce.

Morphing this to kill the log message.
Component: General → Sync
OS: Linux → All
QA Contact: general → sync
Hardware: x86 → All
Summary: Store.Forms: WARN: Ignoring form record update request! → Downgrade log message to trace: "Store.Forms: WARN: Ignoring form record update request!"
Target Milestone: --- → 1.5
Probably can trigger it by doing a full resync. The log message should probably just be removed.
Target Milestone: 1.5 → 1.6
Priority: -- → P1
This was quicker to fix than to triage!
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
Attachment #521702 - Flags: review?(philipp)
Priority: P1 → P2
Target Milestone: 1.6 → ---
Comment on attachment 521702 [details] [diff] [review]
Proposed patch. v1

*rubberstamp*
Attachment #521702 - Flags: review?(philipp) → review+
Verified fix on S-C. Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:2.2a1pre) Gecko/20110407 Firefox/4.2a1pre
Whiteboard: [fixed in services] → [verified in services]
http://hg.mozilla.org/mozilla-central/rev/5fb27adf75a9
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla5
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.