Can't upload file

[ccallendar]

Hi, We upgraded BonCode from 1.0.36 to 1.0.40, and now we can no longer upload files from a web form to Lucee (v5.1.3.18) backend. I've also tried with 1.0.37, 38, and 39 and same problem.

If I upload straight through tomcat then it works, but with IIS+BonCode it fails, eventually hitting the lucee request timeout (50 seconds). I tried making the Lucee request timeout longer (3 minutes) and the uploads will work most of the time, but they take a very long time (~2 minutes for a 5 MB file on my computer going to local server).

The weird part is if I set my BonCode LogLevel up to 3 or 4, then the uploads work! And are very fast (~ 5 seconds).

My tomcat/lucee server.xml file has this line: <Connector port="8009" protocol="AJP/1.3" redirectPort="8443" maxThreads="500" keepAliveTimeout="-1" connectionTimeout="121000" packetSize="65536" /> My IIS app pool Idle timeout is 2 minutes.

And my BonCodeAJP13.settings file is this:

<Settings>
  <Port>8009</Port>
  <Server>localhost</Server>   
  <MaxConnections>500</MaxConnections>
  <PacketSize>65536</PacketSize>
  <LogLevel>2</LogLevel>
  <LogDir>c:\Temp\BonCodeLogs</LogDir>
  <EnableRemoteAdmin>False</EnableRemoteAdmin>
  <EnableHeaderDataSupport>True</EnableHeaderDataSupport>
  <ForceSecureSession>False</ForceSecureSession>
  <AllowEmptyHeaders>True</AllowEmptyHeaders>
  <FlushThresholdTicks>50000</FlushThresholdTicks>
</Settings>

Thanks!

[Bilal-S]

Chris, is there a min test case that you can share? Or does this happen with any upload (sending from browser to tomcat)? If we were to create page A: render HTML and allow a file for upload to page B and page B: target for upload (form post)

Will that do?

Best, Bilal

[ccallendar]

Thanks for the reply!

I just discovered something else too. I cloned your repo, and did a diff between versions 1.0.36 and 37, and the first thing I noticed was your custom BonCodeAJP13ServerConnection.ReadStream method.

I put in some logging and sure enough - the Thread.Sleep(300) line is getting called a lot because p_NetworkStream.DataAvailable is false. From what I saw it looks like every other call of ReadStream this happens, so the upload ends up taking a really long time. As a test I simply removed that DataAvailable check from the if statement, rebuilt, and sure enough my uploads took a few seconds instead of minutes.

Anyway, I can try and get a small test case together if it would still help?

[ccallendar]

Okay here is my really simple upload form:

<cfoutput>
<h2>BonCode Upload Test</h2>
<script type="text/javascript">
function beforeSubmit() {
    document.getElementById("startTime").value = new Date().getTime();
    document.getElementById("startTimeDisplay").innerHTML = new Date().toTimeString();
}
</script>
<form action="bonCodeAcceptUpload.cfm" method="post" enctype="multipart/form-data" target="output" onsubmit="beforeSubmit(); return true;">
    <input type="hidden" id="startTime" name="startTime" value="0"/>
    <input type="file" id="Filedata" name="Filedata" value=""><br><br>
    <input type="submit">
</form><br><br>
Start time: <span id="startTimeDisplay"></span><br><br>
<iframe name="output" id="output" style="width: 800px; height: 400px;"></iframe>
</cfoutput>

Accept page (bonCodeAcceptUpload.cfm):

<cfset startTime = val(form.startTime) />
<cfset uploadFile = { "serverFile" = "", "serverDirectory" = "", "fileSize" = "" } />
<cfset msg = "" />
<cfset fileSize = "" />
<cfset fileOk = false />
<cftry>
    <cffile action="upload" filefield="Filedata" destination="C:\Temp\UploadDir" nameconflict="makeunique" accept="" result="uploadFile" />
    <cfset file = uploadFile.serverDirectory & "\" & uploadFile.serverFile />
    <cfset fileOk = fileExists(file) />
    <cfif fileOk>
        <cfset fileSize = decimalFormat(getFileInfo(file).size / 1048576) & " MB" />
        <cfset fileDelete(file) />
    </cfif>
<cfcatch>
    <cfset msg = cfcatch.message />
</cfcatch>
</cftry>

<cfoutput>
    Success:  #fileOk#<br>
    Message:  #msg#<br>
    End time: #dateTimeFormat(now(), 'HH:nn:ss')#<br>
    Upload time: #decimalFormat((getTickCount() - startTime) / 1000)# seconds<br>
    File exists: #fileOk#<br>
    File size: #fileSize#<br>
</cfoutput>

Hope that helps. On my local server I see these kind of upload times (with v1.0.37): 1.5 MB in 7.5 seconds 3.4 MB in 15.6 seconds 5.5 MB in 25 seconds 10.4 MB in 44 seconds

Where as with v1.0.36 I see 1 second for the 10.4 MB upload.

[Bilal-S]

Chris, thanks for the extra insight. I will revisit the read pausing. We were previously running into issues at times where we would throw errors because we processed faster than network pipe could supply data. I will use your test case to check. Best, Bilal

[ccallendar]

You're welcome, thanks for looking into it!

Based on what I saw, I'm guessing that by simply changing the LogLevel to 4 was enough to slow it down so that DataAvailable was mostly true. So it rarely needed to sleep for the 300ms. Perhaps a shorter sleep time would be a good compromise? Anyway, I look forward to hearing if you can reproduce it. A colleague of mine was able to reproduce it with the same Lucee (5.1.3.18), BonCode (1.0.37), and IIS (10) versions.

[Bilal-S]

Thanks for the sample code. I have replicated the issue and made the changes to resolve it. https://github.com/Bilal-S/iis2tomcat/releases/tag/1.0.41

Best, Bilal

[ccallendar]

Works perfectly, thanks so much for fixing this issue so quickly!

[Bilal-S]

👍