http://coldfusion.com logo
Join Slack
Powered by
I'm having a weird issue between Lucee and Tomcat ...
# lucee
d
I'm having a weird issue between Lucee and Tomcat that I'm trying to debug and I'm a little stuck. I'm having an issue where when Lucee hits its Request Timeout setting on a page and it happens during a JDBC, Tomcat is not getting back the Lucee error page but instead it's returning no response (or "Connection closed by foreign host" when debugging via telnet). Everything works fine as long as the timeout isn't during a JDBC connection. When I try the same code via CommandBox, Undertow returns the expected Lucee error page. So the problem appears to be in the Tomcat configuration. In looking at the catalina.out logs, the output is basically the same as what I'm seeing in the CommandBox Undertow logs. None of the other Tomcat logs are showing anything of interest. Any tips on where I should be looking? Why would Tomcat behavior differently depending on how the Lucee Request Timeout is triggered?
z
d
So I did just discover a difference. I have 2 test scripts, the first one looks like this:
Copy code
<cfsetting requesttimeout="5" />

<cfloop index="idx" from="1" to="100">
	<div><cfoutput>#idx#</cfoutput></div>
	<cfset sleep(1000) />
</cfloop>
When this runs, I see the expected Lucee error screen. It also doesn't show up in Tomcat's catalina.log file. My second script looks like this:
Copy code
<cfsetting requesttimeout="5" />

<cfscript>
	test = queryExecute("WAITFOR DELAY '00:00:45'; select 'finished delay of 00:00:45' as [response]");

	dump(test);
</cfscript>
This ends up sending the exeception to the catalina.log file and I get no output.
My Application.cfc is:
Copy code
component {
	/*
		Configure database properties
	*/
	variables.dbHost = "";
	variables.dbPort = 1433;
	variables.dbName = "";
	variables.dbUsername = "";
	variables.dbPassword = "";
	variables.socketTimeout = 15000; // in milliseconds
	variables.queryTimeout = 10; // in seconds


	this.datasources["sql-server"] = {
		class: "com.microsoft.sqlserver.jdbc.SQLServerDriver",
		bundleName: "org.lucee.mssql",
		bundleVersion: "12.2.0.jre11",
		connectionString: "jdbc:sqlserver://#variables.dbHost#:#variables.dbPort#;UseUnicode=false;CharacterEncoding=false;ZeroDateTimeBehavior=false;TinyInt1isBit=false;databaseName=#variables.dbName#;SendStringParametersAsUnicode=false;AutoReconnect=false;DatetimeParameterType=datetime;Encrypt=false;JdbcCompliantTruncation=false;UseOldAliasMetadataBehavior=false;AllowMultiQueries=true;UseLegacyDatetimeCode=false;SelectMethod=direct;socketTimeout=#variables.socketTimeout#;queryTimeout=#variables.queryTimeout#",
		username: variables.dbUsername,
		password: variables.dbPassword,

		// optional settings
		connectionLimit:-1, // default:-1
		LiveTimeout:15, // default: -1; unit: minutes
		validate:false, // default: false
	};

	this.datasource = "sql-server";
}
So the query is timing out after 10 seconds and that's when I see the request die, but Tomcat isn't handling things the same way as the first request.
@zackster Take a look at the additional information I just put in and see if it makes any sense to you. I appreciate you taking the time!
z
I'm off in meetings again, sorry
c
@dswitzer not sure if this is relevant, but we've had various issues with how Lucee handles query timeouts where sometimes a request would hang and leave a sql transaction open. that open transaction would end up blocking other queries and eventually we'd have a mess on our hands. we solved it by enabling xact abort server-wide in the sql server connection settings
d
@czeller I appreciate the response. Not the problem in this case, because the request is properly dying, but somewhere between Lucee and Tomcat something is going wrong. Works great under CommandBox/Undertow.
👍 1
I'm wonder if this log entry in my 
catalina.2023-09-14.log
is the clue I need:
Copy code
14-Sep-2023 15:06:57.928 SEVERE [http-nio-8080-exec-10] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [CFMLServlet] in context with path [] threw exception [null] with root cause
        java.lang.ThreadDeath
                at java.base/java.lang.Thread.stop(Thread.java:937)
                at lucee.commons.io.SystemUtil._stop(SystemUtil.java:1343)
                at lucee.commons.io.SystemUtil.stop(SystemUtil.java:1334)
                at lucee.commons.io.StopThread.run(SystemUtil.java:1765)
