Closed Bug 1713283 Opened 3 years ago Closed 3 years ago

400 Bad Request errors prevent internal website from loading

Categories

(Core :: Networking, defect, P3)

Product:
Core
Component:
Networking
Version:
Firefox 90
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
firefox-esr78 --- unaffected
firefox88 --- unaffected
firefox89 --- unaffected
firefox90 + fixed

People

(Reporter: Vash63, Unassigned)

References

(Regression)

Details

(Keywords: regression, Whiteboard: [necko-triaged])

Attachments

(1 file)

test-server-with-windows-auth.zip
215.66 KB, application/x-zip-compressed
Details

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:90.0) Gecko/20100101 Firefox/90.0

Steps to reproduce:

Apologies in advance for the lack of detail - the website in question is an internally used corporate website that I don't have permission to share details on. With the latest Firefox Nightly, build 20210527212801, this website will not load, giving an immediate 400 Bad Request error. This did not occur with the previous build I used, which was from May 25th I believe.

I have also verified that the page still loads correctly in Firefox 78.10.1esr, Google Chrome, and does not load in private window or after clearing cache/cookies in Nightly. It will not even load the 'favicon.ico' file or other static content.

Actual results:

The page loads "HTTP Error 400. The request is badly formed."

Expected results:

The page loads successfully.

The Bugbug bot thinks this bug should belong to the 'Core::Widget: Cocoa' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Component: Untriaged → Widget: Cocoa
Product: Firefox → Core

Can you test in safe mode or a fresh profile?

Or can you use mozregression to narrow down which changeset caused the issue? https://mozilla.github.io/mozregression/

Flags: needinfo?(Vash63)

Mozregression gave me:
8:57.65 INFO: No more integration revisions, bisection finished.
8:57.65 INFO: Last good revision: 6e12f7dbc39201a14ef3c9acd9635cf763e59860
8:57.65 INFO: First bad revision: d920aa17a468addd3233ee80dc0278c0e9562674
8:57.65 INFO: Pushlog:
https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=6e12f7dbc39201a14ef3c9acd9635cf763e59860&tochange=d920aa17a468addd3233ee80dc0278c0e9562674

Flags: needinfo?(Vash63)

Thanks.

Component: Widget: Cocoa → Networking
Flags: needinfo?(valentin.gosu)

3 bugs in that range, I'll pick bug 1705659 for the regressed by because it has the most patches, feel free to adjust.

Regressed by: 1705659
Has Regression Range: --- → yes
Status: UNCONFIRMED → NEW
Ever confirmed: true

Set release status flags based on info from the regressing bug 1705659

status-firefox88: --- → unaffected
status-firefox89: --- → unaffected
status-firefox90: --- → affected
status-firefox-esr78: --- → unaffected

[Tracking Requested - why for this release]:
could prevent accessing websites

tracking-firefox90: --- → ?

Thank you for the report. Could you record some HTTP logs using the instructions here?
https://firefox-source-docs.mozilla.org/networking/http/logging.html

If there is sensitive info in the logs feel free to email them instead of attaching them to the bug.

Flags: needinfo?(valentin.gosu) → needinfo?(Vash63)

I am hitting this as well for internal applications that use Windows Authentication.

I was able to reproduce this using a simple application in IIS for which I then activated Windows Authentication. After that, every attempt to access the site results in a Bad Request. In the server logs, these requests only appear as 401 with the substatus 2. According to the error files, this would be the error:

401.2 - Unauthorized: Access is denied due to server configuration.
You do not have permission to view this directory or page using the credentials that you supplied because your Web browser is sending a WWW-Authenticate header field that the Web server is not configured to accept.

Using a sample ASP.NET Core application that uses Windows Authentication without relying on IIS (or IIS Express), I was able to get some more logs on the connection attempt:

dbug: Microsoft.AspNetCore.Server.Kestrel[39]
      Connection id "0HM943RUSKEMA" accepted.
dbug: Microsoft.AspNetCore.Server.Kestrel[1]
      Connection id "0HM943RUSKEMA" started.
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://localhost:5000/ - -
dbug: Microsoft.AspNetCore.Authentication.Negotiate.NegotiateHandler[9]
      AuthenticationScheme: Negotiate was not authenticated.
dbug: Microsoft.AspNetCore.Authentication.Negotiate.NegotiateHandler[6]
      Challenged 401 Negotiate.
info: Microsoft.AspNetCore.Authentication.Negotiate.NegotiateHandler[12]
      AuthenticationScheme: Negotiate was challenged.
dbug: Microsoft.AspNetCore.Server.Kestrel[9]
      Connection id "0HM943RUSKEMA" completed keep alive response.
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET http://localhost:5000/ - - - 401 0 - 0.4862ms
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[6]
      Connection id "0HM943RUSKEMA" received FIN.
