Last Comment Bug 561536 - HTTP CONNECT does not properly handle 302 error
: HTTP CONNECT does not properly handle 302 error
Status: RESOLVED FIXED
: fixed1.9.0.20, regression
Product: Core
Classification: Components
Component: Networking: HTTP (show other bugs)
: Trunk
: All All
: -- normal with 1 vote (vote)
: mozilla1.9.3a5
Assigned To: Boris Zbarsky [:bz]
:
Mentors:
https://www.dyndns.com/account/
: 492459 (view as bug list)
Depends on: 564081
Blocks: 491818
  Show dependency treegraph
 
Reported: 2010-04-24 01:30 PDT by Ivan
Modified: 2013-03-14 08:54 PDT (History)
12 users (show)
bzbarsky: in‑testsuite?
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
betaN+
needed
.5-fixed
needed
.11-fixed


Attachments
hacked version of TinyHTTPProxy.py that returns constant response to CONNECT (7.28 KB, text/x-python-script)
2010-04-24 13:51 PDT, Nickolay_Ponomarev
no flags Details
test page loading the google analytics script over HTTPS (359 bytes, text/html)
2010-04-24 13:54 PDT, Nickolay_Ponomarev
no flags Details
HTTP logs (66.71 KB, application/x-zip)
2010-04-24 14:02 PDT, Nickolay_Ponomarev
no flags Details
Fix (954 bytes, patch)
2010-04-26 10:31 PDT, Boris Zbarsky [:bz]
jduell.mcbugs: review+
mbeltzner: approval1.9.2.4-
mbeltzner: approval1.9.2.5+
mbeltzner: approval1.9.1.10-
mbeltzner: approval1.9.1.11+
dveditz: approval1.9.0.next+
bzbarsky: approval1.8.1.next?
Details | Diff | Splinter Review

Description Ivan 2010-04-24 01:30:14 PDT
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.2; ru; rv:1.9.2.3) Gecko/20100401 MRA 5.6 (build 03278) Firefox/3.6.3 (.NET CLR 3.5.30729)
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.2; ru; rv:1.9.2.3) Gecko/20100401 MRA 5.6 (build 03278) Firefox/3.6.3 (.NET CLR 3.5.30729)

RequestLine size=253 
===========================================
CONNECT ssl.google-analytics.com:443 HTTP/1.1
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.2; ru; rv:1.9.2.3) Gecko/20100401 MRA 5.6 (build 03278) Firefox/3.6.3 (.NET CLR 3.5.30729)
Proxy-Connection: keep-alive
Host: ssl.google-analytics.com


===============================================
RequestLine size=288 
===========================================
HTTP/1.0 302 Moved Temporarily
Server: squid/3.1.0.15
Mime-Version: 1.0
Date: Sat, 24 Apr 2010 08:19:11 GMT
Content-Type: text/html
Content-Length: 0
Location: http://firewall/clear.gif
X-Squid-Error: 403 Access Denied
X-Cache: MISS from Firewall
Proxy-Connection: keep-alive


===============================================


Reproducible: Always

Steps to Reproduce:
1. use squid as proxy, on squid deny google-analytics.com and set deny_info http://firewall/clear.gif

2. try to open any https page with content from google-analytics.com
Actual Results:  
browser infinite wait answer from ssl.google-analytics.com fnd page dos not displayed

Expected Results:  
show page without content from ssl.google-analytics.com
Comment 1 Mike Hommey [:glandium] 2010-04-24 02:26:55 PDT
Something similar seems to happen when the proxy blocks ssl.google-analytics.com, so this might not be related to the 302 status at all.
Comment 2 XtC4UaLL [:xtc4uall] 2010-04-24 03:38:26 PDT
Is Bug 544979 related here?
Comment 3 Mike Hommey [:glandium] 2010-04-24 03:41:57 PDT
It looks like so.
Comment 4 Ivan 2010-04-24 05:11:15 PDT
IE8 work fine: open page with no delay
Proxy redirect all blocked sites/pages to file clear.gif on local server "firewall", with http:// all works fine
Comment 5 Matthias Versen [:Matti] 2010-04-24 05:36:28 PDT
What happens if you redirect to a https page ?
There are security restrictions for https proxy redirects that could cause this.
Blocking the page can block the rendering based on the script, that's normal.
Comment 6 Ivan 2010-04-24 06:11:23 PDT
If i redirect to a https page happens infinite waiting for data.

Then proxy server restarted=connection close, FF request other files and display page.
Comment 7 Nickolay_Ponomarev 2010-04-24 06:45:23 PDT
Can you post a HTTP log for this problem - https://developer.mozilla.org/en/HTTP_Logging ? I'm seeing similar symptoms with squid replaced by a small snippet of python code, but would like to confirm it's the same issue.

