Closed Bug 560184 Opened 12 years ago Closed 12 years ago

Proxy authentication: Initial Weave connection attempt doesn't time out

Categories

(Firefox :: Sync, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED

People

(Reporter: ab+mozbug, Assigned: Mardak)

Details

Attachments

(1 file, 1 obsolete file)

User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.2.3) Gecko/20100415 Ubuntu/10.04 (lucid) Firefox/3.6.3
Build Identifier: Weave 1.2.1

Three seconds after starting Firefox, Weave tries to connect to it's server. When no other proxy connection has been authenticated before the first connection attempt, Weave will hang in the "Logging in" state. The connection  doesn't time out and is not retried (in contrast to when, for example, the proxy is not reachable).

Log info:

2010-04-19 11:47:39	Engine.Prefs         DEBUG	Engine initialized
2010-04-19 11:47:39	Engine.Tabs          DEBUG	Engine initialized
2010-04-19 11:47:39	Engine.Tabs          DEBUG	Resetting tabs last sync time
2010-04-19 11:47:39	Service.Main         INFO	Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.2.3) Gecko/20100415 Ubuntu/10.04 (lucid) Firefox/3.6.3
2010-04-19 11:47:39	Service.Main         DEBUG	Caching URLs under storage user base: https://my.weave.minmal.server/weave/1.0/username/
2010-04-19 11:47:41	Service.Main         DEBUG	Autoconnecting in 3 seconds
2010-04-19 11:47:44	Service.Main         INFO	Logging in user username


When I access a web site through the proxy before Weave starts it's first connection, everything works as expected.

Reproducible: Always

Steps to Reproduce:
1. configure a proxy server that requires authentication (in my case: Squid with NTLM authentication)
2. start Firefox
3. do not access the proxy until Weave has tried to connect to it's server
4. wait indefinitely

Actual Results:  
Weave sync is stuck in "Logging in user" state.

Expected Results:  
Connection attempt times out and is retried.

I'm using FoxyProxy 2.19.1 (authenticating proxy is the default proxy)
Ed, can you do the same stuff with a timeout as you did with sync?
Assignee: nobody → edilee
Status: UNCONFIRMED → NEW
Ever confirmed: true
Flags: blocking-weave1.3+
OS: Linux → All
Hardware: x86 → All
Alexander, can you turn on Trace logging for resources:

about:config -> extensions.weave.log.logger.network.resources -> Trace (from Debug)

Then try autoconnecting again before accessing the proxy.
Target Milestone: --- → 1.3
Hi,

Trace log is not much more informative, see below. I have tried disabling FoxyProxy and using our normal proxy configuration: No difference.

(Login user and Weave server URL have been replaced in the log.)

---cut---
2010-04-21 11:03:47	Service.Main         INFO	Loading Weave 1.2.1
2010-04-21 11:03:47	Engine.Bookmarks     DEBUG	Engine initialized
2010-04-21 11:03:47	Engine.Forms         DEBUG	Engine initialized
2010-04-21 11:03:47	Engine.History       DEBUG	Engine initialized
2010-04-21 11:03:47	Engine.Passwords     DEBUG	Engine initialized
2010-04-21 11:03:47	Engine.Prefs         DEBUG	Engine initialized
2010-04-21 11:03:47	Engine.Tabs          DEBUG	Engine initialized
2010-04-21 11:03:47	Engine.Tabs          DEBUG	Resetting tabs last sync time
2010-04-21 11:03:47	Service.Main         INFO	Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.2.3) Gecko/20100415 Ubuntu/10.04 (lucid) Firefox/3.6.3
2010-04-21 11:03:47	Service.Main         DEBUG	Caching URLs under storage user base: https://my.weave.minimal.server/weave/1.0/username/
2010-04-21 11:03:49	Service.Main         DEBUG	Autoconnecting in 3 seconds
2010-04-21 11:03:52	Service.Main         INFO	Logging in user username
2010-04-21 11:03:52	Net.Resource         TRACE	HTTP Header Content-type: text/plain
2010-04-21 11:03:52	Net.Resource         TRACE	HTTP Header Authorization: ***** (suppressed)
That helps. Seems like the onStartRequest never triggers so the timer never triggers. I guess the next best thing is to start the timer when the constructor is called or maybe just before chanOpen...
I can confirm this behavior (using FoxyProxy, too). Further more, when Weave tries to connect (after ~3 seconds) without being authed to proxy before, I cannot browse any websites till I restart the browser. Where "cannot browse" means that Firefox tries to endlessly connect to the site via proxy even though the proxy auth has been successful.
Attached patch v1 (obsolete) — Splinter Review
Attachment #440545 - Flags: review?(mconnor)
Attachment #440545 - Attachment is obsolete: true
Attachment #440545 - Flags: review?(mconnor)
Attached patch v1Splinter Review
Attachment #440546 - Flags: review?(mconnor)
Attachment #440546 - Flags: review?(mconnor) → review+
http://hg.mozilla.org/labs/weave/rev/199fc2df2d4d
Delay the abort timer from the constructor in addition to onStartRequest and onDataAvailable in-case the callbacks never get called.
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
Edward, you may want to take a look at bug 559084 discussion too.
Reporter, please verify this with the latest build of Weave 1.3b1. thanks
Thanks, now works as expected:

