1320360 - With multi-e10s nightly, on a iffy network, a tab opened in background just stops loading pages, and shows about:newtab

Status: RESOLVED INCOMPLETE

(Core :: Networking, defect, P2)

Description

[Mayank Bansal]

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:53.0) Gecko/20100101 Firefox/53.0
Build ID: 20161124030208

Steps to reproduce:

1. Using my normal profile
2. Using my Mobile phone as a tethering device
3. Sometimes, when I click on a link, and open it in background, it keeps on loading for a while(spinner spinning), but then just stops loading the page, and shows the about:newtab page


This is on a Win10 X64 machine, with multi-e10s added


Actual results:

Maybe I can do some logging to collect data?

Comment 1

[Mayank Bansal]

Tentative ni?

Comment 2

[Honza Bambas (:mayhemer)]

Yes please, see https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging.  If e10s works, there should be more than one log file produced (some with .child-N extensions from child processes).

Please - important - also list the URLs you were visiting and which didn't load.

You can send the log files to my bugzilla email if you don't want to expose private data.

Thanks.

Comment 3

[Mayank Bansal]

Attachment: log.txt-main.3188

I was on:

https://en.wikipedia.org/wiki/Pulp_Fiction

I opened three links in background tabs: 
https://en.wikipedia.org/wiki/Theme_restaurant
https://en.wikipedia.org/wiki/Vietnam_veteran
(the third one i forget. I was clicking links randomly)

None of the links loaded. 

Point to remember is that I was scrolling fast on the foreground tab.

This is an intermittent issue.

Comment 4

[Mayank Bansal]

Attachment: aboutsupport.txt

Comment 5

[Mayank Bansal]

Attachment: log.txt-main.3188

Another one.
I was on : 
https://en.wikipedia.org/wiki/Pulp_Fiction

I opened 5 random links in quick succession:
Unfortunately, i dont remember which I opened. But none of them loaded.

Comment 6

[Honza Bambas (:mayhemer)]

So, there are no .child-N log files produced?

Comment 7

[Honza Bambas (:mayhemer)]

Also, how exactly did you setup the MOZ_LOG env var, just for completeness?

Thanks.

Comment 8

[Mayank Bansal]

(In reply to Honza Bambas (:mayhemer) from comment #6)
> So, there are no .child-N log files produced?

No.I dont think so.

(In reply to Honza Bambas (:mayhemer) from comment #7)
> Also, how exactly did you setup the MOZ_LOG env var, just for completeness?
> 
> Thanks.

I just opened about:networking->Logging->start logging.
Repriduced the issue, and then "stop logging".

Comment 9

[Honza Bambas (:mayhemer)]

The log seems incomplete or tempered with, reporter, did you edit the file in any way?

Also, as you have a number of addons installed, please try to reproduce with a clean profile or try disabling addons one by one to find out if any of them is the cause here.

I see a SPDY problem.  Something for Patrick or Nick:


2016-11-25 18:14:13.180000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Init [this=2740e789800]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=2740e789800 header="Referer" value="https://en.wikipedia.org/wiki/Pulp_Fiction" merge=0]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=2740e789800 header="Cookie" value="" merge=0]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::SetCacheKey [this=2740e789800 key=2741cc68580]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::SetAllowStaleCacheContent [this=2740e789800, allow=0]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::AsyncOpen [this=2740e789800]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=2740e789800 header="Cookie" value="WMF-Last-Access=25-Nov-2016; CP=H2; GeoIP=IN:MH:Pune:18.53:73.87:v4; enwikimwuser-sessionId=1518f96c04db6287" merge=0]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ResolveProxy [this=2740e789800]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnProxyAvailable [this=2740e789800 pi=0 status=0 mStatus=0]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::BeginConnect [this=2740e789800]
2016-11-25 18:14:13.180000 UTC - [Main Thread]: D/nsHttp nsHttpChannel 2740e789800 Using default connection info
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::BeginConnect [this=2740e789800] prefetching
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ContinueBeginConnectWithResult [this=2740e789800]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Connect [this=2740e789800]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=2740e789800 header="Upgrade-Insecure-Requests" value="1" merge=0]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OpenCacheEntry [this=2740e789800]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnCacheEntryAvailable [this=2740e789800 entry=2741cc686a0 new=1 appcache=0 status=0 mAppCache=0 mAppCacheForWrite=0]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::SetupTransaction [this=2740e789800]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp Creating nsHttpTransaction @27417cb4400
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel 2740e789800 created nsHttpTransaction 27417cb4400
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpTransaction::Init [this=27417cb4400 caps=21]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpTransaction 27417cb4400 SetRequestContext 27412b44a50
2016-11-25 18:14:13.181000 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::AddTransaction [trans=27417cb4400 0]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ContinueBeginConnectWithResult result [this=2740e789800 rv=0 mCanceled=0]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Starting nsChannelClassifier 2741cc685c0 [this=2740e789800]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::SuspendInternal [this=2740e789800]
2016-11-25 18:14:13.181000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnLookupComplete [this=2740e789800] prefetch complete: success status[0x0]
2016-11-25 18:14:13.181000 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::TryDispatchTransaction without conn [trans=27417cb4400 ci=27417307390 ci=.S....en.wikipedia.org:443 caps=21 tunnelprovider=0 onlyreused=0 active=1 idle=0]
2016-11-25 18:14:13.182000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ResumeInternal [this=2740e789800]
2016-11-25 18:14:13.182000 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::DispatchTransaction [ent-ci=.S....en.wikipedia.org:443 2741eea1500 trans=27417cb4400 caps=21 conn=27412fc2f00 priority=0]
2016-11-25 18:14:13.182000 UTC - [Socket Thread]: V/nsHttp Spdy Dispatch Transaction via Activate(). Transaction host = en.wikipedia.org, Connection host = en.wikipedia.org
2016-11-25 18:14:13.182000 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Activate [this=27412fc2f00 trans=27417cb4400 caps=21]
2016-11-25 18:14:13.199000 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnSocketStatus [this=27417cb4400 status=804b0005 progress=64]
2016-11-25 18:14:13.199000 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnTransportStatus 27417cb4400 SENDING_TO without request body
2016-11-25 18:14:13.199000 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnSocketStatus [this=27417cb4400 status=804b000a progress=0]
2016-11-25 18:14:13.199000 UTC - [Main Thread]: D/nsHttp sending progress and status notification [this=2740e789800 status=804b000a progress=0/0]
2016-11-25 18:14:13.199000 UTC - [Socket Thread]: V/nsHttp   ProcessNewTransaction Dispatch Immediately trans=27417cb4400