(And trying to install and configure squid is not really something most people would want to do just to troubleshoot an edge case problem.)
Comment 8 Matthias Versen [:Matti] 2010-04-24 06:54:36 PDT
Proxy redirects are disabled with bug 479880 but allowed again for http status codes with bug 491818 (if i read that right).

What happens if you redirect to a document with the right mime-type for a script ?
Comment 9 Ivan 2010-04-24 07:17:51 PDT
Log sended to you by email.

I can give access to my proxy, or config files to squid and nginx
Comment 10 Ivan 2010-04-24 07:29:29 PDT
I tryed without 

C( 257 bytes):
HTTP/1.0 302 Moved Temporarily
Server: squid/3.1.0.15
Mime-Version: 1.0
Date: Sat, 24 Apr 2010 14:21:29 GMT
Location: http://firewall/clear.gif
X-Squid-Error: 403 Access Denied
X-Cache: MISS from Firewall
Content-Length: 0
Connection: keep-alive


and with:
C( 297 bytes):
HTTP/1.0 302 Moved Temporarily
Server: squid/3.1.0.15
Mime-Version: 1.0
Date: Sat, 24 Apr 2010 14:25:06 GMT
Location: http://firewall/clear.gif
X-Squid-Error: 403 Access Denied
X-Cache: MISS from Firewall
Content-Type: application/x-javascript
Content-Length: 0
Connection: keep-alive