dbug: Microsoft.AspNetCore.Server.Kestrel[10]
      Connection id "0HM943RUSKEMA" disconnecting.
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
      Connection id "0HM943RUSKEMA" sending FIN because: "The client closed the connection."
dbug: Microsoft.AspNetCore.Server.Kestrel[2]
      Connection id "0HM943RUSKEMA" stopped.

As for the Firefox logs, here is an excerpt from the logs after it has hit the error 401, requesting a Negotiate authentication:

V/nsHttp nsHttpChannel::OnStartRequest [this=1e26c49b000 request=1e26e5c7b80 status=0]
V/nsHttp nsHttpChannel::ProcessResponse [this=1e26c49b000 httpStatus=401]
D/nsHttp nsHttpHandler::NotifyObservers [chan=1e26c49b040 event="http-on-examine-response"]
V/nsHttp HttpBaseChannel::HasCrossOriginOpenerPolicyMismatch - doc:0 result:0 - compare:1
V/nsHttp doc origin:http://localhost:5000/ - res origin: http://localhost:5000/
V/nsHttp nsHttpChannel::ContinueProcessResponse3 [this=1e26c49b000, rv=804b0001]
D/nsHttp nsHttpChannelAuthProvider::ProcessAuthentication [this=1e26ebe0ee0 channel=1e26c49b750 code=401 SSLConnectFailed=0]
D/nsHttp nsHttpChannelAuthProvider::PrepareForAuthentication [this=1e26ebe0ee0 channel=1e26c49b750]
D/nsHttp   proxy continuation state has been reset
D/nsHttp nsHttpChannelAuthProvider::GetAuthenticator [this=1e26ebe0ee0 channel=1e26c49b750]
D/nsHttp nsHttpChannelAuthProvider::GetCredentialsForChallenge [this=1e26ebe0ee0 channel=1e26c49b750 proxyAuth=0 challenges=Negotiate]
D/nsHttp nsHttpChannelAuthProvider::GetIdentityFromURI [this=1e26ebe0ee0 channel=1e26c49b750]
V/nsHttp nsHttpAuthCache::GetAuthEntryForDomain 1e257fb4078 [realm=]
V/nsHttp nsHttpAuthCache::LookupAuthNode 1e257fb4078 key='^privateBrowsingId=1&partitionKey=%28http%2Clocalhost%2C5000%29:http://localhost:5000' found node=0
D/nsHttp unable to authenticate
V/nsHttp ProcessAuthentication failed [rv=80004004]
D/nsHttp nsHttpChannelAuthProvider::CheckForSuperfluousAuth? [this=1e26ebe0ee0 channel=1e26c49b750]
V/nsHttp nsHttpChannel::ProcessNormal [this=1e26c49b000]
V/nsHttp nsHttpChannel::ContinueProcessNormal [this=1e26c49b000]
V/nsHttp nsHttpChannel::InitCacheEntry [this=1e26c49b000 entry=1e264e84e60]
V/nsHttp nsHttpResponseHead::MustValidate ??
V/nsHttp Must validate since response is an uncacheable error page
V/nsHttp nsHttpChannel::AddCacheEntryHeaders [this=1e26c49b000] begin
V/nsHttp nsHttpChannel::CallOnStartRequest [this=1e26c49b000]
V/nsHttp   calling mListener->OnStartRequest [this=1e26c49b000, listener=1e26e581280]
V/nsHttp Preparing to write data into the cache [uri=http://localhost:5000/]
V/nsHttp Trading cache input stream for output stream [channel=1e26c49b000]
V/nsHttp nsHttpChannel::InstallCacheListener sync tee 1e26ec29a10 rv=0
V/nsHttp nsHttpChannel::OnStopRequest [this=1e26c49b000 request=1e26e5c7b80 status=0]
V/nsHttp OnStopRequest 1e26c49b000 requestFromCache: 0 mFirstResponseSource: 0
V/nsHttp nsHttpChannel 1e26c49b000 has a strongly framed transaction: 1
V/nsHttp Init nsHttpConnectionInfo @1e2734b83e0
V/nsHttp   transaction 1e26ea14010 has sticky connection
V/nsHttp   mAuthRetryPending=0, status=0, sticky conn cap=0
V/nsHttp nsHttpChannel::ContinueOnStopRequestAfterAuthRetry [this=1e26c49b000, aStatus=0 aAuthRetry=0, aIsFromNet=1, aTransWithStickyConn=1e26ea14010]
V/nsHttp nsHttpChannel::ContinueOnStopRequest [this=1e26c49b000 aStatus=0, aIsFromNet=1]
V/nsHttp   nsHttpChannel::OnStopRequest ChannelDisposition 2
V/nsHttp nsHttpChannel::FinalizeCacheEntry [this=1e26c49b000]
V/nsHttp nsHttpChannel::FinalizeCacheEntry [this=1e26c49b000] Is Strongly Framed
V/nsHttp nsHttpChannel 1e26c49b000 calling OnStopRequest

Note the “unable to authenticate” in line 15. If you need more than that, I can also prepare a separate test profile and provide a full log. But scrolling through the one I generated, there didn’t appear to be a lot of useful stuff. For some reason, the displayed 400 response code did not appear in the logs.

If you want, I can also provide a simple example web server application that you should be able to run locally to reproduce this (as long as you are on Windows, Windows Authentication should work out of the box).

Thanks Patrick,

Note the “unable to authenticate” in line 15. If you need more than that, I can also prepare a separate test profile and provide a full log. But scrolling through the one I generated, there didn’t appear to be a lot of useful stuff. For some reason, the displayed 400 response code did not appear in the logs.

I am more curious about the WWW-Authenticate challenges sent by the server.

If you want, I can also provide a simple example web server application that you should be able to run locally to reproduce this (as long as you are on Windows, Windows Authentication should work out of the box).

That would be great! Thanks!

I emailed some logs that hopefully have what you need.

Flags: needinfo?(Vash63)

Thank you.
So, the server sends both Negotiate and NTLM challenges.

2021-05-31 10:53:56.598823 UTC - [Parent 39532: Socket Thread]: E/nsHttp nsHttpTransaction::ParseLine [WWW-Authenticate: Negotiate]
2021-05-31 10:53:56.598835 UTC - [Parent 39532: Socket Thread]: E/nsHttp nsHttpTransaction::ParseLine [WWW-Authenticate: NTLM]

It should attempt to authenticate with Negotiate first, but I think the reordering in bug 1705659 is making us process NTLM first, and it fails.
I'll turn this into a unit test.

Sample ASP.NET Core server application with Windows Authentication (Negotiate). Requires a .NET 5.0 runtime to run. Run test.exe and then navigate to http://localhost:5000 to test it out.

(In reply to Valentin Gosu [:valentin] (he/him) from comment #10)

I am more curious about the WWW-Authenticate challenges sent by the server.

In my case, I only get a single Negotiate header. The logs show the following there:

V/nsHttp nsHttpResponseHead::ParseVersion [version=HTTP/1.1 401 Unauthorized]
E/nsHttp Have status line [version=11 status=401 statusText=Unauthorized]
E/nsHttp nsHttpTransaction::ParseLine [Date: Mon, 31 May 2021 13:57:30 GMT]
E/nsHttp nsHttpTransaction::ParseLine [Server: Kestrel]
E/nsHttp nsHttpTransaction::ParseLine [Content-Length: 0]
E/nsHttp nsHttpTransaction::ParseLine [WWW-Authenticate: Negotiate]
V/nsHttp nsHttpTransaction::HandleContent [this=1e6d72a0000 count=0]
V/nsHttp nsHttpTransaction::HandleContentStart [this=1e6d72a0000]
I/nsHttp http response [
E/nsHttp   HTTP/1.1 401 Unauthorized
E/nsHttp   Date: Mon, 31 May 2021 13:57:30 GMT
E/nsHttp   Server: Kestrel
E/nsHttp   Content-Length: 0
E/nsHttp   WWW-Authenticate: Negotiate
E/nsHttp     OriginalHeaders
E/nsHttp   Date: Mon, 31 May 2021 13:57:30 GMT
E/nsHttp   Server: Kestrel
E/nsHttp   Content-Length: 0
E/nsHttp   WWW-Authenticate: Negotiate
I/nsHttp ]

If you want, I can also provide a simple example web server application that you should be able to run locally to reproduce this (as long as you are on Windows, Windows Authentication should work out of the box).

That would be great! Thanks!

I’ve attached a simple ASP.NET Core application which you can use to replicate this problem. You will need a .NET 5.0 runtime to run this though.

Attachment #9224327 - Attachment mime type: application/octet-stream → application/x-zip-compressed
Severity: -- → S3
Priority: -- → P3
Whiteboard: [necko-triaged]

I can no longer duplicate this on build 20210601213358

Possibly related but the initial connection to the internal site used to hang for a few seconds, that seems to be gone also and it is much faster than before

Fixed by the backout of bug 1705659.
I'll get back to you when I fix the issue and reland.
Thanks for reporting!

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED

(In reply to Valentin Gosu [:valentin] (he/him) from comment #19)

I have a new build here: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/b4Fo3t2WSOCwzcuc1yv69w/runs/0/artifacts/public/build/target.dmg

https://treeherder.mozilla.org/jobs?repo=try&revision=06bbb55152e074e86884cb6d6aa0720566c31069&selectedTaskRun=b4Fo3t2WSOCwzcuc1yv69w.0

Could you check if this one works or not? Thanks!

Nope, this build still gives me the 400 error

Flags: needinfo?(Vash63)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: