1411515 - When sending a POST with array data over http and SSL via a Proxy, The connection gets terminated by Firefox

Status: RESOLVED INCOMPLETE

(Core :: Layout: Form Controls, defect, P3)

Description

[Pascal Fleer]

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

Steps to reproduce:

When connecting from Firefox to an internal web server via a Proxy, a POST Request blocks Firefox.

Firefox 56 (but also Firefox 52 ESR or Firefox Firefox 45 ESR) connects to the web server https://xclc.viennaairport.com/ via a Squid Proxy server. In one of the business processes, a POST is sent to the web server via a squid proxy server.  

As the website is partly internal, reproduction by a Firefox developper is difficult. But we are willing to allow remote access. 


Actual results:

In the trace with have POST with following content (out of wireshark): 
HTML Form URL Encoded: application/x-www-form-urlencoded
    Form item: "flightOid" = "2137525"
    Form item: "flightNumber" = "OS806"
    Form item: "method" = "applyRA"
    Form item: "currentPantryCode" = "*C"
    Form item: "pantryOid" = "70420"
    Form item: "oldCrewCockpit" = "2"
    Form item: "oldCrewCabin" = "3"
    Form item: "crewCockpit" = "2"
    Form item: "crewCabin" = "3"
    Form item: "xcrPerClass[1]" = ""
    Form item: "xcrPerClass[2]" = ""
    Form item: "xcrPerSection[0]" = ""
    Form item: "xcrPerSection[1]" = ""
    Form item: "xcrPerSection[2]" = ""
    Form item: "xcrPerSection[3]" = ""
    Form item: "oldFlightTimeEstimatedString" = ""
    Form item: "flightTimeEstimatedString" = ""
    Form item: "oldFlightTimeMaxString" = ""
    Form item: "flightTimeMaxString" = ""
    Form item: "oldAlternateAirportCode" = ""
    Form item: "alternateAirportCode" = ""
    Form item: "oldCaptainName" = ""
    Form item: "captainName" = ""
    Form item: "maxZeroFuelWeight" = ""
    Form item: "maxTakeoffWeight" = ""
    Form item: "maxLandingWeight" = ""
    Form item: "airlinePhoneNumber" = "[phone]"
    Form item: "supervisorPhoneNumber" = ""
    Form item: "oldTaxiFuel" = "120"
    Form item: "taxiFuel" = "120"
    Form item: "oldTripFuel" = ""
    Form item: "tripFuel" = ""
    Form item: "oldTakeoffFuel" = ""
    Form item: "takeoffFuel" = "1000"
    Form item: "editableCrewMembers.line[0].oid" = ""
    Form item: "editableCrewMembers.line[0].name" = ""
    Form item: "editableCrewMembers.line[0].function" = ""
    Form item: "editableCrewMembers.line[1].oid" = ""
    Form item: "editableCrewMembers.line[1].name" = ""
    Form item: "editableCrewMembers.line[1].function" = ""
    Form item: "editableCrewMembers.line[2].oid" = ""
    Form item: "editableCrewMembers.line[2].name" = ""
    Form item: "editableCrewMembers.line[2].function" = ""
    Form item: "editableCrewMembers.line[3].oid" = ""
    Form item: "editableCrewMembers.line[3].name" = ""
    Form item: "editableCrewMembers.line[3].function" = ""
    Form item: "editableCrewMembers.line[4].oid" = ""
    Form item: "editableCrewMembers.line[4].name" = ""
    Form item: "editableCrewMembers.line[4].function" = ""