z
yeah that's a thread dying, i see that when i'm step debugging lucee and leave the request paused for more than 50s
d
Why would Tomcat be seeing that for what should be a Lucee request timeout page?
Keep in mind, if my 
<cfsetting requesttimeout="XX" />
line is larger than the JDBC timeout, the page returns as expected. It's only when the value is smaller than the JDBC timeout does Tomcat/Lucee have issues.
Those lines in the catalina.log only show up when the 
requesttimeout
is triggering the end of the request. It's also weird that it only does it with the JDBC example.
c
@dswitzer i'm curious if something similar happens with cfhttp or cfftp - where there's network connectivity involved
d
@czeller Good question. Let me check.
CFHTTP doesn't have the problem if you have a 
setting requestTimeout="5";
line, CFHTTP will use that timeout value over the manually specifed 
timeout
in the CFHTTP call. It ends up not being a very equal test because of that.
c
Ah, interesting.
d
Same behavior with CFEXECUTE
z
yeah it's tag timeout minus what's remaining for the request from memory
however i do seem to recall that the request start time starts in app server, before it gets to starting running cfml
d
This (partial) stacktrace looks dubious to me:
Copy code
14-Sep-2023 15:12:38.832 SEVERE [http-nio-8080-exec-7] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [CFMLServlet] in context with path [] threw exception [null] with root cause
        java.lang.ThreadDeath
                at java.base/java.lang.Thread.stop(Thread.java:937)
                at lucee.commons.io.SystemUtil._stop(SystemUtil.java:1343)
                at lucee.commons.io.SystemUtil.stop(SystemUtil.java:1334)
                at lucee.commons.io.StopThread.run(SystemUtil.java:1765)
e.PageContextImpl._doInclude(PageContextImpl.java:948)
        at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:219)
        at lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:44)
        at lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2493)
        at lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2478)
        at lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2449)
        at lucee.runtime.engine.Request.exe(Request.java:45)
That seems to be the problem.
Both Tomcat and CommandBox/Undertow are triggering the ThreadDeath, but CommandBox/Undertow still show the Lucee error page, where as Tomcat's request appears to die at the ThreadDeath.
b
That just sounds like the difference between Lucee giving up on some interruptible code, and tomcat giving up on Lucee when Lucee can't stop itself
Which explains different messages in each scenario.
Not much you can do about it, ither than setting a timeout in your quert.
d
The problem is if the query ends up running longer than the timeout, then the requesttimeout never trickles up.
So if a query unexpectedly runs for a very long time, the exception ends up being completely swallowed.
b
Java can't interrupt queries, so it's not capable of timeing out cleanly. The thread death will eventually kick in from the controller thread, but prolly still won't stop the query.
Yeah, that's what I'm saying, there's not much you can do about it
d
It definitely won't stop the query. It seems like a problem with the way Lucee is killing the thread though.
b
Other than trying a timeout in the cfquery, which may be dependant on the JDBC dricer
d
@bdw429s There is one in the example.
The query is timing out appropriately, it's that Lucee's requesttimeout handling is off
b
Hmm, I'm on my phone but the only query I see above hass mo timeout
d
Either that or it's something in our Tomcat/Lucee configuration. Like I said, in CommandBox I see the expected error.
The timeout is in the JDBC driver. It times out after 15 seconds.
Same code in CommandBox shows the Lucee "request timeout" page. In Tomcat, the page is swallowed up and Tomcat gets a null response.
b
The "livetimout"? I assumed that was for the connection pool
d
No, there's a queryTimeout in the connection string of 15 seconds.
That actually gets triggered, I can see the thread end at around 15 seconds, so it gets honored. If I change the to something like 
setting requesttimeout=30
then it all works as you'd expected.
It's just that if the timeout is less than the queryTimeout on the JDBC connection, that's when things go awry.
b
Ahh, I see it now. You still may want to test the one in cfquery in case Lucee handles it differently https://cfdocs.org/cfquery
Does tomcat have a 500 response still?
d
No, it returns an empty response. No headers, no nothing.
b
CommandBox does have a custom check that always sets the default error page if the response is empty and the response code is not 2xx, but that wouldn't explain the Lucee error page.
d
If I call the page via telnet, all I see is: Connection closed by foreign host.
b
Weird, I can't explain the difference then. I guess you just have to use CommandBox 😁
d
Here's a very simple POC. It runs as expected in CommandBox, but w/Tomcat theThreadDeath that gets triggered causes the empty response. In both cases Lucee fires the ThreadDeath.
page-request-jdbc-timeout-broken-connection.zip
And maybes it's just with the way Tomcat handles the ThreadDeath
I'm more ignorant on how the Lucee/Tomcat picese fit together than I probably should be.
b
I'm OOO until Monday... I know how to track down how and what Undertow is doing, but that's not much help since it's Tomcat misbehaving!
d
My current guess is that Undertow is seeing a ThreadDeath and seeing there's a response, so it's showing the response that's in the buffer, where as Tomcat sees the ThreadDeath and just stops all execution.
I'm thinking the cause is that Lucee's triggering the ThreadDeath when it thinks the thread is stuck, because it didn't timeout around the request timeout period, but it's not accounting for the time to allow it to render the request timeout error once it starts responding.
I ended up just filing a Jira bug for this: https://luceeserver.atlassian.net/browse/LDEV-4696
3 Views
Open in Slack
PreviousNext
Powered by