Firefox fails to load ReCAPTCHA's styles_ltr.css (4 KB/s)

NEW
Unassigned
(Needinfo from 2 people)

Status

()

P3
normal
2 years ago
11 months ago

People

(Reporter: BladeMight, Unassigned, NeedInfo)

Tracking

Trunk
x86_64
All
Points:
---

Firefox Tracking Flags

(firefox57 affected, firefox58 affected, firefox59 affected)

Details

(Whiteboard: [gfx-noted][necko-triaged])

Attachments

(2 attachments)

(Reporter)

Description

2 years ago
User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:47.0) Gecko/20100101 Firefox/47.0
Build ID: 20160604131506

Steps to reproduce:

Go to any of these pages:
https://developer.mozilla.org/en/users/account/signup
http://myanimelist.net/register.php
Wait while ReCAPTCHA loads...


Actual results:

And it fails to load ReCAPTCHA's styles_ltr.css file(you can view requests in DevTools), it loads 20-50 KB's but it size is ~90 KB, how can i make it work?



Expected results:

To load all stylees_ltr.css file.

Additional info:

Firefox: 47.0 and 49.0a2
Windows: 10.1511
Internet Speed: 4 KB/s(FOUR KILOBYTES PER SECOND)

Tested in Chrome and it works... I don't want just because of ReCAPTCHA switch to Chrome.
So can you help me?

Comment 1

2 years ago
WFM with FF48 on Win7x64, styles_ltr.css is 200 OK.

Can you make a test with a clean profile?
https://support.mozilla.org/en-US/kb/profile-manager-create-and-remove-firefox-profiles
Flags: needinfo?(BladeMight)
(Reporter)

Comment 2

2 years ago
>Can you make a test with a clean profile?

Same...

What i have done:
For quickly generate new profile i renamed 'Mozilla' folders in %appdata%\local %appdata%\roaming, start Firefox.
And then go to http://myanimelist.net/register.php and here what happens:

http://i80.fastpic.ru/big/2016/0812/92/bcf427806ecbb28208a241686f640392.png

First time it loads 36,06 KB of styles_ltr.css and second time aborts request, which in Chrome is 206(partial content) and after it fallback will be 200 OK, but in Firefox 400 Bad Request due to not loaded styles_ltr.css.
Flags: needinfo?(BladeMight)
User Agent: Mozilla/5.0 (Windows NT 10.0; rv:51.0) Gecko/20100101 Firefox/51.0
Build ID: 20160811030201

I have tested your issue on latest FF release (v48.0) and latest Nightly (v51.0a1) and managed to reproduce it. I have set a bandwidth limit using NetBalancer to 4KB/s and accessed http://myanimelist.net/register.php . In the Web Console->Network tab I can see that `styles_ltr.css` is 200 OK, but on the page the Captcha is not loading/is not displayed and sometimes a message is displayed which informs the user about the poor connection to the internet. 
The same steps were applied using Google Chrome and the Captcha was displayed, there were no issues.
Status: UNCONFIRMED → NEW
Component: Untriaged → ImageLib
Ever confirmed: true
OS: Unspecified → Windows 10
Product: Firefox → Core
Hardware: Unspecified → x86_64
See Also: → bug 1271433
Version: 47 Branch → Trunk
(Reporter)

Comment 4

2 years ago
> I have tested your issue on latest FF release (v48.0) and latest Nightly (v51.0a1) and managed to reproduce it. I have set a bandwidth limit using NetBalancer to 4KB/s and accessed http://myanimelist.net/register.php . In the Web Console->Network tab I can see that `styles_ltr.css` is 200 OK, but on the page the Captcha is not loading/is not displayed and sometimes a message is displayed which informs the user about the poor connection to the internet. 
The same steps were applied using Google Chrome and the Captcha was displayed, there were no issues.

