Closed Bug 619162 Opened 14 years ago Closed 14 years ago

meta.payload is undefined in WeaveSvc__remoteSetup

Categories

(Firefox :: Sync, defect)

Product:
Firefox
Component:
Sync
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED

People

(Reporter: tchung, Assigned: rnewman)

References

Details

Attachments

(9 files)

WeaveSvc__remoteSetup error screenshot
88.12 KB, text/rtf
Details
Log of failed attempt to repro.
30.58 KB, application/octet-stream
Details
current sync.log from minefield
45.27 KB, text/plain
Details
current sync.log.1 from minefield
64.06 KB, text/plain
Details
sync with extra debugging, issue still happening
21.88 KB, text/plain
Details
sync log as of 12-20-10
13.79 KB, application/octet-stream
Details
Retry GET if we get a status 0, v1
5.92 KB, patch
philikon
: review+
Details | Diff | Splinter Review
HTTP log file
226.76 KB, text/plain
Details
finally a sync-log with an error captured
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.
Going to attempt to repro this locally.
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
Marking as WORKSFORME. Please reopen if you can find a robust repro recipe.
Status: ASSIGNED → RESOLVED
Closed: 14 years ago
Resolution: --- → WORKSFORME
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 → ---
We need the full contents of about:sync-log (and about:sync-log.1 if it's rolled over).
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.
(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.
Matt, if I send you a verbose-logging XPI, could you give it a try on top of your b0rked Minefield?
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.)
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
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.
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.
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?
(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.
(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.
(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?
Mozilla wifi.
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
mozilla wifi should throw http responses right?   perhaps hopping on a guest network and seeing if this reproduces with the logging?
Already tried guest wifi -- no dice.

I see an auth error in the log first. WTF.
I've sent inquiry to some networking developers, see if any of this rings any bells for them.
(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.
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?
(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.
I take it back, it now fails pretty regularly on my home wifi network. Even after minefield update today.
(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.?
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 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+
(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.
(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...
Reviewed + amended version pushed:

http://hg.mozilla.org/services/fx-sync/rev/75b60f47bb74

Not marking as resolved yet: there's more to this issue.
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.
Still seeing the problem. I will collect the log.
Attached file HTTP log file — 

    
    

    
  
FYI: It happened as soon as I started up minefield.

    
    

    
  
(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...

    
    

    
  
Correction: 401 makes absolute sense. There's no authentication header in the request. Now looking to see why that is...

    
    

    
  
New XPI sent to Matt...

    
    

    
  
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.

    
    

    
  
(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

    
    

    
  
Still haven't seen this problem with the new xpi. Anything else?

    
    

    
  
(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.

    
    

    
  
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!
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

        Attachment #501486 -
        Attachment mime type: application/octet-stream → text/plain

    
    

    
  
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

    
    

    
  
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

    
    

    
  
(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.
No longer blocks: 623788
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.
        






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: