http://coldfusion.com logo
Join Slack
Powered by
Our datacenter has been doing a lot of networking ...
# lucee
d
Our datacenter has been doing a lot of networking patching lately and we're seeing some application instability due to this. What happens is if the network connection is dropped during a JDBC connection, that connection doesn't detect the network failure and Lucee continues to wait for a response that will never arrive. We're using the SQL Server JDBC extension bundle version 12.2.0.jre11. I can replicate the behavior by emulating a long running query and then using the 
tc
command in Linux to drop packets to the database server. Once I resume traffic, the Lucee thread will continue to run waiting on a response from the JDBC server. I'm playing around with different "connection" settings now, but does anyone know of a graceful way to deal with this?
z
what does the thread state look like when it hangs?
i.e. from the threads panel in my performance analzyer
d
The FusionReactor truncated profile stack looks like this:
Copy code
100.0% - 59.864s java.lang.Thread.run(Thread.java)
53 Collapsed Methods (show)
100.0% - 59.864s lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java)
55.5% - 33.229s lucee.runtime.listener.ModernAppListener.call(ModernAppListener.java)
64 Collapsed Methods (show)
55.5% - 33.229s java.net.SocketInputStream.socketRead0(Native Method)
55.5% - 33.229s Self Time
44.5% - 26.634s lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java)
25 Collapsed Methods (show)
44.5% - 26.634s java.net.SocketInputStream.socketRead0(Native Method)
44.5% - 26.634s Self Time
Here's a full stack trace from an example thread that's still running in my Dev VM:
Copy code
http-nio-8080-exec-3" Id=76 RUNNABLE (in native)
   java.lang.Thread.State: RUNNABLE
        at java.base@11.0.20/java.net.SocketInputStream.socketRead0(Native Method)
        at java.base@11.0.20/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
        at java.base@11.0.20/java.net.SocketInputStream.read(SocketInputStream.java:168)
        at java.base@11.0.20/java.net.SocketInputStream.read(SocketInputStream.java:140)
        at com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.readInternal(IOBuffer.java:1193)
        at com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.read(IOBuffer.java:1179)
        at com.microsoft.sqlserver.jdbc.TDSChannel.read(IOBuffer.java:2151)
        at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(IOBuffer.java:6895)
        at com.microsoft.sqlserver.jdbc.TDSReader.nextPacket(IOBuffer.java:6788)
        at com.microsoft.sqlserver.jdbc.TDSReader.ensurePayload(IOBuffer.java:6760)
        at com.microsoft.sqlserver.jdbc.TDSReader.peekTokenType(IOBuffer.java:6985)
        at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:66)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1691)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.processResults(SQLServerStatement.java:1356)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.processBatch(SQLServerStatement.java:1347)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.processExecuteResults(SQLServerStatement.java:1339)
        at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.processResponse(SQLServerPreparedStatement.java:546)
        at com.microsoft.sqlserver.jdbc.TDSCommand.close(IOBuffer.java:7755)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.discardLastExecutionResults(SQLServerStatement.java:155)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.closeInternal(SQLServerStatement.java:697)
        at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.closeInternal(SQLServerPreparedStatement.java:338)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.$fr$close(SQLServerStatement.java:712)
        at com.microsoft.sqlserver.jdbc.SQLServerStatement.close(SQLServerStatement.java)
        at lucee.commons.db.DBUtil.closeEL(DBUtil.java:71)
        at lucee.runtime.type.QueryImpl.executeMSSQL(QueryImpl.java:505)
        at lucee.runtime.type.QueryImpl.execute(QueryImpl.java:257)
        at lucee.runtime.type.QueryImpl.(QueryImpl.java:235)
        at lucee.runtime.tag.Query.executeDatasoure(Query.java:1135)
        at lucee.runtime.tag.Query._doEndTag(Query.java:700)
        at lucee.runtime.tag.Query.doEndTag(Query.java:566)
        at tags.query_cfc$cf.udfCall(/basecom/tags/Query.cfc:322)
        at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
        at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
        at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:586)
        at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1933)
        at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
        at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1775)
        at shared.gateways.sessionstoragegateway_cfc$cf.udfCall1(/rootcom/shared/gateways/SessionStorageGateway.cfc:89)
        at shared.gateways.sessionstoragegateway_cfc$cf.udfCall(/rootcom/shared/gateways/SessionStorageGateway.cfc)
        at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
        at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
        at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:586)
        at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1933)
        at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
        at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1775)
        at base.service.basesessionservice_cfc$cf.udfCall2(/rootcom/base/service/BaseSessionService.cfc:418)
        at base.service.basesessionservice_cfc$cf.udfCall(/rootcom/base/service/BaseSessionService.cfc)
        at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
        at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
        at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:586)
        at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1933)
        at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
        at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1775)
        at onrequestend_cfm$cf.call(/OnRequestEnd.cfm:31)
        at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:1056)
        at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:948)
        at lucee.runtime.PageContextImpl.doInclude(PageContextImpl.java:929)
        at application_cfc$cf.udfCall1(/Application.cfc:359)
        at application_cfc$cf.udfCall(/Application.cfc)
        at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
        at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
        at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:586)
        at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1933)
        at lucee.runtime.listener.ModernAppListener.call(ModernAppListener.java:444)
        at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:230)
        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)
        at lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1216)
        at lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1162)
        at lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:97)
        at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:779)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.cfmlprojects.regexpathinfofilter.RegexPathInfoFilter.doFilter(RegexPathInfoFilter.java:47)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at jdk.internal.reflect.GeneratedMethodAccessor134.invoke(Unknown Source)
        at java.base@11.0.20/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base@11.0.20/java.lang.reflect.Method.invoke(Method.java:566)
        at com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:134)
        at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doNext(FusionReactorRequestHandler.java:772)
        at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doHttpServletRequest(FusionReactorRequestHandler.java:344)
        at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doFusionRequest(FusionReactorRequestHandler.java:207)
        at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.handle(FusionReactorRequestHandler.java:809)
        at com.intergral.fusionreactor.j2ee.filter.FusionReactorCoreFilter.doFilter(FusionReactorCoreFilter.java:36)
        at jdk.internal.reflect.GeneratedMethodAccessor133.invoke(Unknown Source)
        at java.base@11.0.20/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base@11.0.20/java.lang.reflect.Method.invoke(Method.java:566)
        at com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:71)
        at jdk.internal.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)
        at java.base@11.0.20/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base@11.0.20/java.lang.reflect.Method.invoke(Method.java:566)
        at app//com.intergral.fusionreactor.agent.filter.FusionReactorStaticFilter.doFilter(FusionReactorStaticFilter.java:54)
        at app//com.intergral.fusionreactor.agent.pointcuts.NewFilterChainPointCut$1.invoke(NewFilterChainPointCut.java:42)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:177)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:769)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:360)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:399)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:891)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1784)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        - locked org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@5f2091a7
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base@11.0.20/java.lang.Thread.run(Thread.java:829)

   Locked ownable synchronizers: 
        - org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker <0x1b5e8a1a>
        - java.util.concurrent.locks.ReentrantLock$NonfairSync <0x7a77d166>
        - java.util.concurrent.locks.ReentrantLock$NonfairSync <0x18ef4410>
        - java.util.concurrent.locks.ReentrantLock$NonfairSync <0x5ba93a58>
z
d
I'm playing around with the connection timeouts to see how they affect things.
The problem with 
socketTimeout
is if the query does not return results within the setting value, it will throw an exception. So if a query is legimately running for longer than the setting, then it would timeout prematurely. Ideally I'm trying to detect if the connection was dropped and would no longer respond.
j
i don't know how to do exactly what you say, but you should at least define a socketTimeout that will cover your longest query. the default, unlimited timeouts are bad news. in case it helps, some notes on timeouts on one of my projects: https://gist.github.com/jamiejackson/0e7f4eb399b161e610c1392c5d657d0e
d
@jamiejackson You make sound points. The problem is we use a single DSN for our application today and certain areas of the application (such as reporting) can have long running queries. So we'd end up needing to set the socketTimeout so high it's effectively useless. I may need to refactor the application so that we use multiple DSN, one of general queries that should always be shortlived and one for the areas of the application where long running queries are allowed. This just is not a trivial change in this codebase, so it's not a "quick fix". I was hoping I could find some setting or some way to identify threads waiting on a response where the connection was dropped. I've got to look through the JDBC source code (https://github.com/microsoft/mssql-jdbc) but it would seem like it should be able to identify a dropped connection.
Unfortunately the only setting I've found so far is the 
socketTimeout
setting, which affects all queries and would need to be set higher than the longest running query you want to run, which for our current purposes wouldn't really help us much because it's not really going to kill the threads any faster than they're being killed today.
d
lateral thought: have you thought of trying the other jdbc driver for sql (there are two, the ms one and the jDTS one) we had some issues with ms one on certain systems and swtiching fixed issues (could introduce others of course, but maybe worth a try) also trying different versions of the mssql driver could help the situation. (as different versions can have different functionality and maybe one of them has the issue, another one does not)
d
@dawesi We need the Microsoft JDBC driver. There are things only is supports (like Always Encrypted).
👍 1
d
so v6.x and higher of ms jdbc has 'AE'...
d
The JTDS driver has the same problem (but admittently I'm running the version that comes with Lucee with is 1.3.1). From what I can tell, without setting either a 
socketTimeout
or 
queryTimeout
connection setting, the JDBC driver has no when an existing connection has dropped. Seemed like it should be able to determine the connection was lost, but it doesn't.
z
yeah i think all this tech is designed around reliable, fast networks
d
It's just driving me crazy because our datacenter keeps doing network maintenance, which is leading to dropped connections and then the application is not recovering gracefully.
It feels like the JDBC driver should be able to detect the broken connection, like it should be sending back a beacon that tells the driver "yep, I'm alive and still working on that request"
z
but that would probably affect performance
d
Going by your "designed around ... fast networks" if it's sending back a simple packet to stay alive you would think that would not really impact performance, but I could be wrong.
My undertstand of the low level network stack is not as good as it probably should be.
z
d
Thanks. I've seen that option. Doesn't really seem to help me though, because it still waits for the natural queryTimeout threshold to hit. What I'm trying to accomplish is to allow legit long running queries (i.e. those that are actually running w/an open connection) run as long as they need to, but if the connection is dropped silently then an exception is thrown. So the 
cancelQueryTimeout
would probably be perfect if it didn't require the 
queryTimeout
too.
The only solution I've found that doesn't require changing the JDBC driver, would be to start using 2 different datasources--one for standard queries and one for queries in which we want to allow them to run for a long time. It's actually probably a good idea in general, but it won't be something we can implement quickly. And it still won't complete resolve the issue, because it could end up leaving some requests open for a very long time.
z
ask the datacenter for a refund on hosting?
d
We've filed requests for several SLA credit.
z
what about a jdbc proxy?
d
I'm just trying to see what I can do to make the application more resilient. Credits are nice, but reducing downtime is better. 🙂
I haven't considered using a proxy. Might try that to see if that changes anything. However, since the JDBC drive is unaware of a dropped connection, not sure if the JDBC proxy will change anything. It's worth trying though.
@zackster So in all this troubleshooting, I've discovered an issue with the 
QueryImpl
in Lucee. One could argue it's actually in the MSSQL JDBC driver, but it's something I believe Lucee could at least work around. One thing I noticed is that my 
queryTimeout
values never seemed to be honored correctly. When I discovered is that if the 
stat
ends up throwing an exception due to a timeout, 
QueryImpl
still tries to call the 
close()
method on the 
stat
object. When this happens and the connection was broken, then the thread will wait until the 
socketTimeout
before the code will continue, or if there is no 
socketTimeout
, which is the default, it will just wait indefinitely. This is because the 
close()
method on the statement is still waiting for a response from the server. I'm not sure if I can get you a test case, because part of the process involves triggering off a command to kill the established connection, but I can definitely show it to you tomorrow if you want to see it.
Open in Slack
PreviousNext
Powered by