---cut---
2010-04-26 10:37:40	Service.Main         INFO	Loading Weave 1.3b1
2010-04-26 10:37:40	Engine.Bookmarks     DEBUG	Engine initialized
2010-04-26 10:37:40	Engine.Forms         DEBUG	Engine initialized
2010-04-26 10:37:40	Engine.History       DEBUG	Engine initialized
2010-04-26 10:37:40	Engine.Passwords     DEBUG	Engine initialized
2010-04-26 10:37:40	Engine.Prefs         DEBUG	Engine initialized
2010-04-26 10:37:40	Engine.Tabs          DEBUG	Engine initialized
2010-04-26 10:37:40	Engine.Tabs          DEBUG	Resetting tabs last sync time
2010-04-26 10:37:40	Service.Main         INFO	Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.2.3) Gecko/20100415 Ubuntu/10.04 (lucid) Firefox/3.6.3
2010-04-26 10:37:40	Service.Main         DEBUG	Caching URLs under storage user base: https://my.weave.minimal.server/weave/1.0/username/
2010-04-26 10:37:42	Service.Main         DEBUG	Autoconnecting in 3 seconds
2010-04-26 10:37:45	Service.Main         INFO	Logging in user username
2010-04-26 10:37:45	Net.Resource         TRACE	HTTP Header Content-type: text/plain
2010-04-26 10:37:45	Net.Resource         TRACE	HTTP Header Authorization: ***** (suppressed)
2010-04-26 10:37:45	Service.Main         DEBUG	verifyLogin failed: NS_ERROR_PROXY_CONNECTION_REFUSED JS Stack trace: Channel_onStopRequest([object XPCWrappedNative_NoHelper],null,2152398920)@resource.js:333 < Res__request(...)@resource.js:208 < Res_get()@resource.js:271 < ()@service.js:530 < WrappedNotify()@util.js:114 < _verifyLogin()@service.js:519 < ()@service.js:691 < WrappedNotify()@util.js:114 < WrappedLock()@util.js:86 < WrappedCatch()@util.js:65 < WeaveSvc_login()@service.js:674 < _autoConnect([object Object])@service.js:653 < notify([object XPCWrappedNative_NoHelper])@util.js:629
2010-04-26 10:37:45	Service.Main         DEBUG	Exception: Login failed: error.login.reason.network No traceback available
2010-04-26 10:37:45	Service.Main         DEBUG	Autoconnect failed: error.login.reason.network; retry in 94 sec.
2010-04-26 10:39:19	Service.Main         INFO	Logging in user username
2010-04-26 10:39:19	Net.Resource         TRACE	HTTP Header Content-type: text/plain
2010-04-26 10:39:19	Net.Resource         TRACE	HTTP Header Authorization: ***** (suppressed)
2010-04-26 10:39:19	Service.Main         DEBUG	verifyLogin failed: NS_ERROR_PROXY_CONNECTION_REFUSED JS Stack trace: Channel_onStopRequest([object XPCWrappedNative_NoHelper],null,2152398920)@resource.js:333 < Res__request(...)@resource.js:208 < Res_get()@resource.js:271 < ()@service.js:530 < WrappedNotify()@util.js:114 < _verifyLogin()@service.js:519 < ()@service.js:691 < WrappedNotify()@util.js:114 < WrappedLock()@util.js:86 < WrappedCatch()@util.js:65 < WeaveSvc_login()@service.js:674 < _autoConnect()@service.js:653 < ([object Object])@service.js:661 < notify([object XPCWrappedNative_NoHelper])@util.js:629
2010-04-26 10:39:19	Service.Main         DEBUG	Exception: Login failed: error.login.reason.network No traceback available
2010-04-26 10:39:19	Service.Main         DEBUG	Autoconnect failed: error.login.reason.network; retry in 192 sec.
2010-04-26 10:42:30	Service.Main         INFO	Logging in user username
2010-04-26 10:42:30	Net.Resource         TRACE	HTTP Header Content-type: text/plain
2010-04-26 10:42:30	Net.Resource         TRACE	HTTP Header Authorization: ***** (suppressed)
2010-04-26 10:42:31	Net.Resource         TRACE	GET https://my.weave.minimal.server/weave/1.0/username/info/collections
[etc.]
Target Milestone: 1.3 → 1.3b1
Confirmed!