The connection is terminated by Firefox (wireshark trace):
8944	2017-10-25 09:14:06.552130	WS673560-LHSYS.lic.fra.dlh.de	prx-fracute-integ01.inet.cns.fra.dlh.de	HTTP	575	POST /MACHwbclc/load/basicFlightData.vie HTTP/1.1  (application/x-www-form-urlencoded)
8945	2017-10-25 09:14:06.553717	prx-fracute-integ01.inet.cns.fra.dlh.de	WS673560-LHSYS.lic.fra.dlh.de	TCP	60	8080 → 65231 [ACK] Seq=233450 Ack=23786 Win=84224 Len=0
9137	2017-10-25 09:14:08.315083	prx-fracute-integ01.inet.cns.fra.dlh.de	WS673560-LHSYS.lic.fra.dlh.de	TCP	60	8080 → 65232 [FIN, ACK] Seq=1416 Ack=1662 Win=32768 Len=0
9138	2017-10-25 09:14:08.315172	WS673560-LHSYS.lic.fra.dlh.de	prx-fracute-integ01.inet.cns.fra.dlh.de	TCP	54	65232 → 8080 [ACK] Seq=1662 Ack=1417 Win=65280 Len=0
9140	2017-10-25 09:14:08.315480	WS673560-LHSYS.lic.fra.dlh.de	prx-fracute-integ01.inet.cns.fra.dlh.de	TLSv1.2	107	Alert (Level: Warning, Description: Close Notify)
9141	2017-10-25 09:14:08.315561	WS673560-LHSYS.lic.fra.dlh.de	prx-fracute-integ01.inet.cns.fra.dlh.de	TCP	54	65232 → 8080 [FIN, ACK] Seq=1715 Ack=1417 Win=65280 Len=0
9142	2017-10-25 09:14:08.317229	prx-fracute-integ01.inet.cns.fra.dlh.de	WS673560-LHSYS.lic.fra.dlh.de	TCP	60	8080 → 65232 [RST] Seq=1417 Win=0 Len=0
9143	2017-10-25 09:14:08.317230	prx-fracute-integ01.inet.cns.fra.dlh.de	WS673560-LHSYS.lic.fra.dlh.de	TCP	60	8080 → 65232 [RST] Seq=1417 Win=0 Len=0

See the attached log file at line 
2017-10-25 07:56:55.333000 UTC - [Main Thread]: I/nsHttp   POST /MACHwbclc/load/basicFlightData.vie HTTP/1.1

If desired, additionnal logs with different options can be generated.
Active logging settings: SET MOZ_LOG=timestamp,sync,rotate:200,nsHttp:5,nsSocketTransport:5,nsStreamPump:5,nsHostResolver:5




Expected results:

Firefox should not terminate the connection. At the moment, the web site hangs.

A workaround has been implemented for Firefox. Other browsers (Chrome, Edge) do not have this symptom

Comment 1

[Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz)]

Hi Pascal, it sounds like you already capture a MOZ_LOG from your bug description. Can you help upload it to bugzilla so that we can do the first hand analysis? Thanks!

Comment 2

[Pascal Fleer]

Attachment: MOZ_LOG.zip

Hello,
This is the MOZ_LOG zipped as requested.
Cheers, Pascal

Comment 3

[Dragana Damjanovic [:dragana]]

In the log I see that something is canceling the http channel:

2017-10-26 07:35:57.214000 UTC - [Main Thread]: D/nsHttp HttpChannelChild::Cancel [this=000001AE730EC000]

 do not know that is canceling it, it is out of necko so it is not captured by this log.

Can you tell me how this request is made? is it a form, xhr?

Comment 4

[Pascal Fleer]

Hello,

As I have full control of the logging options and can recreate the issue at will, could suggest additionnal flags for logging?

At the moment I start tracing and logging as follows:

REM SSL Key Capture for wireshark decoding
SET SSLKEYLOGFILE=.\SSLKEY.LOG

REM NSPR logging options and location
SET NSPR_LOG_MODULES=timestamp,sync,all:5
SET NSPR_LOG_FILE=.\NSPRLOGFILE.TXT

REM MOZLOG logging options and location
SET MOZ_LOG=timestamp,sync,rotate:200,nsHttp:5,nsSocketTransport:5,nsStreamPump:5,nsHostResolver:5
SET MOZ_LOG_FILE=.\MOZLOGFILE.TXT

REM Start options - no remote for distinct setup, show console, 
"C:\Program Files (x86)\Mozilla Firefox\firefox.exe" -no-remote -console -profile "D:\DATA\cfdev\CF\FIREFOX\PROFILE" https://xclc.viennaairport.com/

As for the procedure:
A bit of background : The web application is a aircraft load control application, with a business process "fuel and crew".
A mask with entry fields collects information from the operator, and the operator pushes a button which triggers the http POST due to the use of a HTML Form.

Out of the integrated debugger I copied the following data:

---- Request Header ---- : 
Host	
xclc.viennaairport.com
User-Agent	
Mozilla/5.0 (Windows NT 10.0; …) Gecko/20100101 Firefox/56.0
Accept	
text/html,application/xhtml+xm…plication/xml;q=0.9,*/*;q=0.8
Accept-Language	
en-US,en;q=0.5
Accept-Encoding	
gzip, deflate, br
Referer	
https://xclc.viennaairport.com…ghtData.vie?flightOid=2142402
Content-Type	
application/x-www-form-urlencoded
Content-Length	
1234
Cookie	
JSESSIONID=B293882E6973B4C19CA…D1311A7B41DCFF86E808FD29E0C43
Connection	
keep-alive
Upgrade-Insecure-Requests	
1
----------------

---- Params ---- :
flightOid=2142402
flightNumber=OS800
method=applyRA
currentPantryCode=*C
pantryOid=70420
oldCrewCockpit=2
oldCrewCabin=3
crewCockpit=2
crewCabin=3
xcrPerClass[1]
xcrPerClass[2]
xcrPerSection[0]
xcrPerSection[1]
xcrPerSection[2]
xcrPerSection[3]
oldFlightTimeEstimatedString
flightTimeEstimatedString
oldFlightTimeMaxString
flightTimeMaxString
oldAlternateAirportCode
alternateAirportCode
oldCaptainName
captainName
maxZeroFuelWeight
maxTakeoffWeight
maxLandingWeight
airlinePhoneNumber=00431700724365
supervisorPhoneNumber
oldTaxiFuel=120
taxiFuel=120
oldTripFuel
tripFuel
oldTakeoffFuel
takeoffFuel=1000
editableCrewMembers.line[0].oid
editableCrewMembers.line[0].name
editableCrewMembers.line[0].function
editableCrewMembers.line[1].oid
editableCrewMembers.line[1].name
editableCrewMembers.line[1].function
editableCrewMembers.line[2].oid
editableCrewMembers.line[2].name
editableCrewMembers.line[2].function
editableCrewMembers.line[3].oid
editableCrewMembers.line[3].name
editableCrewMembers.line[3].function
editableCrewMembers.line[4].oid
editableCrewMembers.line[4].name
editableCrewMembers.line[4].function
----------------

the POST is initiated directly by Firefox due to the HTML Form.

When the web application developer takes out the array elements of the POST, the POST works. But he doesn't want to change his code at the moment due to the argument that the other browsers (Edge, Chrome) work. 

This situation only happens in conjunction with a Proxy. If the proxy is left out of the communication chain, Firefox works as charm.

If you need to access my test setup, I can provide access through a remote access (teamviewer for example)

Comment 5

[Pascal Fleer]

Additionnal information: 
The issues exists also with the 45ESR branch and the 52ESR branch.
Cheers, Pascal

Comment 6

[Dragana Damjanovic [:dragana]]

Can you make a http log without proxy as well?

From log I have seen that something on the page is canceling the load. I do not see that the TCP connection is failing. I do not know how the behavior is different with or without proxy.

A remote access would be good.

Comment 7

[Dragana Damjanovic [:dragana]]

Daniel, you have looked at the proxy code recently. Do you know why the proxy makes a difference here? Can you look at the code.

Comment 8

[Pascal Fleer]

Attachment: MOZ LOG for connection without proxy, where the post is successfull

As requested by Dragana

Comment 9

[Pascal Fleer]

Additionnal Information:

When reducing the size of the POST payload, for example:
---- Params ---- :
flightOid=2142402
flightNumber=OS800
method=applyRA
currentPantryCode=*C
pantryOid=70420
oldCrewCockpit=2
oldCrewCabin=3
crewCockpit=2
crewCabin=3
airlinePhoneNumber=00431700724365
oldTaxiFuel=120
taxiFuel=120
takeoffFuel=1000
----------------

The POST goes through. But this workaround implies to rework the html form and replace it with a XHR based request. 

And I would renew my offer for a remote session where I make the system available for testing.

Comment 10

[Pascal Fleer]

I redid the test with the newest Firefox 57.0 and Firefox 52.3.0esr - (no surprise) the issue persists.

Comment 11

[Dragana Damjanovic [:dragana]]

Can you setup a remote access?

Comment 12

[Pascal Fleer]

(In reply to Dragana Damjanovic [:dragana] from comment #11)
> Can you setup a remote access?

Yes I can. Is using teamviewer as software (https://www.teamviewer.com/) Ok with you? If yes, I would setup a virtual machine with a fresh install of Windows and Firefox. I would then assist you with the access to the application.

What would be the preferred time? Which time zone are you?

Comment 13

[Dragana Damjanovic [:dragana]]

Actually thinking of it , my comment #3 suggested that the channel is canceled from outside necko. I head another look and I think this is not a networking problem.

It would be better that someone from the Form team take a look at this.

Comment 14

[Pascal Fleer]

(In reply to Dragana Damjanovic [:dragana] from comment #13)
> Actually thinking of it , my comment #3 suggested that the channel is
> canceled from outside necko. I head another look and I think this is not a
> networking problem.
> 
> It would be better that someone from the Form team take a look at this.

Remote access setup is ready. The test can be done with either FF 52.5.0esr as well as FF 57.0
Due to confidentiality, I would not post the access details here. How should we proceed?

Comment 15

[Jet Villegas (inactive)]

(In reply to Dragana Damjanovic [:dragana] from comment #13)
> Actually thinking of it , my comment #3 suggested that the channel is
> canceled from outside necko. I head another look and I think this is not a
> networking problem.
> 
> It would be better that someone from the Form team take a look at this.

Jonathan: can you have a look and see if we close channels from within Form Layout? I don't know of any proxy-dependent behavior in our rendering code. Perhaps this proxy cancels connections that match these parameters? Thx!

Comment 16

[Jonathan Watt [:jwatt]]

(In reply to Pascal Fleer from comment #4)
> When the web application developer takes out the array elements of the POST,
> the POST works.

That's weird.

If I created a custom build with some extra logging would you still be able to run it?

Comment 17

[Pascal Fleer]

(In reply to Jonathan Watt [:jwatt] from comment #16)
> (In reply to Pascal Fleer from comment #4)
> > When the web application developer takes out the array elements of the POST,
> > the POST works.
> 
> That's weird.
> 
> If I created a custom build with some extra logging would you still be able
> to run it?

Hello Jonathan,

yes, we can try that. Although i would have to recreate a test web site. 

The developer of the page has since then rewritten the web application. 

Would you send me a download link?

Pascal

Comment 18

[Jonathan Watt [:jwatt]]

It appears that Try no longer supports editing the in-tree mozconfig files. Waiting on a resolution to bug 1509354.

Comment 19

[Jonathan Watt [:jwatt]]

I've created a debug build. It will run a lot slower than the non-debug-but-with-symbols build I was trying to create, but maybe it will work. The patch just dumps out a stack trace whenever HttpChannelChild::Cancel() is called so that we get an idea of why the request is being cancelled:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=74d189dd81b9b059cb9f65dff51949d6bdb2b435

The .zip containing the build is here:

https://queue.taskcluster.net/v1/task/VrsyFX_yRX2yq1LZ1ZrIxA/runs/0/artifacts/public/build/target.zip

Comment 20

[Honza Bambas (:mayhemer)]

If the caller is a JS script you can get that information from an http log: https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging, Cancel() on parent and child both log the calling script, if there is one.

Comment 21

[Jonathan Watt [:jwatt]]

(In reply to Honza Bambas (:mayhemer) from comment #20)
> If the caller is a JS script you can get that information from an http log:
> https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging,
> Cancel() on parent and child both log the calling script, if there is one.

Thanks. I believe that was already enabled for the logs that were previously provided and so it seems Cancel is being called from C++ code.

Comment 22

[Jonathan Watt [:jwatt]]

I don't appear to have mentioned this before, but I did previously set up a local server to serve a PAC file and made application/x-www-form-urlencoded posts through a proxy. I retested over the weekend with form data that contains an array. I wasn't able to reproduce either time.

Comment 23

[Jonathan Watt [:jwatt]]

Pascal, any luck trying the debug build?

Comment 24

[Jonathan Watt [:jwatt]]

Actually, it sounds from the comments in bug 1509354 like you should be able to use the Release build:

https://queue.taskcluster.net/v1/task/F1KrfP2oTkG-f3zr1-dRsw/runs/0/artifacts/public/build/target.zip

Comment 25

[Pascal Fleer]

(In reply to Jonathan Watt [:jwatt] from comment #23)
> Pascal, any luck trying the debug build?

Hi Jonathan, 
I have to recreate the situation with the proxy, as the operator of the server that produced the error has switched to another framework that produces less data, and doesn't trigger anymore the bug. 

I will retest the situation with the old ESR, to confirm that the bug is there, the build that you provided me, and then the release build. 

stay tuned. 

Pascal

Comment 26

[Jonathan Watt [:jwatt]]

Attachment: WIP: Bug 1411515 - Some debug logging

Comment 27

[Jonathan Watt [:jwatt]]

The patch I attached in comment 26 is just to provide a record of the logging I added to the custom build that I provided to the reporter.