no affect :(
Comment 11 Nickolay_Ponomarev 2010-04-24 13:51:48 PDT
Created attachment 441303 [details]
hacked version of TinyHTTPProxy.py that returns constant response to CONNECT
Comment 12 Nickolay_Ponomarev 2010-04-24 13:54:32 PDT
Created attachment 441304 [details]
test page loading the google analytics script over HTTPS

From comparing HTTP logs, I think this testcase is close enough to the problem Ivan is seeing. To reproduce, run TinyHTTPProxy.py, set proxy in Firefox settings to 0.0.0.0:8000 for all protocols, then open this page via file:///
Comment 13 Nickolay_Ponomarev 2010-04-24 14:02:25 PDT
Created attachment 441305 [details]
HTTP logs

My and Ivan's logs.
Comment 14 Nickolay_Ponomarev 2010-04-24 14:27:20 PDT
The relevant part of the log in my testcase shows how Necko ends up calling nsScriptLoader::OnStreamComplete without aContext, which causes it to assert and drop the script load request, which I think should lead to the symptoms (script stuck in the loading state forever).

-1340452864[d553d0]: nsHttpTransaction::HandleContentStart [this=1db25fe0]
-1340452864[d553d0]: http response [
-1340452864[d553d0]:   HTTP/1.0 302 Moved Temporarily
...
-1340452864[d553d0]: SSL proxy CONNECT failed!
-1340452864[d553d0]: nsHttpTransaction::HandleContent [this=1db25fe0 count=0 read=0 mContentRead=0 mContentLength=0]
-1340452864[d553d0]: nsHttpConnection::CloseTransaction[this=db8fd0 trans=1db25fe0 reason=80470002]
-1340452864[d553d0]: nsHttpTransaction::Close [this=1db25fe0 reason=0]
...
-1607481568[d0a9b0]: sending status notification [this=1db25970 status=804b000a progress=0/0]
-1607481568[d0a9b0]: nsHttpChannel::OnStartRequest [this=1db25970 request=1e353480 status=0]
-1607481568[d0a9b0]: nsHttpChannel::ProcessResponse [this=1db25970 httpStatus=302]
-1607481568[d0a9b0]: Cancelling failed SSL proxy connection [this=1db25970 httpStatus=302]
-1607481568[d0a9b0]: nsHttpChannel::Cancel [this=1db25970 status=804b000d]
-1607481568[d0a9b0]: nsHttpConnectionMgr::CancelTransaction [trans=1db25fe0 reason=804b000d]
-1607481568[d0a9b0]: STS dispatch [dd0900]
-1340452864[d553d0]:     ...returned after 303213 milliseconds
-1340452864[d553d0]: nsHttpConnectionMgr::OnMsgCancelTransaction [trans=1db25fe0]
-1340452864[d553d0]: nsHttpTransaction::Close [this=1db25fe0 reason=804b000d]
-1340452864[d553d0]:   already closed
...
-1607481568[d0a9b0]: nsHttpChannel::OnStopRequest [this=1db25970 request=1e353480 status=804b000d]
-1607481568[d0a9b0]: nsHttpTransaction::DeleteSelfOnConsumerThread [this=1db25fe0]
-1607481568[d0a9b0]: Destroying nsHttpTransaction @1db25fe0
-1607481568[d0a9b0]: nsHttpChannel::FinalizeCacheEntry [this=1db25970]
-1607481568[d0a9b0]:   calling OnStopRequest
-1607481568[d0a9b0]: ###!!! ASSERTION: null request in stream complete handler: 'request', file /Users/nickolay/dev/mozilla-work/src/content/base/src/nsScriptLoader.cpp, line 989
-1607481568[d0a9b0]: WARNING: NS_ENSURE_TRUE(request) failed: file /Users/nickolay/dev/mozilla-work/src/content/base/src/nsScriptLoader.cpp, line 990

I'm not sure how this should be fixed, but when the proxy is down, the context is set at this stack:
#0	0x123bcadf in nsStreamLoader::OnStartRequest at nsStreamLoader.cpp:113
#1	0x1246df2b in nsHttpChannel::CallOnStartRequest at nsHttpChannel.cpp:824
#2	0x12474b1d in nsHttpChannel::OnStartRequest at nsHttpChannel.cpp:5210
#3	0x12385ade in nsInputStreamPump::OnStateStart at nsInputStreamPump.cpp:441
#4	0x123868a0 in nsInputStreamPump::OnInputStreamReady at nsInputStreamPump.cpp:397
#5	0x006ef088 in nsInputStreamReadyEvent::Run at nsStreamUtils.cpp:112
#6	0x00722d74 in nsThread::ProcessNextEvent at nsThread.cpp:527
#7	0x006a60ba in NS_ProcessPendingEvents_P at nsThreadUtils.cpp:200
#8	0x131868df in nsBaseAppShell::NativeEventCallback at nsBaseAppShell.cpp:125

and when it's up, but returning the 302 response, we end up here instead:
#0	0x1245f9bc in nsHttpChannel::ProcessFailedSSLConnect at nsHttpChannel.cpp:925
#1	0x124742ba in nsHttpChannel::ProcessResponse at nsHttpChannel.cpp:958
#2	0x124749bf in nsHttpChannel::OnStartRequest at nsHttpChannel.cpp:5181
#3	0x12385ade in nsInputStreamPump::OnStateStart at nsInputStreamPump.cpp:441
#4	0x123868a0 in nsInputStreamPump::OnInputStreamReady at nsInputStreamPump.cpp:397
#5	0x006ef088 in nsInputStreamReadyEvent::Run at nsStreamUtils.cpp:112

.. and never call nsStreamLoader::OnStartRequest, only calling nsStreamLoader::OnStopRequest (which has NULL context at this moment).

I think Necko is supposed to pass the correct context to nsScriptLoader. What I don't know is where the fix should be - should the stream loader have its OnStartRequest called by that point, or should it just pass the context from the channel (I haven't figured out why it's even stored yet). Biesi?
Comment 15 Boris Zbarsky [:bz] 2010-04-26 10:20:56 PDT
> and never call nsStreamLoader::OnStartRequest, only calling
> nsStreamLoader::OnStopRequest 

This would be a bug!  OnStartRequest is guaranteed to be called after AsyncOpen by the nsIChannel API.
Comment 16 Boris Zbarsky [:bz] 2010-04-26 10:29:57 PDT
I have no idea how to write tests for this.. But I can certainly confirm using steps from comment 12.  Looks like a regression from bug 491818.
Comment 17 Boris Zbarsky [:bz] 2010-04-26 10:31:43 PDT
Created attachment 441528 [details] [diff] [review]
Fix

I assume we need this on all the branches too, right?
Comment 18 Jason Duell [:jduell] (needinfo me) 2010-04-26 20:40:01 PDT
Comment on attachment 441528 [details] [diff] [review]
Fix

D'oh!  Yup, totally my code and my fault.  Thanks to all for tracking it down.  And yes, this should be applied to all branches.
Comment 19 Reed Loden [:reed] (use needinfo?) 2010-04-26 20:54:33 PDT
Drivers, this seems to be a regression from bug 491818, which in turn was a regression from bug 479880, which was an sg:high bug. It's a one line fix.
Comment 20 Mike Hommey [:glandium] 2010-04-26 23:58:32 PDT
(In reply to comment #16)
> I have no idea how to write tests for this..

I guess httpd.js should be augmented to allow CONNECT requests.
Comment 21 Boris Zbarsky [:bz] 2010-05-05 11:22:56 PDT
Pushed http://hg.mozilla.org/mozilla-central/rev/d237da454ab7
Comment 22 Boris Zbarsky [:bz] 2010-05-05 11:24:03 PDT
Comment on attachment 441528 [details] [diff] [review]
Fix

Requesting approvals for all affected branches.
Comment 23 Mike Beltzner [:beltzner, not reading bugmail] 2010-05-05 12:50:51 PDT
Comment on attachment 441528 [details] [diff] [review]
Fix

a=beltzner for 1.9.1 and 1.9.2 default (not the relbranches, though) which map to the upcoming 1.9.2.5 and 1.9.1.11

Not sure to handle the request for 1.9.0.19 or 1.8.1.next at this time.
Comment 24 Mike Beltzner [:beltzner, not reading bugmail] 2010-05-05 12:55:41 PDT
Comment on attachment 441528 [details] [diff] [review]
Fix

oops - setting flags appropriately
Comment 26 Ben Bucksch (:BenB) 2010-05-18 01:37:02 PDT
*** Bug 492459 has been marked as a duplicate of this bug. ***
Comment 27 Ben Bucksch (:BenB) 2010-05-18 01:40:04 PDT
Thank you, bz! (See bug 492459)

My problem is fixed (so VERIFIED as far as I'm concerned).
Comment 28 Zeno Kugy 2010-07-15 11:32:13 PDT
I have the impression that this bug is not completely fixed.
For example if I block etracker.com by my proxy (privoxy 3.0.16) , I cannot any longer access www.kreditkarte.at.
Firefox will wait forever for code.etracker.com

I am using Firefox 3.5.2 on Windows XP and Firefox 3.6.6 on Windows Vista.
Comment 29 Boris Zbarsky [:bz] 2010-07-15 11:54:26 PDT
Well, 3.5.2 would certainly not have this fix (and is at least 9 security updates out of date).  3.5.11 should.

For some reason the 1.9.2 repo is not showing the push from comment 25 at all.  But in any case, I _think_ it would have landed best-case in 1.9.2.7....
Comment 30 Boris Zbarsky [:bz] 2010-07-15 12:00:13 PDT
Looks like this actually landed on the 1.9.2 branch as http://hg.mozilla.org/releases/mozilla-1.9.2/rev/ba8960ab9acd

I still suspect that it'll be in 1.9.2.7, but I'm totally lost in our branch stuff now.
Comment 31 Zeno Kugy 2010-07-16 02:37:39 PDT
Tested also on 3.5.10. 
Also here https://www.kreditkarte.at cannot be accessed if etracker.com blocked via privoxy.
Comment 32 Boris Zbarsky [:bz] 2010-07-16 09:31:22 PDT
> Tested also on 3.5.10. 

_Please_ read comment 29.  The fix is in 3.5.11.  It's NOT in any earlier versions.  What made you think it was?
Comment 33 Michael 2010-07-16 20:00:41 PDT
Is firefox 3.6.6 supposed to have this fix? It doesn't seem to.
Comment 34 Michael 2010-07-16 20:07:17 PDT
Think I know why my proxy returns 405 errors rather than 302 errors.
Comment 35 Boris Zbarsky [:bz] 2010-07-16 20:11:55 PDT
> Is firefox 3.6.6 supposed to have this fix?

Michael, please read the bug.  I answered that question once already...
Comment 36 Heiko Baums 2010-07-17 04:09:12 PDT
Boris, when did you answer that? I can't find any comment regarding 3.6.6.
Comment 37 Nickolay_Ponomarev 2010-07-17 05:26:34 PDT
bz refers to comments 29 & 30. 1.9.2.7 is a Gecko version corresponding to Firefox 3.6.7. You can get a build for testing from http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/3.6.7-candidates/build2/
Comment 38 Heiko Baums 2010-07-17 05:53:43 PDT
Thanks, Nickolay.

Just a note: Normal users don't know the version numbers of the engine and which engine version is in which browser version. So they are only interested in the browser version.
Comment 39 Boris Zbarsky [:bz] 2010-07-17 21:13:05 PDT
Heiko, my apologies.  I was sure the 3.6/1.9.2 discussion included the Firefox version numbers, not just the Gecko ones... looks like I was wrong.
Comment 40 Daniel Veditz [:dveditz] 2010-07-22 19:17:05 PDT
Comment on attachment 441528 [details] [diff] [review]
Fix

Approved for 1.9.0.20, a=dveditz
Comment 41 Smokey Ardisson (offline for a while; not following bugs - do not email) 2010-07-24 14:53:11 PDT
Boris, do you mind if I go ahead and check this in for you on 1.9.0 when I'm doing all the patches for which I requested approval?
Comment 42 Boris Zbarsky [:bz] 2010-07-24 18:33:16 PDT
Fine by me.
Comment 43 Smokey Ardisson (offline for a while; not following bugs - do not email) 2010-07-25 22:12:21 PDT
Thanks!

Checking in netwerk/protocol/http/src/nsHttpChannel.cpp;
/cvsroot/mozilla/netwerk/protocol/http/src/nsHttpChannel.cpp,v  <--  nsHttpChannel.cpp
new revision: 1.339; previous revision: 1.338
done

Note You need to log in before you can comment on or make changes to this bug.