561536 - HTTP CONNECT does not properly handle 302 error

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Ivan]

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

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

[(mostly gone) XtC4UaLL [:xtc4uall]]

Is Bug 544979 related here?

Comment 3

[Mike Hommey [:glandium]]

It looks like so.

Comment 4

[Ivan]

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

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]

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]

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

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]

Log sended to you by email.

I can give access to my proxy, or config files to squid and nginx

Comment 10

[Ivan]

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]

Attachment: hacked version of TinyHTTPProxy.py that returns constant response to CONNECT

Comment 12

[Nickolay_Ponomarev]

Attachment: 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]

Attachment: HTTP logs

My and Ivan's logs.

Comment 14

[Nickolay_Ponomarev]

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 [:bzbarsky]]

> 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 [:bzbarsky]]

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 [:bzbarsky]]

Attachment: Fix

I assume we need this on all the branches too, right?

Comment 18

[Jason Duell]

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

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

(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 [:bzbarsky]]

Pushed http://hg.mozilla.org/mozilla-central/rev/d237da454ab7

Comment 22

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 441528 [details] [diff] [review]
Fix

Requesting approvals for all affected branches.

Comment 23

[Mike Beltzner [:beltzner, not reading bugmail]]

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

Comment on attachment 441528 [details] [diff] [review]
Fix

oops - setting flags appropriately

Comment 25

[Boris Zbarsky [:bzbarsky]]

Pushed:
 http://hg.mozilla.org/releases/mozilla-1.9.2/rev/a84d87dc5f1f
 http://hg.mozilla.org/releases/mozilla-1.9.1/rev/b1b05fd77e73

Comment 27

[Ben Bucksch (:BenB)]

Thank you, bz! (See bug 492459)

My problem is fixed (so VERIFIED as far as I'm concerned).

Comment 28

[Zeno Kugy]

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 [:bzbarsky]]

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 [:bzbarsky]]

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]

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 [:bzbarsky]]

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

Is firefox 3.6.6 supposed to have this fix? It doesn't seem to.

Comment 34

[Michael]

Think I know why my proxy returns 405 errors rather than 302 errors.

Comment 35

[Boris Zbarsky [:bzbarsky]]

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

Boris, when did you answer that? I can't find any comment regarding 3.6.6.

Comment 37

[Nickolay_Ponomarev]

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]

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 [:bzbarsky]]

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

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)]

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 [:bzbarsky]]

Fine by me.

Comment 43

[Smokey Ardisson (offline for a while; not following bugs - do not email)]

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