YES! That is it!
Is there some kind of timeout in imagelib that would fail? Or is that something that belongs to another component, like network?
Flags: needinfo?(tnikkel)
Whiteboard: [gfx-noted]
The ReCAPTCHA looks to be an iframe, not an image, so I don't see why this would have anything to do with imagelib.
Component: ImageLib → Networking
Flags: needinfo?(tnikkel)
styles_ltr.css is served through h2.  Sounds like spdy/h2 problem.  Nick, can you take a look?
Assignee: nobody → hurley
Whiteboard: [gfx-noted] → [gfx-noted][necko-active]
Hrm, I'll take a look, but this doesn't sound on the face of it like a spdy/h2 problem - excepting request timeouts, we don't care how fast or slow the connection is (and to be clear, I tried to reproduce this already on an unshaped connection with no problems, so this obviously works fine on a fast connection).

I'm also unclear where the message about poor connection to the internet (comment 3) is coming from - I don't see those words anywhere in any of our error messages. I will try on a connection shaped down to 4K/s to see what happens.
So I'm apparently cursed - this is being added to that list of bugs I apparently can't reproduce (either win10 with NetBalancer, or on linux using tc to shape traffic). :VladB, if you can still reproduce, can you attach a screenshot of the "poor connection" error you got?

Note, I can get a bunch of stuff to time out when trying to load the myanimelist page mentioned above, things just time out before loading styles_ltr.css.
Flags: needinfo?(vlad.bacia)
Created attachment 8791503 [details]
recaptcha

Hi Nicholas, I have attached a screenshot with the message. This issue is still reproducible on latest Nightly (Build ID: 20160914030200).
Flags: needinfo?(vlad.bacia)
Thanks Vlad. So the error is a recaptcha error, but the 400 Bad Request in the log is interesting. I seem to remember some google bug a while back causing that kind of error on h2 connections, but I also think they fixed it a while ago.

I'll keep trying to repro on my end so we don't need the back and forth, but in the meantime, could I get you to reproduce with HTTP logging enabled (https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging) as well as a packet capture using wireshark, and an SSL Key Log (https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSS/Key_Log_Format). Looking at bug 1188657, it seems like you might need to reproduce on aurora to get the SSL Key Logging to work.

Thanks!
Flags: needinfo?(vlad.bacia)
I've talked with Nicholas in private and sent him some logs. Please let me know if there's anything else that I need to do.
Flags: needinfo?(vlad.bacia) → needinfo?(hurley)
Flags: needinfo?(hurley)

Comment 14

a year ago
Nick, any status here?
Priority: P1 → P2
Whiteboard: [gfx-noted][necko-active] → [gfx-noted]

Updated

a year ago
Flags: needinfo?(hurley)
I was never able to repro this myself, and given the lack of any mention earlier, I don't think I got anything from the logs, either.
Assignee: hurley → nobody
Flags: needinfo?(hurley)
Priority: P2 → P3

Comment 16

a year ago
Vlad: are you still seeing this?
Flags: needinfo?(vbacia.work)
Whiteboard: [gfx-noted] → [gfx-noted][necko-triaged]
Created attachment 8915955 [details]
reCAPTCHA issue

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:58.0) Gecko/20100101 Firefox/58.0
Build ID: 20171006100327

