1094156 - 301/302 not redirect properly

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[Alexandre Vicenzi]

Attachment: redirect.png

User Agent: Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.104 Safari/537.36

Steps to reproduce:

Access this URL: http://ava.furb.br


Actual results:

Moved Permanently page.


Expected results:

Redirect to http://ava.furb.br/ava/portal/index.php

Comment 1

[:Gijs (he/him)]

I can't reproduce, and get the redirect immediately (both using Firefox 34 beta and 36 nightly from Nov. 4). Have you tried a clean profile and/or restarting with add-ons disabled? What version of Firefox did you test with?

Comment 2

[Alexandre Vicenzi]

Happens with http://reddit.com/ too.
I'm using 36.0a1 (2014-11-04).

After restarting doesn't happens anymore.

Comment 3

[Alexandre Vicenzi]

I'm getting this error again.

Access http://www.google.com.br/ and got 302 Moved.

Restart FF and everything is OK. I have no idea how to simulate this, it's a random error.

Comment 4

[:Gijs (he/him)]

(In reply to alexandrevicenzi from comment #3)
> I'm getting this error again.
> 
> Access http://www.google.com.br/ and got 302 Moved.
> 
> Restart FF and everything is OK. I have no idea how to simulate this, it's a
> random error.

Are you using e10s? Does it happen if you disable e10s? Does it happen on a clean profile?

Without a way to reproduce this and/or more details about under what circumstances this happens, it's going to be very hard to figure out what's at fault here (whether that's Firefox at all or something else). :-(

Comment 5

[Alexandre Vicenzi]

e10s is disabled, as I said, it's to random :/

There's no way to get some log?

Comment 6

[:Gijs (he/him)]

(In reply to alexandrevicenzi from comment #5)
> e10s is disabled, as I said, it's to random :/
> 
> There's no way to get some log?

You can get a NSPR log, and/or use a packet tracing tool like wireshark, but if the network responses are sensible but the UI response isn't, I don't know how much that'll tell you. Could try the wireshark option in case something else is inserting the response you're seeing (like a proxy or whatever) - that might give us clues.

You've not answered my add-ons question. :-)

Comment 7

[Alexandre Vicenzi]

About:

> Does it happen on a clean profile?

Happened twice, and I don't know how to reproduce. So, with a clean profile I'll need to wait until this happen again, if it will someday.

And yes, I'm behind a proxy (http://dansguardian.org/), but if I restart FF, everything works OK.

Comment 8

[Alexandre Vicenzi]

The scenario is:

Access a site like: www.foobar.com
When access this URL the site redirect with 302 to www.foobar.com/someurl

Instead of redirect to this new URL FF shows "302 Moved" in bold.

If I go to Inspector/Network I can see a 302 response, but it's not being redirected.

Comment 9

[:Gijs (he/him)]

(In reply to alexandrevicenzi from comment #7)
> About:
> 
> > Does it happen on a clean profile?
> 
> Happened twice, and I don't know how to reproduce. So, with a clean profile
> I'll need to wait until this happen again, if it will someday.
> 
> And yes, I'm behind a proxy (http://dansguardian.org/), but if I restart FF,
> everything works OK.

Hm, sure, but it might be related to the length of time you're connected to the proxy and/or time of day and... stuff.

Sounds like using wireshark might still be worth it, if it can catch more details about what kind of 302 this is and where it comes from...

Also, to be clear... it sounds now like you're saying Firefox will somehow get into this state where any of these requests will get 'stuck' on the 302 page - ie you can refresh, and it'll happen again, etc. ?

Comment 10

[Alexandre Vicenzi]

(In reply to :Gijs Kruitbosch from comment #9)

> Hm, sure, but it might be related to the length of time you're connected to
> the proxy and/or time of day and... stuff.

Needed to restart PC after this happen, so, was a short time.

> Sounds like using wireshark might still be worth it, if it can catch more
> details about what kind of 302 this is and where it comes from...

If I could reproduce this more frequently I could try to catch all requests. I'll keep an eye on this.

> Also, to be clear... it sounds now like you're saying Firefox will somehow
> get into this state where any of these requests will get 'stuck' on the 302
> page - ie you can refresh, and it'll happen again, etc. ?

Yes, and when happens there's no way to stop until restart FF. If happens to one site, it will happens to all, even if I close the tab or press F5.

Just to clarify, at home, without proxy and using openSUSE, this never happened. I know Dans Guardian is a suck sometimes, but all other browsers work fine.

Comment 11

[:Gijs (he/him)]

Patrick, Victor, I know that there's not necessarily much to go on here, but does this bug so far ring any bells and/or do you have suggestions as to how to debug further? Thanks!

Comment 12

[Victor Porof [:vporof][:vp]]

I don't have much experience when it comes to this sort of stuff. I'm assuming the standard problems were already ruled out? (add-ons disabled, clean profile, try aurora etc.)

Comment 13

[Patrick McManus [:mcmanus]]

is this really any website, or is it google? There was one report yesterday about redirect problems with google that went away. If I was guessing I would suspect that google.com updated their server side h2 code and there is a problem at that layer. If you're seeing this with non google then that's not a lead.

You can get a huge log that would help via https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging - but its a really huge log. If you turn the http level down to 4 (the example has it at 5) the log will get orders of magnitude smaller - but of course we lose information.

I'll ping my google.com contacts and see if they've heard of this.

Comment 14

[Patrick McManus [:mcmanus]]

ah - I just same comment 2 about http://reddit.com - so its not a google.com or h2 issue. sorry for the distraction.

Comment 15

[Blair McBride [:Unfocused] (UNAVAILABLE)]

I'm getting this on (I think) any site at the moment.

The trouble is, restarting fixes it for a time. The issue pops up again only after several hours (I've already had this happen twice, think it's been fixed by a Nightly update, then have it occur half a day later).

Given the time period I seem to need to wait until I hit this after restarting, HTTP logging doesn't seem viable :\

Comment 16

[Patrick McManus [:mcmanus]]

smells like e10s.. +jason

Comment 17

[Patrick McManus [:mcmanus]]

any ideas jason?

Comment 18

[:Gijs (he/him)]

(In reply to Patrick McManus [:mcmanus] from comment #16)
> smells like e10s.. +jason

comment #5 says e10s is disabled. I don't know if that's the case for Blair, too.

Comment 19

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(In reply to :Gijs Kruitbosch from comment #18)
> (In reply to Patrick McManus [:mcmanus] from comment #16)
> > smells like e10s.. +jason
> 
> comment #5 says e10s is disabled. I don't know if that's the case for Blair,
> too.

I have e10s disabled too.

Comment 20

[Paul Silaghi, QA [:pauly]]

Everything's also fine with e10s ON, 36.0a1 (2014-11-17) Win 7 x64

Comment 21

[Jason Duell]

Honza, could this be related to the cache somehow?  I guess it would need to be memory cache since it goes away when we restart.

Comment 22

[Jason Duell]

Blair, are you saying that when this happens, you suddenly get an error page for every 301/302 redirect that you encounter until you restart?  Or you just get them once in a while?  Or you get them reliably, but only for certain URIs?

Comment 23

[Honza Bambas (:mayhemer)]

I'll wait for more info here first.

To confirm:

The symptoms are exactly:
- you go to page www.example.com
- you expect to be redirected to www.foo.com and see it's content
- but instead you see www.example.com left in the address bar and the content is a server error page "30X The page has been redirected _here_" or something like that

Questions: 
- after this has happened, and you go to www.example.com in a new tab/window (typing the address in again) are you still getting this 30X page?
- when you try to open the page in Private browsing window, do you still get the same behavior?
- what is the code number(s) you see?  301, 302 or which one exactly?

Comment 24

[Alexandre Vicenzi]

(In reply to Honza Bambas (:mayhemer) from comment #23)
> I'll wait for more info here first.
> 
> To confirm:
> 
> The symptoms are exactly:
> - you go to page www.example.com
> - you expect to be redirected to www.foo.com and see it's content
> - but instead you see www.example.com left in the address bar and the
> content is a server error page "30X The page has been redirected _here_" or
> something like that
> 
> Questions: 
> - after this has happened, and you go to www.example.com in a new tab/window
> (typing the address in again) are you still getting this 30X page?

Yes.

> - when you try to open the page in Private browsing window, do you still get
> the same behavior?

Happened twice, and I didn't made this test, but just restarting FF to solve.

> - what is the code number(s) you see?  301, 302 or which one exactly?

I got "302 Moved" message, no more than this.

Comment 25

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(Sorry for lag, been away at a conference)

(In reply to Jason Duell [:jduell] (needinfo? me for lower latency) from comment #22)
> Blair, are you saying that when this happens, you suddenly get an error page
> for every 301/302 redirect that you encounter until you restart?

AFAICT, yes, this.

Comment 26

[Honza Bambas (:mayhemer)]

Note: if comment 25 is really the behavior, then it could be some of the redirect veto listeners that goes crazy (always vetoes).  Safe mode could help discover any addon involved.  There are too many places to check in Gecko/desktop tho.  NSPR log might help as well (nsHttp:4 and then a failing URL to search for it in the log).

Comment 27

[Alexandre Vicenzi]

I found another way to reproduce.

Step:

Enable e10s.
Go to this url: https://github.com/PagueVeloz/ClientAPI/blob/master/python/pagueveloz/api/base.py
Click on Raw button.

Result:

"You are being redirected." message. But it's not redirected.

It's not redirecting properly.

Build 37.0a1 (2014-12-15) on Windows 8.1 x64.

Comment 28

[:Gijs (he/him)]

(In reply to alexandrevicenzi from comment #27)
> I found another way to reproduce.
> 
> Step:
> 
> Enable e10s.
> Go to this url:
> https://github.com/PagueVeloz/ClientAPI/blob/master/python/pagueveloz/api/
> base.py
> Click on Raw button.
> 
> Result:
> 
> "You are being redirected." message. But it's not redirected.
> 
> It's not redirecting properly.
> 
> Build 37.0a1 (2014-12-15) on Windows 8.1 x64.

I can reliably reproduce this, but only on my win8 machine, not on osx. NSPR logs coming up.

Comment 29

[:Gijs (he/him)]

Attachment: nsprlog.txt

Comment 30

[:Gijs (he/him)]

Attachment: nsprlog.txt.child-1

Comment 31

[:Gijs (he/him)]

Interestingly, when stuck on the redirect page, ctrl-u opens the page source showing the correct (redirected) content... and after closing firefox and restoring the session, the correct content loads, too.

Comment 32

[Dragana Damjanovic [:dragana]]

This is maybe the same problem as bug 1106396.
In bug 1106396 somehow redirect is a bit strange, but I do not know what is I am trying to figure it out.

I am able to reproduce this with my Win XP, I will add some log to see if it is the same problem as bug 1106396.

Comment 33

[Dragana Damjanovic [:dragana]]

Ok it is not the same thing.
But I have found this in the log, (I have run it with timestamp,all:5):

request is cancelled at:
http://hg.mozilla.org/mozilla-central/annotate/249dbdbe09e0/dom/security/nsCSPService.cpp#l339 

2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsAsyncRedirectVerifyHelper::OnRedirectVerifyCallback() result=0 expectedCBs=1 mResult=0
2014-12-16 04:26:49.375000 UTC - 0[c17140]: Destroying nsStandardURL @7d6e2f0
2014-12-16 04:26:49.375000 UTC - 0[c17140]:   result=0 expectedCBs=0
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsAsyncRedirectVerifyHelper::DelegateOnChannelRedirect() sink=65dee84 expectedCBs=0 mResult=0
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPContext::ShouldLoad, aContentLocation: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPPolicy::permits, aUri: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py, aDir: 7, aSpecific: false
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPDirective::permits, aUri: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPHostSrc::permits, aUri: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPHostSrc::permits, aUri: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPHostSrc::permits, aUri: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPHostSrc::permits, aUri: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPHostSrc::permits, aUri: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPHostSrc::permits, aUri: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPContext::permitsInternal, false
2014-12-16 04:26:49.375000 UTC - 0[c17140]: THRD(c042b0) Dispatch [7d89460 0]
2014-12-16 04:26:49.375000 UTC - 0[c17140]: EVENTQ(c042e8): notify
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsCSPContext::ShouldLoad, decision: load, aContentLocation: https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: CSPService::AsyncOnChannelRedirect called for https://raw.githubusercontent.com/PagueVeloz/ClientAPI/master/python/pagueveloz/api/base.py
2014-12-16 04:26:49.375000 UTC - 0[c17140]: CSPService::AsyncOnChannelRedirect CANCELLING request.
2014-12-16 04:26:49.375000 UTC - 0[c17140]:   result=804b0001 expectedCBs=1
2014-12-16 04:26:49.375000 UTC - 0[c17140]:   emulating OnRedirectVerifyCallback...
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsAsyncRedirectVerifyHelper::OnRedirectVerifyCallback() result=804b0001 expectedCBs=1 mResult=0
2014-12-16 04:26:49.375000 UTC - 0[c17140]: nsAsyncRedirectVerifyHelper::ExplicitCallback() result=804b0001 expectedCBs=0 mCallbackInitiated=0 mResult=804b0001

Comment 34

[Dragana Damjanovic [:dragana]]

Hi Christoph,

I am not sure how is the right person to take a look at this (comment 33). You had change it recently.

Comment 35

[Christoph Kerschbaumer [:ckerschb, back on May 21st]]

Hey Dragana,

thanks for bringing this problem to my attention. Apparently there are several problems acting together here.

CC'ing [sicking,tanvi,sstamm]

First, here is the test I use to reproduce (always reproduceable on nightly - thanks Gijs for providing that testcase):
Go to:
  https://github.com/PagueVeloz/ClientAPI/blob/master/python/pagueveloz/api/base.py
Click: 'raw' button



Second, CSP is blocking the redirect in e10s, but why only on e10s?
Lets look at the principal that we use to grep the CSP in ::AsyncOnChannelRedirect()
http://mxr.mozilla.org/mozilla-central/source/dom/security/nsCSPService.cpp#288

non-10s:
Principal: SystemPrincipal

e10s:
Principal: https://github.com/PagueVeloz/ClientAPI/blob/master/python/pagueveloz/api/base.py

If the Principal is system, the ::GetCSP() returns null, see
http://mxr.mozilla.org/mozilla-central/source/caps/nsSystemPrincipal.cpp#129
and the non-e10s case returns without inspecting the CSP - no good!
In fact, the principal for e10s and non e10s mode should be the same!

In e10s mode, we can query a CSP and call shouldLoad.
Internally TYPE_DOCUMENT maps to FRAME_SRC, see:
http://mxr.mozilla.org/mozilla-central/source/dom/security/nsCSPUtils.cpp#155
and since the CSP of that page contains a FRAME_SRC directive that redirect gets blocked.
Reason for the problem is, that in the regular shouldLoad() case, we explicitly whitelist TYPE_DOCUMENT, see:
http://mxr.mozilla.org/mozilla-central/source/dom/security/nsCSPService.cpp#136
I think we also have to whitelist TYPE_DOCUMENT in the redirect case in ::AsyncOnChannelRedirect().

Sid, I am going to inspect why we are having different principals in the LoadInfo for e10s and non-e10s cases, any chance you want to update the TYPE_DOCUMENT whitelisting?


%--------- CSP of the GitHub page ----------
default-src *;
script-src assets-cdn.github.com collector-cdn.github.com;
object-src assets-cdn.github.com;
style-src 'self' 'unsafe-inline' 'unsafe-eval' assets-cdn.github.com;
img-src 'self' data: assets-cdn.github.com identicons.github.com www.google-analytics.com collector.githubapp.com *.githubusercontent.com *.gravatar.com *.wp.com;
media-src 'none';
frame-src 'self' render.githubusercontent.com gist.github.com www.youtube.com player.vimeo.com checkout.paypal.com;
font-src assets-cdn.github.com;
connect-src 'self' ghconduit.com:25035 live.github.com uploads.github.com www.google-analytics.com s3.amazonaws.com

Comment 36

[Christoph Kerschbaumer [:ckerschb, back on May 21st]]

Jonas, I further debugged the testcase from Comment 35 and I found the root cause of the problem, which is here:
http://mxr.mozilla.org/mozilla-central/source/docshell/base/nsDocShell.cpp#10315

Do you happen to know why in e10s the requestingNode->NodePrincipal() is
  https://github.com/PagueVeloz/ClientAPI/blob/master/python/pagueveloz/api/base.py
whereas in regular mode is
  SystemPrincipal
for that particular testcase (see Comment 35). That's really surprising to me actually.

Since the SystemPrincipal does not hold a CSP but the principal of
  https://github.com/PagueVeloz/ClientAPI/blob/master/python/pagueveloz/api/base.py
holds the page's CSP we end up blocking the redirect in e10s but not in regular mode.
Since it's a load of TYPE_DOCUMENT, the load should be permitted without even consulting CSP.

Any idea why the node might have a different principal in e10s?

Comment 37

[Sid Stamm [:geekboy or :sstamm]]

(In reply to Christoph Kerschbaumer [:ckerschb] from comment #35)
> Sid, I am going to inspect why we are having different principals in the
> LoadInfo for e10s and non-e10s cases, any chance you want to update the
> TYPE_DOCUMENT whitelisting?

We should probably make TYPE_DOCUMENT map to nsIContentSecurityPolicy::NO_DIRECTIVE since there really aren't any mappings that make sense (since we don't enforce CSP on targets of link clicks, for example).

Comment 38

[Christoph Kerschbaumer [:ckerschb, back on May 21st]]

Since bug 1112782 got fixed, the problem described in this bug can be marked as fixed as well. Since we encountered a different problem as well while debugging, I filed Bug 1113196 to investigate.

Clearing needinfo flags for honza and jonas.

Gijs, can you confirm that Bug 1112782 indeed fixed all the problems mentioned in this bug?
If so, please marked it as fixed.

Comment 39

[:Gijs (he/him)]

(In reply to Christoph Kerschbaumer [:ckerschb] from comment #38)
> Since bug 1112782 got fixed, the problem described in this bug can be marked
> as fixed as well. Since we encountered a different problem as well while
> debugging, I filed Bug 1113196 to investigate.
> 
> Clearing needinfo flags for honza and jonas.
> 
> Gijs, can you confirm that Bug 1112782 indeed fixed all the problems
> mentioned in this bug?

I can confirm that it fixes the testcase from comment #28.

That said... was the fix e10s-specific? The original issue this was filed for happens with e10s disabled, so I don't know if that still reproduces. I think either Blair or Alexandre might be able to tell us.

NB: this patch will appear in *tomorrow*'s nightlies - not in today's. I tested with a local build. You can get a build from m-c that has the patch here:

64-bit: http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-central-win64-pgo/1418916614/

32-bit: http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-central-win32-pgo/1418916614/

Comment 40

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Oh, I'd completely forgotten about this bug, as I haven't encountered it recently. So I can only assume some other change fixed it for non-e10s.

Comment 41

[Christoph Kerschbaumer [:ckerschb, back on May 21st]]

(In reply to :Gijs Kruitbosch from comment #39)
> That said... was the fix e10s-specific?

Two things acting together caused the redirect to get blocked.
1) e10s and non-e10s have a different nodePrincipal in some cases - we still investigate why in bug 1113196.
2) CSPs redirect handling didn't account for top-level loads and accidentaly we ended up mapping TYPE_DOCUMENT to the wrong directive internally. This specific mapping problem got fixed in Bug 1112782 which makes e10s and non-e10s work again.

Comment 42

[Alexandre Vicenzi]

(In reply to :Gijs Kruitbosch from comment #39)
> (In reply to Christoph Kerschbaumer [:ckerschb] from comment #38)
> > Since bug 1112782 got fixed, the problem described in this bug can be marked
> > as fixed as well. Since we encountered a different problem as well while
> > debugging, I filed Bug 1113196 to investigate.
> > 
> > Clearing needinfo flags for honza and jonas.
> > 
> > Gijs, can you confirm that Bug 1112782 indeed fixed all the problems
> > mentioned in this bug?
> 
> I can confirm that it fixes the testcase from comment #28.
> 
> That said... was the fix e10s-specific? The original issue this was filed
> for happens with e10s disabled, so I don't know if that still reproduces. I
> think either Blair or Alexandre might be able to tell us.
> 
> NB: this patch will appear in *tomorrow*'s nightlies - not in today's. I
> tested with a local build. You can get a build from m-c that has the patch
> here:
> 
> 64-bit:
> http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-
> central-win64-pgo/1418916614/
> 
> 32-bit:
> http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-
> central-win32-pgo/1418916614/

I can't reproduce the original issue anymore. The issue from #27 is a little bit different. Testing again I can't reproduce anymore. Build 37.0a1 (2014-12-18).

Comment 43

[:Gijs (he/him)]

Thanks! :-)