java.lang.RuntimeException when updating to 5.3.10.120

I updated from 5.3.9.141 to 5.3.10.120 and now get the following error “lucee.runtime.exp.NativeException: java.lang.InterruptedException”. The errors come in short succession and then stops then starts again. No other changes have been done apart from the update. No code changes. No couchbase jar updates etc. The errors do not happen on 5.3.9.141.

|Servlet Container |Apache Tomcat/9.0.72|
|Java |11.0.18 (Eclipse Adoptium) 64bit|
|OS |Windows Server 2012 R2 (6.3) 64bit|

Lucee.runtime.exp.NativeException: java.lang.InterruptedException
at com.couchbase.client.core.util.CoreAsyncUtils.block(CoreAsyncUtils.java:43)
at com.couchbase.client.core.api.kv.CoreAsyncResponse.toBlocking(CoreAsyncResponse.java:53)
at com.couchbase.client.core.api.kv.CoreKvOps.getAndTouchBlocking(CoreKvOps.java:111)
at com.couchbase.client.java.Collection.getAndTouch(Collection.java:322)
at jdk.internal.reflect.GeneratedMethodAccessor125.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at lucee.runtime.reflection.pairs.MethodInstance.invoke(MethodInstance.java:56)
at lucee.runtime.reflection.Reflector.callMethod(Reflector.java:877)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:831)
at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1775)
at couchbaseclient_cfc$cf.udfCall2(/cfcouchbase/CouchbaseClient.cfc:793)
at couchbaseclient_cfc$cf.udfCall(/cfcouchbase/CouchbaseClient.cfc)
at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:697)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:584)
at lucee.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1950)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1794)
at breakdownservices.services.sessionservice_cfc$cf.udfCall2(/com/breakdownservices/services/sessionService.cfc:441)
at breakdownservices.services.sessionservice_cfc$cf.udfCall(/com/breakdownservices/services/sessionService.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:696)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:584)
at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1931)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1775)
at breakdownservices.services.sessionservice_cfc$cf.udfCall1(/com/breakdownservices/services/sessionService.cfc:47)
at breakdownservices.services.sessionservice_cfc$cf.udfCall(/com/breakdownservices/services/sessionService.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:696)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:584)
at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1931)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1775)
at application_cfc$cf.udfCall(/Application.cfc:60)
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:696)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:584)
at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1931)
at lucee.runtime.listener.ModernAppListener.call(ModernAppListener.java:444)
at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:135)
at lucee.runtime.listener.ModernAppListener.onRequest(ModernAppListener.java:107)
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:596)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:209)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:492)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:360)
at org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:433)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:926)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1791)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
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/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.RuntimeException: java.lang.InterruptedException
… 81 more
Caused by: java.lang.InterruptedException
at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:385)
at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
at com.couchbase.client.core.util.CoreAsyncUtils.block(CoreAsyncUtils.java:41)
… 80 more

@nonfatmedia Checked this issue and could not replicate this issue when I updated from 5.3.9.141 to version 5.3.10.120. Can you provide any other details to help replicate this issue?

Thank you for taking the time to look at this: I’ve spent 2 fulls days trying different things but since I can’t replicate it on in our lower tiers which makes it very difficult to debug. It seems to only happen in a production environment where there are lots of concurrent requests. That specific issue happens in our session service. We rolled our own session management to have more control over session using the Ortus couchbase SDK. We also have the Ortus couchbase extension installed version 3.2.0.00006. so we use the SDK and extension running at the same time for different purposes.

The SDK couchbase client is initialized and placed in the server scope so the different apps that run can use a single couchbase client. So even though each VM has over a dozen apps it shares a single client. on every requeststart() we do a getandtouch() to get the session data and place it in the request scope. on requestend() we write any session data back to couchbase any data that may have changed during the request. When this issue starts to manifest itself we notice that it starts to error in different applications at the same time which makes sense since they all share a single client. We do not see any issue with writing data to couchbase.

Application.cfc of each app contains the mapping:

THIS.mappings[“/cfcouchbase”]= “C:\Sites\www\breakdown-services-full\webservices.breakdownexpress.com\com\breakdownservices\libraries\cfcouchbase-3.4.4”;

Session service is inited in each app on start which creates the client and places it in the server scope if it doesn’t exist:

<cflock timeout="10" name="cbsessionstore" throwontimeout="true">
			<cfif NOT structkeyexists(SERVER.cbClient,"cbsessionstore")>
				<cfset SERVER.cbClient.cbsessionstore = new cfcouchbase.CouchbaseClient({
					servers = VARIABLES.clustermembers,
					bucketName  = 'cbsessionstore',
					userName  = 'cbsessionstore',
					password = VARIABLES.bucketpassword,
					EnableConfigHeartBeat = true
				}) />
			</cfif>
		</cflock>

The session services cfc contains the following function which is called by OnRequestStart():

<cffunction name="getSessionObject" access="public" output="false" returntype="struct">
	<cfargument name="key" type="string" required="true" />
	<cfif len(ARGUMENTS.key)>
		<cfset LOCAL.getsession = SERVER.cbClient.cbsessionstore.getAndTouch(id=ARGUMENTS.key,  timeout=VARIABLES.sessionTimeout) />
		<cfif NOT isnull(LOCAL.getsession) AND isstruct(LOCAL.getsession) AND structKeyExists(LOCAL.getsession,"value")>
			<cfset LOCAL.session = LOCAL.getsession.value/>
			<cfset LOCAL.session.success = true/>
		<cfelse>
			<cfset LOCAL.session = THIS.initSession()/>
			<cfset LOCAL.session.success = false/>
		</cfif>
	<cfelse>
		<cfset LOCAL.session = THIS.initSession()/>
		<cfset LOCAL.session.success = false/>
	</cfif>
	<cfreturn LOCAL.session />
</cffunction>

onError() writes the following fragment to our database with the StackTrace above.

Error occurs in C:\Sites\www\breakdown-services-full\webservices.breakdownexpress.com\com\breakdownservices\libraries\cfcouchbase-3.4.4\CouchbaseClient.cfc
couchbaseclient_cfc$cf.udfCall2(/cfcouchbase/CouchbaseClient.cfc:793)

791: thisExpiryDuration,
792: options
793: );
794: }
795: catch( any e ) {

1 Like

I am having a very similar issue with version 5.3.10.120. The majority of errors are timeout errors “lucee.runtime.exp.RequestTimeoutException: request [name/location of file requested] has run into a timeout (timeout: [50] seconds) and has been stopped. The thread started [57734] ms ago”, but I’m also seeing “Interrupted during LDAP operation;lucee.runtime.exp.NativeException: Interrupted during LDAP operation”. All of the errors reference “ajp-nio…8009…”

Under “normal” load, errors occur occassionally (1-3 times every 20-40 minutes). Under heavier load (300-500 sign-in requests per hour), the application becomes unresponsive.

Concurrently, the memory utilization on the MS SQL Server increases to 90% (or more).

After attempts to “remedy” (make minor tweaks in application code; wait for peak load situations; watch application die; restart systems) over a 2-week period, we reverted to the last stable release we used, which is 5.3.9.166.

There are no exceptions reported in the exception log since the version was reverted, no timeouts, no interrupted operations.

|Servet Container|Apache Tomcat/9.0.73|
|Java|11.0.18 (Red Hat, Inc.) 64bit|
|OS|Linux (4.18.0-425.13.1.el8_7.x86_64) 64bit|
|Database|Microsoft SQL Server 13.00.5108|
|Driver|Microsoft JDBC Driver 8.4 for SQL Server 8.4.1.0 (JDBC 4.2)|