This issue is still reproducible on latest Firefox Release v56.0 and latest Nightly v58.0a1.
Flags: needinfo?(vbacia.work) → needinfo?(jduell.mcbugs)
For this scenario I have used the Network Link Conditioner app (http://nshipster.com/network-link-conditioner/) to simulate the low bandwidth on a Mac. In the app I have added a new profile that has 32 kbps => 4 kB/s and turn ON the switch. After that I have opened in a new tab the link provided in comment 2 and waited. The issue is still there.
Vlad, can you please provide logs according https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging ?  That may help us figure this out or narrow down at least.

None of us can reproduce it, it's then up to you.  Thank you!
Flags: needinfo?(BladeMight)

Comment 20

a year ago
Vlad, not sure Honza used the right email address to needinfo you?

As he said, we could really use an HTTP log that you start right before you open the new tab, and then stop after you've seen the error.  

  https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging
Flags: needinfo?(jduell.mcbugs) → needinfo?(vbacia.work)
Flags: needinfo?(vbacia.work) → needinfo?(ciprian.muresan)
Sorry it took me this much to respond.
Here (https://goo.gl/UDDSVr) is a link to the requested logs.

The issue is still reproducible on http://myanimelist.net/register.php using the latest Nightly 59.0a1 (Build ID 20171119220126) on Windows 10 x64 and Mac 10.12.6.
status-firefox57: --- → affected
status-firefox58: --- → affected
status-firefox59: --- → affected
Flags: needinfo?(ciprian.muresan) → needinfo?(honzab.moz)
OS: Windows 10 → All
The correct URL is: https://www.gstatic.com/recaptcha/api2/r20171115120512/styles__ltr.css

There are two requests made for this URL in the log.  Both are only partially cached but not resumable, hence we do a full (non-range) request.  This is all expected and working, but both the channels are from an unknown reason canceled in the middle of the load with NS_BINDING_ABORTED error from the child process side.

We need a child log as well.  Hence, please use the environment vars to setup logging [1].  Please use the following list of modules:

MOZ_LOG=timestamp,nsHttp:5,DocumentLeak:5,DocLoader:5,nsDocShellLeak:5,RequestContext:5,LoadGroup:5,nsChannelClassifier:5

If this takes too long to reproduce, you can limit the log size with adding rotate:500 to limit each process' log to 500MB.  Please zip or xzip the logs before uploading.  They will be much much smaller then.

Thanks!

[1] https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging#Logging_HTTP_activity_by_manually_setting_environment_variables
Flags: needinfo?(honzab.moz) → needinfo?(ciprian.muresan)
If I've set up the environment correctly, these should be the correct logs.
gstatic - https://goo.gl/ZopQWg
myanimelist - https://goo.gl/uiyhjD

gstatic.zip are the logs for when I've tried to reproduce the issue using https://www.gstatic.com/recaptcha/api2/r20171115120512/styles__ltr.css, but the whole page appears to load completely.

myanimelist.zip are the logs for the http://myanimelist.net/register.php site, where I still get the "please update to a captcha supported browser" message.

I haven't found any mention of NS_BINDING_ABORTED in any of those files.
Flags: needinfo?(ciprian.muresan) → needinfo?(honzab.moz)
(In reply to Ciprian Muresan [:cmuresan], Desktop Engineering QA from comment #23)
> If I've set up the environment correctly, these should be the correct logs.
> gstatic - https://goo.gl/ZopQWg
> myanimelist - https://goo.gl/uiyhjD

Thanks!

> 
> gstatic.zip are the logs for when I've tried to reproduce the issue using
> https://www.gstatic.com/recaptcha/api2/r20171115120512/styles__ltr.css, but
> the whole page appears to load completely.

I don't see anything wrong with the css in this set of logs.

> 
> myanimelist.zip are the logs for the http://myanimelist.net/register.php
> site, where I still get the "please update to a captcha supported browser"
> message.

Here a problem with only partially loaded css is manifested.  I can see we are trying to load the style in an iframe as a top level load (it has its own docshell).  Later during load progress the docloader (docshell) is being called Stop().

However, I don't fully understand how can this lead to "please update to a captcha supported browser" message.

This is how it starts:

2017-11-23 13:32:07.934 ⁃ nsDocShell ⁃ 171c780e800 ⁃ created ⁃ about:blank,https://www.gstatic.com/recaptcha/api2/r20171115120512/styles__ltr.css
2017-11-23 13:32:07.934000 UTC - [Main Thread]: D/nsDocShellLeak DOCSHELL 00000171C780E800 created
2017-11-23 13:32:07.934 ⁃ nsLoadGroup ⁃ 171cb60e000 ⁃ created ⁃ 1 ⁃ 1
2017-11-23 13:32:07.934000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Created.
2017-11-23 13:32:07.934000 UTC - [Main Thread]: D/DocLoader DocLoader:00000171C780E800: load group 00000171CB60E000.
nsDocShell @171c780e800 --> nsLoadGroup @171cb60e000
2017-11-23 13:32:07.979000 UTC - [Main Thread]: D/nsDocShellLeak DOCSHELL 00000171C780E800 SetCurrentURI about:blank
2017-11-23 13:32:07.980000 UTC - [Main Thread]: D/nsDocShellLeak nsDocShell[00000171C780E800]: loading about:blank with flags 0x00040000
2017-11-23 13:32:07.981000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Adding request 00000171C7669670 about:blank (count=0).
nsLoadGroup @171cb60e000 --> unknown request @171c7669670
2017-11-23 13:32:07.981000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Firing OnStartRequest for request 00000171C7669670.(foreground count=1).
2017-11-23 13:32:07.981000 UTC - [Main Thread]: D/LoadGroup nsLoadGroup::SetDefaultLoadRequest this=00000171CB60E000 default-request=00000171C7669670
nsLoadGroup @171cb60e000 --> unknown request @171c7669670
2017-11-23 13:32:07.986000 UTC - [Main Thread]: D/nsDocShellLeak nsDocShell[00000171C780E800]: loading https://www.gstatic.com/recaptcha/api2/r20171115120512/styles__ltr.css with flags 0x00000000
2017-11-23 13:32:07.986000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Adding request 00000171CB8900E0 about:document-onload-blocker (count=1).
nsLoadGroup @171cb60e000 --> unknown request @171cb8900e0
2017-11-23 13:32:07.986000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Firing OnStartRequest for request 00000171CB8900E0.(foreground count=2).
2017-11-23 13:32:07.986000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Canceling request 00000171CB8900E0 about:document-onload-blocker.
2017-11-23 13:32:07.986000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Removing request 00000171CB8900E0 about:document-onload-blocker status 804b0002 (count=1).
unknown request @171cb8900e0
2017-11-23 13:32:07.986000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Firing OnStopRequest for request 00000171CB8900E0.(foreground count=1).
2017-11-23 13:32:07.987000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Canceling request 00000171C7669670 about:blank.
2017-11-23 13:32:07.987000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Removing request 00000171C7669670 about:blank status 804b0002 (count=0).
unknown request @171c7669670
2017-11-23 13:32:07.987000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Firing OnStopRequest for request 00000171C7669670.(foreground count=0).
2017-11-23 13:32:07.987000 UTC - [Main Thread]: D/LoadGroup nsLoadGroup::SetDefaultLoadRequest this=00000171CB60E000 default-request=0000000000000000
nsLoadGroup @171cb60e000 --> unknown default request @0
2017-11-23 13:32:07.988 ⁃ HttpChannelChild ⁃ 171ca7f7000 ⁃ data ⁃ https://www.gstatic.com/recaptcha/api2/r20171115120512/styles__ltr.css ⁃ n/a
2017-11-23 13:32:07.988000 UTC - [Main Thread]: D/nsHttp Creating HttpChannelChild @00000171CA7F7000

This is what I can see at the end of the log:

2017-11-23 13:33:36.746000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnDataAvailable [this=00000260BD03E000 request=00000260BD015EB0 offset=75334 count=1401]
2017-11-23 13:33:36.746000 UTC - [Main Thread]: D/nsHttp sending progress and status notification [this=00000260BD03E000 status=804b0006 progress=76735/90700]
  804b0006 = STATUS_RECEIVING_FROM
2017-11-23 13:33:36.746000 UTC - [Main Thread]: D/nsHttp HttpChannelParent::OnStatus [this=00000260BCA45F60 status=804b0006]
2017-11-23 13:33:36.746000 UTC - [Main Thread]: D/nsHttp HttpChannelParent::OnStatus [this=00000260BCA45F60 progress=76735max=90700]
2017-11-23 13:33:36.746000 UTC - [Main Thread]: D/nsHttp HttpChannelParent::OnDataAvailable [this=00000260BCA45F60 aRequest=00000260BD03E048 offset=75334 count=1401]
2017-11-23 13:33:37.685000 UTC - [Main Thread]: D/nsHttp HttpChannelParent::RecvSetPriority [this=00000260BCA45F60, priority=-40]
2017-11-23 13:33:37.685000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::SetPriority 00000260BD03E000 p=-40
2017-11-23 13:33:37.685000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Canceling request 00000171CA7A8F80 about:document-onload-blocker.
2017-11-23 13:33:37.685000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Removing request 00000171CA7A8F80 about:document-onload-blocker status 804b0002 (count=1).
unknown request @171ca7a8f80
2017-11-23 13:33:37.685000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Firing OnStopRequest for request 00000171CA7A8F80.(foreground count=1).
2017-11-23 13:33:37.685000 UTC - [Main Thread]: D/LoadGroup LOADGROUP [00000171CB60E000]: Canceling request 00000171CA7F7070 https://www.gstatic.com/recaptcha/api2/r20171115120512/styles__ltr.css.
2017-11-23 13:33:37.687000 UTC - [Main Thread]: D/nsHttp HttpChannelParent::RecvCancel [this=00000260BCA45F60]
2017-11-23 13:33:37.687000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Cancel [this=00000260BD03E000 status=804b0002]
2017-11-23 13:33:37.687000 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnStopRequest [this=00000260BD03E000 request=00000260BD015EB0 status=804b0002]
2017-11-23 13:33:37.687000 UTC - [Main Thread]: D/nsHttp OnStopRequest 00000260BD03E000 requestFromCache: 0 mFirstResponseSource: 0
2017-11-23 13:33:37.687000 UTC - [Main Thread]: D/nsHttp nsHttpChannel 00000260BD03E000 has a strongly framed transaction: 0
2017-11-23 13:33:37.687000 UTC - [Main Thread]: D/nsHttp nsHttpChannel 00000260BD03E000 calling OnStopRequest
2017-11-23 13:33:37.687000 UTC - [Main Thread]: D/nsHttp HttpChannelParent::OnStopRequest: [this=00000260BCA45F60 aRequest=00000260BD03E048 status=804b0002]
2017-11-23 13:33:37.687000 UTC - [Main Thread]: D/nsHttp nsHttpChannel [this=00000260BD03E000] SetWarningReporter [0000000000000000]
2017-11-23 13:33:37.687000 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::RemoveAsNonTailRequest this=00000260BD03E000, rc=00000260BCFDA3A0, already added=1
RequestContext @260bcfda3a0
2017-11-23 13:33:37.699000 UTC - [Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=00000260BCA45F60 bgParent=00000260BC152D80]
2017-11-23 13:33:37.702000 UTC - [Main Thread]: D/nsHttp HttpChannelParent::OnBackgroundParentDestroyed [this=00000260BCA45F60]
2017-11-23 13:33:37.702000 UTC - [Main Thread]: D/nsHttp Destroying HttpChannelParent [this=00000260BCA45F60]
2017-11-23 13:33:37.702000 UTC - [Main Thread]: D/nsHttp nsHttpChannel [this=00000260BD03E000] SetWarningReporter [0000000000000000]
2017-11-23 13:33:37.751000 UTC - [Main Thread]: D/nsHttp Destroying nsHttpChannel [this=00000260BD03E000]


The interesting thing is the -40 prioritization that happens right before cancellation.  It could help finding the spot.


> 
> I haven't found any mention of NS_BINDING_ABORTED in any of those files.

It's a code I've translated to a name.
Flags: needinfo?(honzab.moz)
I completely missed one thing: it takes ~90s to get ~2/3 of the 90k content.  The h2 stream is: 

(https://goo.gl/uiyhjD)
Http2Stream @260bc1b2300 created 2017-11-23 13:32:13.881
className = Http2Stream
id = F
logid = 714
pointer = 260bc1b2300
state = released
status = 804B0002
upstreamstate = UPSTREAM_COMPLETE
url = https://www.gstatic.com/recaptcha/api2/r20171115120512/styles__ltr.css

Are we prioritizing wrong?  OTOH, it seems the stream is alone on the session.
Flags: needinfo?(hurley)
You need to log in before you can comment on or make changes to this bug.