Closed
Bug 619162
Opened 14 years ago
Closed 14 years ago
meta.payload is undefined in WeaveSvc__remoteSetup
Categories
(Firefox :: Sync, defect)
Firefox
Sync
Tracking
()
RESOLVED
FIXED
People
(Reporter: tchung, Assigned: rnewman)
References
Details
Attachments
(9 files)
88.12 KB,
text/rtf
|
Details | |
30.58 KB,
application/octet-stream
|
Details | |
45.27 KB,
text/plain
|
Details | |
64.06 KB,
text/plain
|
Details | |
21.88 KB,
text/plain
|
Details | |
13.79 KB,
application/octet-stream
|
Details | |
5.92 KB,
patch
|
philikon
:
review+
|
Details | Diff | Splinter Review |
226.76 KB,
text/plain
|
Details | |
28.60 KB,
text/plain
|
Details |
This was triggered on matt evan's 12/14 mac nightly build today. He has a v3 sync account, and updated to this nightly build. As auto-syncing started, it threw a notification error and this exception:
2010-12-14 11:48:35 Service.Main INFO In sync().
2010-12-14 11:48:35 Net.Resource DEBUG GET success 200 https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/info/collections
2010-12-14 11:48:35 Service.Main DEBUG Fetching global metadata record
2010-12-14 11:48:35 Service.Main CONFIG Starting backoff, next sync at:Tue Dec 14 2010 13:00:58 GMT-0800 (PST)
2010-12-14 11:48:35 Service.Main DEBUG Exception: meta.payload is undefined JS Stack trace: WeaveSvc__remoteSetup([object String])@service.js:1229< ()@service.js:1579< WrappedNotify()@util.js:147< WrappedLock()@util.js:119< WrappedCatch()@util.js:97< sync()@service.js:1529< SUI_doSync()@browser.js:5122< ([object XULElement],[object Object])@browser.js:5238< callbackWrapper([object XULElement],[object Object])@notifications.js:146< _doButtonCommand([object XULCommandEvent])@notification.xml:409< oncommand([object XULCommandEvent])@browser.xul:1
2010-12-14 11:48:41 Service.Main INFO In sync().
2010-12-14 11:48:41 Net.Resource DEBUG GET success 200 https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/info/collections
2010-12-14 11:48:41 Service.Main DEBUG Fetching global metadata record
2010-12-14 11:48:41 Service.Main CONFIG Starting backoff, next sync at:Tue Dec 14 2010 14:06:02 GMT-0800 (PST)
2010-12-14 11:48:41 Service.Main DEBUG Exception: meta.payload is undefined JS Stack trace: WeaveSvc__remoteSetup([object String])@service.js:1229< ()@service.js:1579< WrappedNotify()@util.js:147< WrappedLock()@util.js:119< WrappedCatch()@util.js:97< sync()@service.js:1529< SUI_doSync()@browser.js:5122< ([object XULElement],[object Object])@browser.js:5238< callbackWrapper([object XULElement],[object Object])@notifications.js:146< _doButtonCommand([object XULCommandEvent])@notification.xml:409< oncommand([object XULCommandEvent])@browser.xul:1
** Full log attached. Comment if you want the account name.
Repro:
1) setup a v3 sync account
2) install minefield nightly 12/14 on mac
3) let it auto sync and connect
4) Verify notification error in the addon bar, and the exception thrown in the logs
Expected:
- sync successful
Actual:
- exception fired, sync unable to sync.
Assignee | ||
Comment 1•14 years ago
|
||
Going to attempt to repro this locally.
Assignee | ||
Comment 2•14 years ago
|
||
I removed the line that cleared logs in resetServer, so the attached is a single continuous log of:
* 3.6.13 + 1.5.1: create account, first sync
* M-C build, quickly remove 1.5.1 addon, restart
* Allow to login, upgrade, and sync.
As you can see, I don't get this error.
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
Assignee | ||
Comment 3•14 years ago
|
||
Marking as WORKSFORME. Please reopen if you can find a robust repro recipe.
Status: ASSIGNED → RESOLVED
Closed: 14 years ago
Resolution: --- → WORKSFORME
Reporter | ||
Comment 4•14 years ago
|
||
matt is continually hitting this problem. cc'ing him to the bug. I've asked him to add repro steps and perhaps leave his account name if that helps you diagnose.
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Assignee | ||
Comment 5•14 years ago
|
||
We need the full contents of about:sync-log (and about:sync-log.1 if it's rolled over).
Comment 6•14 years ago
|
||
The repro steps were taking an older sync account and upgrading it late November. After each minefield upgrade, I seem to get the "Sync encountered an error while connecting: Server incorrectly configured. Please try again." message. If I clicked the Preference button, it didn't show any error. Thereafter until the next update, Syncing would work without error.
After the minefield update if 12/13/2010 I am now getting this error message continually. Attached both sync logs.
Comment 7•14 years ago
|
||
Comment 8•14 years ago
|
||
Assignee | ||
Comment 9•14 years ago
|
||
(In reply to comment #6)
> After the minefield update if 12/13/2010 I am now getting this error message
> continually. Attached both sync logs.
This is an odd one. It looks like the server is rejecting the initial request in some of your syncs, which causes us to abort with an error.
Note that there are 6 successful syncs in just one of your logs, so not all of them are failing.
I'm asking ops to grab some server logs for me; might be able to see why.
Bug 600261 tracks making our error reporting less noisy.
Assignee | ||
Comment 10•14 years ago
|
||
Matt, if I send you a verbose-logging XPI, could you give it a try on top of your b0rked Minefield?
Assignee | ||
Comment 11•14 years ago
|
||
I sent Matt an XPI with additional logging.
It looks like Resource._onComplete is throwing, hence the
GET cached: 0
line in the logs. That isn't supposed to occur, and I've never seen it locally. That's resulting in a status of 0 being returned, which causes failure.
(We also see 401 Unauthorized in our server logs, but I don't know if that's related.)
Assignee | ||
Comment 12•14 years ago
|
||
Aha! I got this myself just now.
2010-12-15 11:48:38 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 12:48:38 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 13:48:38 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 14:48:39 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 15:48:39 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 16:48:39 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 17:48:39 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 22:20:26 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 22:41:35 Service.Main DEBUG Idle timer created for sync, will sync after 5 seconds of inactivity.
2010-12-15 22:41:37 Service.Main INFO In sync().
2010-12-15 22:41:49 Net.Resource DEBUG GET success 200 https://phx-sync223.services.mozilla.com/1.0/holygoat/info/collections
2010-12-15 22:42:17 Net.Resource DEBUG GET cached: 0
2010-12-15 22:42:17 Service.Main DEBUG Exception: info.obj is null JS Stack trace: ()@service.js:1577 < WrappedNotify()@util.js:147 < WrappedLock()@util.js:119 < WrappedCatch()@util.js:97 < sync(false)@service.js:1529 < ([object Object])@service.js:554 < notify([object XPCWrappedNative_NoHelper])@util.js:1126
Looks like something very odd is happening in recent Minefield builds. Tomorrow I guess I'll trawl through commit logs...
Status: REOPENED → ASSIGNED
Assignee | ||
Comment 13•14 years ago
|
||
I don't see too much in the past week or two that would cause this, and I'm unable to repro with heavy logging added.
(Maybe I should go back to my hotel, see if I can get it to happen again!)
There is some code in resource.js that makes me go "wha?", so I might try to walk through it with mconnor later, see if there's anything we ought to error on pre-emptively.
Assignee | ||
Comment 14•14 years ago
|
||
Walked through code with mardak and mconnor. They also went "wha?".
Looks like the Resource code is hitting a cached response, even though it shouldn't. (Possibly related to redirects and non-propagation of flags in network layer.)
It's then returning *true* for response.success, which doesn't make any sense.
Going to try further to repro, and likely file one or more followup bugs... and be more careful in our code.
Comment 15•14 years ago
|
||
the logging xpi file received isn't compatible with 4.0b9pre minefield. Please send an updated version.
Question: What is the predicted prevalence of this issue?
Assignee | ||
Comment 16•14 years ago
|
||
(In reply to comment #15)
> the logging xpi file received isn't compatible with 4.0b9pre minefield. Please
> send an updated version.
>
> Question: What is the predicted prevalence of this issue?
It sure seems to be very, very, very hard to reproduce. Seems to be related to network transitions and network auth redirect pages, but even that isn't giving any leads. You might be the only person who sees it.
Reporter | ||
Comment 17•14 years ago
|
||
(In reply to comment #15)
> the logging xpi file received isn't compatible with 4.0b9pre minefield. Please
> send an updated version.
>
> Question: What is the predicted prevalence of this issue?
Matt, you can try forcing compatibility with that addon. To do this,
1) goto about:config
2) right click -> create new bool
3) type in extensions.checkCompatibility.4.0b = false
4) restart, and launch addons manager to see if it worked.
Comment 18•14 years ago
|
||
Assignee | ||
Comment 19•14 years ago
|
||
(In reply to comment #18)
> Created attachment 498244 [details]
> sync with extra debugging, issue still happening
Thanks Matt. If you could catch the problem with the extra logging I just sent you, that would help still further.
One hypothesis confirmed: the channel is throwing an exception when we try to read headers, because it doesn't have an HTTP response. This simply should not occur.
Are you on a hotel or guest network, or a regular "just works" net?
Comment 20•14 years ago
|
||
Mozilla wifi.
Comment 21•14 years ago
|
||
2010-12-16 15:57:22 Collection DEBUG POST success 200 https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/storage/tabs
2010-12-16 15:57:22 Engine.Tabs DEBUG Total (ms): sync 432, processIncoming 287, uploadOutgoing 144, syncStartup 1, syncFinish 0, createRecord 17, findDupe 0, isEqual 8, reconcile 8, syncCleanup 0
2010-12-16 15:57:22 Service.Main INFO Sync completed successfully in 2.37 secs.
2010-12-16 15:57:29 Service.Main INFO In sync().
2010-12-16 15:57:29 Net.Resource DEBUG In _doRequest.
2010-12-16 15:57:29 Net.Resource DEBUG Channel is [xpconnect wrapped (nsISupports, nsIChannel, nsIRequest, nsIHttpChannel)]
2010-12-16 15:57:29 Net.Resource DEBUG onStartRequest.
2010-12-16 15:57:29 Net.Resource DEBUG GET https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/info/collections
2010-12-16 15:57:29 Net.Resource DEBUG In _onComplete. Error is null, data is "Authentication failed"
2010-12-16 15:57:29 Net.Resource DEBUG Data: "\"Authentication failed\""
2010-12-16 15:57:29 Net.Resource DEBUG Channel: [xpconnect wrapped (nsISupports, nsIChannel, nsIRequest, nsIHttpChannel)]
2010-12-16 15:57:29 Net.Resource DEBUG Action: GET
2010-12-16 15:57:29 Net.Resource DEBUG Inside try block.
2010-12-16 15:57:29 Net.Resource DEBUG GET cached: 0
2010-12-16 15:57:29 Net.Resource DEBUG Caught exception Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIHttpChannel.visitResponseHeaders] Stack trace: _onComplete()@resource://services-sync/resource.js:248 < innerBind()@resource://services-sync/util.js:1369 < Channel_onStopRequest()@resource://services-sync/resource.js:463 in _onComplete.
2010-12-16 15:57:29 Service.Main DEBUG Fetching global metadata record
2010-12-16 15:57:29 Service.Main DEBUG Clearing cached meta record. metaModified is 1292282027.38, setting to undefined
2010-12-16 15:57:29 Net.Resource DEBUG In _doRequest.
2010-12-16 15:57:29 Net.Resource DEBUG Channel is [xpconnect wrapped (nsISupports, nsIChannel, nsIRequest, nsIHttpChannel)]
2010-12-16 15:57:29 Net.Resource DEBUG onStartRequest.
2010-12-16 15:57:29 Net.Resource DEBUG GET https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/storage/meta/global
2010-12-16 15:57:29 Net.Resource DEBUG In _onComplete. Error is null, data is {"id":"global","payload":"{\"syncID\":\"jaUDJCl2BTI_\",\"storageVersion\":5,\"engines\":{\"clients\":{\"version\":1,\"syncID\":\"kbDmq7hVnDgz\"},\"bookmarks\":{\"version\":2,\"syncID\":\"qiT2GqfqTeNn\"},\"forms\":{\"version\":1,\"syncID\":\"V1ezb08F3rnA\"},\"history\":{\"version\":1,\"syncID\":\"JUdn8TN_VEXS\"},\"passwords\":{\"version\":1,\"syncID\":\"WmNxwmB0uMwf\"},\"prefs\":{\"version\":2,\"syncID\":\"HBVACJSmWLxl\"},\"tabs\":{\"version\":1,\"syncID\":\"1nbby5ddrZ_z\"}}}","modified":1292282027.38}
2010-12-16 15:57:29 Net.Resource DEBUG Data: "{\"id\":\"global\",\"payload\":\"{\\\"syncID\\\":\\\"jaUDJCl2BTI_\\\",\\\"storageVersion\\\":5,\\\"engines\\\":{\\\"clients\\\":{\\\"version\\\":1,\\\"syncID\\\":\\\"kbDmq7hVnDgz\\\"},\\\"bookmarks\\\":{\\\"version\\\":2,\\\"syncID\\\":\\\"qiT2GqfqTeNn\\\"},\\\"forms\\\":{\\\"version\\\":1,\\\"syncID\\\":\\\"V1ezb08F3rnA\\\"},\\\"history\\\":{\\\"version\\\":1,\\\"syncID\\\":\\\"JUdn8TN_VEXS\\\"},\\\"passwords\\\":{\\\"version\\\":1,\\\"syncID\\\":\\\"WmNxwmB0uMwf\\\"},\\\"prefs\\\":{\\\"version\\\":2,\\\"syncID\\\":\\\"HBVACJSmWLxl\\\"},\\\"tabs\\\":{\\\"version\\\":1,\\\"syncID\\\":\\\"1nbby5ddrZ_z\\\"}}}\",\"modified\":1292282027.38}"
2010-12-16 15:57:29 Net.Resource DEBUG Channel: [xpconnect wrapped (nsISupports, nsIChannel, nsIRequest, nsIHttpChannel)]
2010-12-16 15:57:29 Net.Resource DEBUG Action: GET
2010-12-16 15:57:29 Net.Resource DEBUG Inside try block.
2010-12-16 15:57:29 Net.Resource DEBUG New headers: {"date":"Thu, 16 Dec 2010 23:57:29 GMT","server":"Apache/2.2.3 (CentOS)","x-powered-by":"PHP/5.2.9","x-weave-timestamp":"1292543849.24","content-length":"506","keep-alive":"timeout=10, max=2047","connection":"Keep-Alive","content-type":"application/json"}
2010-12-16 15:57:29 Net.Resource DEBUG Status: 200
2010-12-16 15:57:29 Net.Resource DEBUG Success: true
2010-12-16 15:57:29 Net.Resource DEBUG mesg: GET success 200 https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/storage/meta/global
2010-12-16 15:57:29 Net.Resource DEBUG GET success 200 https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/storage/meta/global
2010-12-16 15:57:29 Service.Main DEBUG Weave Version: 1.7b1pre Local Storage: 5 Remote Storage: 5
2010-12-16 15:57:29 Service.Main INFO Sync key is up-to-date: no need to upgrade.
2010-12-16 15:57:29 Service.Main DEBUG Fetching and verifying -- or generating -- symmetric keys.
2010-12-16 15:57:29 Service.Main WARN info/collections returned non-200 response. Failing key fetch.
2010-12-16 15:57:29 Service.Main WARN Failed to fetch symmetric keys. Failing remote setup.
2010-12-16 15:57:29 Service.Main DEBUG Exception: aborting sync, remote setup failed No traceback available
Reporter | ||
Comment 22•14 years ago
|
||
mozilla wifi should throw http responses right? perhaps hopping on a guest network and seeing if this reproduces with the logging?
Assignee | ||
Comment 23•14 years ago
|
||
Already tried guest wifi -- no dice.
I see an auth error in the log first. WTF.
Assignee | ||
Comment 24•14 years ago
|
||
I've sent inquiry to some networking developers, see if any of this rings any bells for them.
Comment 25•14 years ago
|
||
This problem was just reported on the Google Group as well:
https://groups.google.com/group/mozilla-labs-weave/browse_thread/thread/417a990f08b3ea4b
Assignee | ||
Comment 26•14 years ago
|
||
(In reply to comment #25)
> This problem was just reported on the Google Group as well:
>
> https://groups.google.com/group/mozilla-labs-weave/browse_thread/thread/417a990f08b3ea4b
And these lines:
Net.Resource DEBUG GET success 200 https://phx-sync095.services.mozilla.com/1.0/wkrakowski/info/collections
Service.Main DEBUG Fetching global metadata record
Service.Main DEBUG verifyLogin failed: meta.payload is undefined JS Stack trace:
indicate that it's exactly the same problem: meta/global is never fetched by Resource, with Resource.get returning some useless object.
mardak, mconnor, and myself did some code reading on Thursday. It looks like we can detect this case in Resource.get, and return a failure... but the underlying problem still needs to be identified and resolved.
With any luck I'll get a reply on Monday.
Comment 27•14 years ago
|
||
Oddly, I am not seeing this error on my home wifi. In fact the only place I see it is on the the Mozilla wifi ssid in Mt. View. It was not happening on the guest ssid.
Need any logs from the successful access cases?
Assignee | ||
Comment 28•14 years ago
|
||
(In reply to comment #27)
> Oddly, I am not seeing this error on my home wifi. In fact the only place I see
> it is on the the Mozilla wifi ssid in Mt. View. It was not happening on the
> guest ssid.
Yeah, I discovered the latter myself.
I only saw this once, and that was on the hotel wifi.
Given the reported troubles with MoCo wifi, it would seem that some networking edge case prompts weird responses in Resource.get...
> Need any logs from the successful access cases?
No, but thanks.
Comment 29•14 years ago
|
||
I take it back, it now fails pretty regularly on my home wifi network. Even after minefield update today.
Assignee | ||
Comment 30•14 years ago
|
||
(In reply to comment #29)
> I take it back, it now fails pretty regularly on my home wifi network. Even
> after minefield update today.
Could you please post updated logs? I'd like to see if there's a pattern in which requests fail and which succeed.
Is there some noticeable correlation with other activity -- e.g., first sync after waking the machine, or lots of tabs loading, etc.?
Comment 31•14 years ago
|
||
Assignee | ||
Comment 32•14 years ago
|
||
Here's one possible Band-Aid.
This patch does two things:
* The default 'success' value for a fetch is *false*, not true.
* If we get a status == 0 on a GET fetch, we retry once. We never want to use cached responses.
Tests also, of course.
This doesn't fix any underlying networking bug, but it will at least stop error bars from popping up all the time.
Thoughts, mconnor and philiKON?
Attachment #498795 -
Flags: review?(philipp)
Comment 33•14 years ago
|
||
Comment on attachment 498795 [details] [diff] [review]
Retry GET if we get a status 0, v1
> // Got a response but no header; must be cached (use default values)
> catch(ex) {
>+ this._log.debug("Got exception \"" + ex + "\" in Resource._onComplete.");
> this._log.debug(action + " cached: " + status);
> }
Remove that extra debugging line please.
The existence of this catch clause got me thinking briefly that whoever wrote this must've run into some sort of caching issue, too. Either it was before they set the cache-bypass flags or they were seeing what we're seeing now, too.
>- return this._request("GET");
>+ let response = this._request("GET");
>+ if (response.status == 0) {
>+ // This must be an erroneously cached response. Try again.
>+ this._log.debug("Status 0 in Res_get: retrying once.");
s/Res_get/Resource.get/
I wonder if we want to add the same hack to AsyncResource.get too?
Attachment #498795 -
Flags: review?(philipp) → review+
Assignee | ||
Comment 34•14 years ago
|
||
(In reply to comment #33)
> The existence of this catch clause got me thinking briefly that whoever wrote
> this must've run into some sort of caching issue, too. Either it was before
> they set the cache-bypass flags or they were seeing what we're seeing now, too.
Indeed, and I also saw it during my crypto work -- that's where my overly thorough checks for info.obj/meta.obj came from. It's apparently becoming less intermittent over time, though...
> I wonder if we want to add the same hack to AsyncResource.get too?
It's slightly more involved -- would require intercepting the callback. Your call.
I believe J-PAKE is the only code that directly uses AsyncResource at this point.
Comment 35•14 years ago
|
||
(In reply to comment #34)
> > I wonder if we want to add the same hack to AsyncResource.get too?
>
> It's slightly more involved -- would require intercepting the callback. Your
> call.
Sure, if by intercepting the callback you mean
this._doRequest("GET", undefined, function() {
...
callback.apply(this, arguments);
});
> I believe J-PAKE is the only code that directly uses AsyncResource at this
> point.
Indeed, but if I get my way it won't stay that way for long and then we probably don't want to be chasing bugs we had already fixed elsewhere...
Assignee | ||
Comment 36•14 years ago
|
||
Reviewed + amended version pushed:
http://hg.mozilla.org/services/fx-sync/rev/75b60f47bb74
Not marking as resolved yet: there's more to this issue.
Assignee | ||
Comment 37•14 years ago
|
||
Matt, are you still seeing this issue?
If so, would you mind following the steps in
https://developer.mozilla.org/en/HTTP_Logging
to get a trace of the HTTP interaction?
Note that your password will be embedded in the auth headers, so feel free to sanitize it.
Comment 38•14 years ago
|
||
Still seeing the problem. I will collect the log.
Comment 39•14 years ago
|
||
Comment 40•14 years ago
|
||
FYI: It happened as soon as I started up minefield.
Assignee | ||
Comment 41•14 years ago
|
||
(In reply to comment #40)
> FYI: It happened as soon as I started up minefield.
Thanks Matt.
I see a real 401 in the log:
384610304[1033280b0]: http response [
384610304[1033280b0]: HTTP/1.1 401 Unauthorized
384610304[1033280b0]: Date: Tue, 28 Dec 2010 01:00:19 GMT
384610304[1033280b0]: Server: Apache/2.2.3 (CentOS)
384610304[1033280b0]: X-Powered-By: PHP/5.2.9
384610304[1033280b0]: X-Weave-Timestamp: 1293498019.08
384610304[1033280b0]: WWW-Authenticate: Basic realm="Weave"
384610304[1033280b0]: Content-Length: 23
384610304[1033280b0]: Keep-Alive: timeout=10, max=2042
384610304[1033280b0]: Connection: Keep-Alive
384610304[1033280b0]: Content-Type: application/json
384610304[1033280b0]: ]
which doesn't really make much sense, because your subsequent Sync requests work fine. Still, gives us something to go on...
Assignee | ||
Comment 42•14 years ago
|
||
Correction: 401 makes absolute sense. There's no authentication header in the request. Now looking to see why that is...
Assignee | ||
Comment 43•14 years ago
|
||
New XPI sent to Matt...
Comment 44•14 years ago
|
||
After installing the new xpi, I have not seen a failure at all. I will post a log as soon as I see a failure.
Assignee | ||
Comment 45•14 years ago
|
||
(In reply to comment #44)
> After installing the new xpi, I have not seen a failure at all. I will post a
> log as soon as I see a failure.
Thanks Matt! Ah, bugs :D
Comment 46•14 years ago
|
||
Still haven't seen this problem with the new xpi. Anything else?
Comment 47•14 years ago
|
||
Assignee | ||
Comment 48•14 years ago
|
||
(In reply to comment #47)
> Created attachment 501486 [details]
> finally a sync-log with an error captured
Perfect, thanks Matt.
This log tells the story:
In _doRequest.
Adding basic authentication for username shjqlmpsmh5iu77cvx3dp3rs6xgptaou
Headers: {}
Channel is [xpconnect wrapped (nsISupports, nsIChannel, nsIRequest, nsIHttpChannel)]
onStartRequest called for channel [xpconnect wrapped nsIRequest].
oStaR: GET https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/info/collections
onStopRequest called for channel [xpconnect wrapped (nsISupports, nsIRequest, nsIHttpChannel)].
oStoR: null, 0
isSuccessCode? true
channel: flags = 262784, status = 401, success = false, URI = https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/info/collections
Calling _onComplete.
In _onComplete. Error is null, data is "Authentication failed"
In summary:
* We make a request, which for some reason doesn't end up with the Auth header.
* Naturally, we get a 401 (Unauthorized) response.
* This apparently comes with no headers, so we throw an exception trying to visit them.
* An old coding error in Resource leads to this returning a 0 status code.
* A retry attempt that we added then causes us to retry; this time we get the right basic auth header, and info/collections proceeds.
The same thing then happens for history:
2011-01-05 15:15:44 Collection DEBUG channel: flags = 262784, status = 401, success = false, URI = https://phx-sync271.services.mozilla.com/1.0/shjqlmpsmh5iu77cvx3dp3rs6xgptaou/storage/history
but we don't retry status 0 for POSTs...
This is weird (that header should always be added!) but it does give us something to go on.
Assignee | ||
Comment 49•14 years ago
|
||
OK Matt, new XPI for you:
http://people.mozilla.com/~rnewman/matt.xpi
This will log headers at various steps of the process, so we can see what's different between a failing and successful request...
Thanks!
Updated•14 years ago
|
OS: Mac OS X → All
Hardware: x86 → All
Summary: Auto-syncing throws an exception in WeaveSvc__remoteSetup([object String])@service.js:1229 → meta.payload is undefined in WeaveSvc__remoteSetup
Updated•14 years ago
|
Attachment #501486 -
Attachment mime type: application/octet-stream → text/plain
Comment 50•14 years ago
|
||
The same error was just reported on the mailing list by a user running 3.6. I believe this is the first time we've gotten a report for 3.6. Stack trace:
2011-01-09 17:27:18 Service.Main DEBUG verifyLogin failed:
meta.payload is undefined JS Stack trace:
WeaveSvc__remoteSetup()@service.js:1229 < ()@service.js:841 <
WrappedNotify()@util.js:147 < verifyLogin()@service.js:807 <
()@service.js:1049 < WrappedNotify()@util.js:147 <
WrappedLock()@util.js:119 < WrappedCatch()@util.js:97 <
WeaveSvc_login()@service.js:1025 < Change_doChangePassphrase()@generic-
change.js:173 < anonymous([object Event])@dialog.xml:358 <
_fireButtonEvent("accept")@dialog.xml:359 <
_doButtonCommand("accept")@dialog.xml:333 <
_handleButtonCommand([object XULCommandEvent])@dialog.xml:322
See https://groups.google.com/group/mozilla-labs-weave/browse_thread/thread/60386e85bf916789/7d297305dbfdddc0#7d297305dbfdddc0
Comment 51•14 years ago
|
||
Landed the fix on the 1.6.x branch as well so that we pick it up in our next 1.6.x release: https://hg.mozilla.org/services/fx-sync/rev/7be62a437fd0
Resolving this bug as the symptom seems to be have been cured. (Bugs that have patches landed and are resolved are easier for QA to verify.) Filed bug 624264 to make sure we still investigate the root cause.
Status: ASSIGNED → RESOLVED
Closed: 14 years ago → 14 years ago
Resolution: --- → FIXED
Assignee | ||
Comment 53•14 years ago
|
||
(In reply to comment #51)
> Landed the fix on the 1.6.x branch as well so that we pick it up in our next
> 1.6.x release: https://hg.mozilla.org/services/fx-sync/rev/7be62a437fd0
Great.
Note that Bug 623080 layers on top of this.
> Resolving this bug as the symptom seems to be have been cured. (Bugs that have
> patches landed and are resolved are easier for QA to verify.) Filed bug 624264
> to make sure we still investigate the root cause.
There's another question hiding here: why some of Matt's requests are rejected with a 401, and others succeed.
Matt, if you continue to see this, let us know and I'll open a fresh bug to track.
Updated•6 years ago
|
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.
Description
•