> Here we close the session:

2016-11-25 18:14:29.567000 UTC - [Socket Thread]: I/nsHttp Http2Session::Close 274137a5800 804B000E

 = NS_ERROR_NET_TIMEOUT


2016-11-25 18:14:29.567000 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::Close [this=27417cb4400 reason=80004004]


> which converts to NS_ERROR_FAILURE, which doesn't have any error page in docshell and gives just a blank page (might be e10s specific here).


2016-11-25 18:14:29.567000 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction 27417cb4400 request context set to null in ReleaseBlockingTransaction() - was 27412b44a50
2016-11-25 18:14:29.568000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnStartRequest [this=2740e789800 request=274172b53e0 status=80004004]
2016-11-25 18:14:29.568000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ProcessFallback [this=2740e789800]
2016-11-25 18:14:29.569000 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::SetApplyConversion [this=2740e789800 value=0]
2016-11-25 18:14:29.569000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::GetCacheKey [this=2740e789800]
2016-11-25 18:14:29.569000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnStopRequest [this=2740e789800 request=274172b53e0 status=80004004]
2016-11-25 18:14:29.569000 UTC - [Main Thread]: D/nsHttp nsHttpChannel 2740e789800 has a strongly framed transaction: 0
2016-11-25 18:14:29.569000 UTC - [Main Thread]: D/nsHttp nsHttpTransaction::DeleteSelfOnConsumerThread [this=27417cb4400]
2016-11-25 18:14:29.569000 UTC - [Main Thread]: D/nsHttp Destroying nsHttpTransaction @27417cb4400
2016-11-25 18:14:29.569000 UTC - [Main Thread]: D/nsHttp nsHttpTransaction 27417cb4400 request context set to null in ReleaseBlockingTransaction() - was 0
2016-11-25 18:14:29.569000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::FinalizeCacheEntry [this=2740e789800]
2016-11-25 18:14:29.569000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::CloseCacheEntry [this=2740e789800] mStatus=80004004 mCacheEntryIsWriteOnly=1
2016-11-25 18:14:29.621000 UTC - [Main Thread]: D/nsHttp Destroying nsHttpChannel [this=2740e789800]
2016-11-25 18:14:29.621000 UTC - [Main Thread]: V/nsHttp Destroying HttpBaseChannel @e789800 


This can well be just an intermittent network issue (bad wifi router, bad ISP) that we don't communicate well to UI.  But here I don't follow the e10s influence, so might be a red herring.

Needs some more diagnoses.

Comment 10

[Honza Bambas (:mayhemer)]

(In reply to mayankleoboy1 from comment #8)
> (In reply to Honza Bambas (:mayhemer) from comment #6)
> > So, there are no .child-N log files produced?
> 
> No.I dont think so.

about:networking->Logging causes that...

> 
> (In reply to Honza Bambas (:mayhemer) from comment #7)
> > Also, how exactly did you setup the MOZ_LOG env var, just for completeness?
> > 
> > Thanks.
> 
> I just opened about:networking->Logging->start logging.
> Repriduced the issue, and then "stop logging".

Aha!  That's the reason I'm missing some stuff like startup and initial DNS lookups...  Hmm.. using env vars has some advantages..

Comment 11

[Patrick McManus [:mcmanus]]

Nothing had happened in a long long time.. would percolating TIMEOUT up to docshell be the right thing?

Comment 12

[Honza Bambas (:mayhemer)]

Patrick, Nick, I was asking you for looking at the logs.  It seems like an h2 issue.

I think we propagate timeout to docshell, don't we?

Comment 13

[Firefox Bug Husbandry Bot]

Bulk change to priority: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258

Comment 14

[Honza Bambas (:mayhemer)]

for lack of response