2010-04-27 08:58:18	Service.Main         INFO	Loading Weave 1.3b2
2010-04-27 08:58:18	Engine.Bookmarks     DEBUG	Engine initialized
2010-04-27 08:58:18	Engine.Forms         DEBUG	Engine initialized
2010-04-27 08:58:18	Engine.History       DEBUG	Engine initialized
2010-04-27 08:58:18	Engine.Passwords     DEBUG	Engine initialized
2010-04-27 08:58:18	Engine.Prefs         DEBUG	Engine initialized
2010-04-27 08:58:18	Engine.Tabs          DEBUG	Engine initialized
2010-04-27 08:58:18	Engine.Tabs          DEBUG	Resetting tabs last sync time
2010-04-27 08:58:18	Service.Main         INFO	Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.3) Gecko/20100401 Firefox/3.6.3 ImageShackToolbar/5.2.4 ( .NET CLR 3.5.30729)
2010-04-27 08:58:18	Service.Main         DEBUG	Caching URLs under storage user base: https://sj-weave01.services.mozilla.com/1.0/rnicoletto/
2010-04-27 08:58:23	Service.Main         DEBUG	Autoconnecting in 4 seconds
2010-04-27 08:58:27	Service.Main         INFO	Logging in user xxx
2010-04-27 08:58:27	Service.Main         DEBUG	verifyLogin failed: NS_ERROR_PROXY_CONNECTION_REFUSED JS Stack trace: Channel_onStopRequest([object XPCWrappedNative_NoHelper],null,2152398920)@resource.js:333 < Res__request(...)@resource.js:208 < Res_get()@resource.js:271 < ()@service.js:530 < WrappedNotify()@util.js:114 < _verifyLogin()@service.js:519 < ()@service.js:691 < WrappedNotify()@util.js:114 < WrappedLock()@util.js:86 < WrappedCatch()@util.js:65 < WeaveSvc_login()@service.js:674 < _autoConnect([object Object])@service.js:653 < notify([object XPCWrappedNative_NoHelper])@util.js:629
2010-04-27 08:58:27	Service.Main         DEBUG	Exception: Login failed: error.login.reason.network No traceback available
2010-04-27 08:58:27	Service.Main         DEBUG	Autoconnect failed: error.login.reason.network; retry in 93 sec.

Using Firefox 3.6.3 on Windows XP + Weave Sync 1.3 beta 2.
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.