Creating DSNs tanks Lucee server

Michael_Muller · July 11, 2019, 7:56pm

I have been successfully creating DSNs on the fly in both Lucee and ACF using this piece of code, below. Lately, however, whenever I use it, Lucee stops flat while it works on the process, and every website on my server comes to a stop, too, while they wait.

And, when I say stop and wait… I mean FIFTEEN MINUTES

Now, admittedly, I’ve already got over 400 DSNs in there. But… should that matter?

Just on a whim, I tried to check a few DSNs that are no longer being used (probably quite a few in there that are no longer in service) and then click delete. It’s now been five minutes, and I’m still looking at a greyed-out “Please Wait” screen. Five minutes. Ah. It timed out.

I’m currently running Lucee 5.3.1.102 on Windows Server 2012, connecting to another Win2012 running MS SQL Server.

I’m pretty much stopped in my tracks here, if I can’t create new databases and connect to them, or manage the connections through Lucee.

A friend who’s helping me posted a support ticket for this several months ago, but it hasn’t seen any movement. He’s given me two suggestions for how to change my process programmatically to get around this issue, but I’m hoping someone else has had this problem and figured out a simpler solution.

Thanks,

Mik

<cfadmin
action="updateDatasource"
type="server"
password="#variables.adminpw#"
classname="com.microsoft.jdbc.sqlserver.SQLServerDriver"
dsn="jdbc:sqlserver://#variables.ip#:#variables.port#"
host="#variables.ip#"
port="#variables.port#"
name="#variables.newdbname#"
newname="#variables.newdbname#"
database="#variables.newdbname#"
dbusername="#variables.newdbuname#"
dbpassword="#variables.newdbpname#"
connectionLimit="500"
connectionTimeout="60"
blob="false"
clob="true"
allowed_select="true"
allowed_insert="true"
allowed_update="true"
allowed_delete="true"
allowed_alter="true"
allowed_drop="true"
allowed_revoke="false"
allowed_create="true"
allowed_grant="false"
sendStringParametersAsUnicode="false"
SelectMethod="cursor">

bdw429s · July 11, 2019, 8:00pm

What does a stack trace show is happening during that 15 minutes? I assume there’s something Lucee does while looping over the datasources that is to fast to notice with only a few datasources but gets very slow when there are 400 of them.

A friend who’s helping me posted a support ticket for this several months ago,

Link? If you need an immediate fix for this, consider contacting @Gert to hire Rasia for a sponsored fix right away.

Michael_Muller · July 11, 2019, 8:14pm

I’ll ask him for the link.
@Gert can you provide an estimate for what a ‘sponsored fix’ would cost?

Michael_Muller · July 11, 2019, 8:19pm

As for the stack trace, I’ll wait till late tonight to try it again, as I don’t want to bring my server down for 15 minutes during business hours. Maybe FusionReactor can spit something out.

bdw429s · July 11, 2019, 8:23pm

Yes, FR will show you the stack of the thread running the code. I would also recommend getting a full thread dump of the JVM under “Resources” > “Threads” > “Stack Trace All” to capture any other processes that may be kicked off in a separate thread as part of the save.

Gert · July 11, 2019, 8:29pm

Hi Michael, I will have a look at it tomorrow. What’s the best way to get in contact with you?

Gert

Michael_Muller · July 11, 2019, 8:31pm

Email is fine.

Michael_Muller · July 12, 2019, 12:33pm

This is the stack trace of the thread after it timed out.

java.util.zip.ZipFile.open(Native Method)
java.util.zip.ZipFile.<init>(ZipFile.java:225)
java.util.zip.ZipFile.<init>(ZipFile.java:155)
java.util.jar.JarFile.<init>(JarFile.java:166)
java.util.jar.JarFile.<init>(JarFile.java:130)
lucee.runtime.osgi.BundleInfo.<init>(BundleInfo.java:93)
lucee.runtime.osgi.BundleFile.<init>(BundleFile.java:41)
lucee.runtime.osgi.BundleFile.<init>(BundleFile.java:37)
lucee.runtime.osgi.OSGiUtil.installBundle(OSGiUtil.java:105)
lucee.runtime.MappingImpl.loadArchive(MappingImpl.java:159)
lucee.runtime.MappingImpl.<init>(MappingImpl.java:141)
lucee.runtime.MappingImpl.cloneReadOnly(MappingImpl.java:319)
lucee.runtime.config.XMLConfigWebFactory.loadMappings(XMLConfigWebFactory.java:1492)
lucee.runtime.config.XMLConfigWebFactory.load(XMLConfigWebFactory.java:477)
 - locked <0xb285947> (a java.lang.Class)
lucee.runtime.config.XMLConfigWebFactory.reloadInstance(XMLConfigWebFactory.java:336)
lucee.runtime.config.XMLConfigAdmin._reload(XMLConfigAdmin.java:323)
 - locked <0x5cae9038> (a lucee.runtime.config.XMLConfigAdmin)
lucee.runtime.config.XMLConfigAdmin.storeAndReload(XMLConfigAdmin.java:306)
 - locked <0x5cae9038> (a lucee.runtime.config.XMLConfigAdmin)
lucee.runtime.tag.Admin.store(Admin.java:5093)
lucee.runtime.tag.Admin.doRemoveDatasource(Admin.java:2900)
lucee.runtime.tag.Admin._doStartTag(Admin.java:750)
lucee.runtime.tag.Admin.doStartTag(Admin.java:341)
test_cfm$cf.call(/test.cfm:29)
lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:911)
lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:803)
lucee.runtime.listener.ClassicAppListener._onRequest(ClassicAppListener.java:64)
lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:43)
lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2367)
lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2357)
lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2332)
lucee.runtime.engine.Request.exe(Request.java:43)
lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1045)
lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:991)
lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:102)
lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
sun.reflect.GeneratedMethodAccessor83.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:134)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doNext(FusionReactorRequestHandler.java:764)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doHttpServletRequest(FusionReactorRequestHandler.java:344)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doFusionRequest(FusionReactorRequestHandler.java:207)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.handle(FusionReactorRequestHandler.java:801)
com.intergral.fusionreactor.j2ee.filter.FusionReactorCoreFilter.doFilter(FusionReactorCoreFilter.java:36)
sun.reflect.GeneratedMethodAccessor82.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:71)
sun.reflect.GeneratedMethodAccessor81.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
com.intergral.fusionreactor.agent.filter.FusionReactorStaticFilter.doFilter(FusionReactorStaticFilter.java:54)
com.intergral.fusionreactor.agent.pointcuts.NewFilterChainPointCut$1.invoke(NewFilterChainPointCut.java:41)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:486)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
 - locked <0x439210d7> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers: 
    - java.util.concurrent.ThreadPoolExecutor$Worker <0xa8fac0b>

Zackster · July 12, 2019, 12:35pm

Does it happen with 5.3.2.77 or 5.3.3.60-RC?

Michael_Muller · July 12, 2019, 12:37pm

Stack Trace All Threads

"ajp-nio-8009-exec-391" Id=942954 RUNNABLE (in native)
Trace Time	12-Jul-19 08:41:00.830
Thread Id	0xe636a (942954)
Thread Name	ajp-nio-8009-exec-391
Priority	1
HashCode	118563273
State	RUNNABLE
Daemon	true
Blocked Time 	00:02:20.547
Blocked Count 	3173
Waited Time 	3 days 21:57:49.550
Waited Count 	24386
CPU Time 	00:11:47.421
User Time 	00:09:38.546
Allocated Memory 	94,575.46 MB

java.util.zip.ZipFile.open(Native Method)
java.util.zip.ZipFile.<init>(ZipFile.java:225)
java.util.zip.ZipFile.<init>(ZipFile.java:155)
java.util.jar.JarFile.<init>(JarFile.java:166)
java.util.jar.JarFile.<init>(JarFile.java:130)
lucee.runtime.osgi.BundleInfo.<init>(BundleInfo.java:93)
lucee.runtime.osgi.BundleFile.<init>(BundleFile.java:41)
lucee.runtime.osgi.BundleFile.<init>(BundleFile.java:37)
lucee.runtime.osgi.OSGiUtil.installBundle(OSGiUtil.java:105)
lucee.runtime.MappingImpl.loadArchive(MappingImpl.java:159)
lucee.runtime.MappingImpl.<init>(MappingImpl.java:141)
lucee.runtime.MappingImpl.cloneReadOnly(MappingImpl.java:319)
lucee.runtime.config.XMLConfigWebFactory.loadMappings(XMLConfigWebFactory.java:1492)
lucee.runtime.config.XMLConfigWebFactory.load(XMLConfigWebFactory.java:477)
 - locked <0xb285947> (a java.lang.Class)
lucee.runtime.config.XMLConfigWebFactory.reloadInstance(XMLConfigWebFactory.java:336)
lucee.runtime.config.XMLConfigAdmin._reload(XMLConfigAdmin.java:323)
 - locked <0x5cae9038> (a lucee.runtime.config.XMLConfigAdmin)
lucee.runtime.config.XMLConfigAdmin.storeAndReload(XMLConfigAdmin.java:306)
 - locked <0x5cae9038> (a lucee.runtime.config.XMLConfigAdmin)
lucee.runtime.tag.Admin.store(Admin.java:5093)
lucee.runtime.tag.Admin.doRemoveDatasource(Admin.java:2900)
lucee.runtime.tag.Admin._doStartTag(Admin.java:750)
lucee.runtime.tag.Admin.doStartTag(Admin.java:341)
test_cfm$cf.call(/test.cfm:29)
lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:911)
lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:803)
lucee.runtime.listener.ClassicAppListener._onRequest(ClassicAppListener.java:64)
lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:43)
lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2367)
lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2357)
lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2332)
lucee.runtime.engine.Request.exe(Request.java:43)
lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1045)
lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:991)
lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:102)
lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
sun.reflect.GeneratedMethodAccessor83.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:134)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doNext(FusionReactorRequestHandler.java:764)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doHttpServletRequest(FusionReactorRequestHandler.java:344)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doFusionRequest(FusionReactorRequestHandler.java:207)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.handle(FusionReactorRequestHandler.java:801)
com.intergral.fusionreactor.j2ee.filter.FusionReactorCoreFilter.doFilter(FusionReactorCoreFilter.java:36)
sun.reflect.GeneratedMethodAccessor82.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:71)
sun.reflect.GeneratedMethodAccessor81.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
com.intergral.fusionreactor.agent.filter.FusionReactorStaticFilter.doFilter(FusionReactorStaticFilter.java:54)
com.intergral.fusionreactor.agent.pointcuts.NewFilterChainPointCut$1.invoke(NewFilterChainPointCut.java:41)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:486)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
 - locked <0x439210d7> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers: 
    - java.util.concurrent.ThreadPoolExecutor$Worker <0xa8fac0b>

Michael_Muller · July 12, 2019, 12:41pm

Not sure. We could install patch (5.3.4.2-SNAPSHOT), but have they worked on that code?

Zackster · July 12, 2019, 12:44pm

there’s one easy way to find out…

btw which version of the mssql extension and java are you using?

Michael_Muller · July 12, 2019, 1:07pm

MS SQL
Installed version: 6.2.2.jre8
Available version: 7.2.1

Not sure of the Java version.

BTW, I’m on Windows Server 2016 64bit, not 2012.

joe.gooch · July 12, 2019, 4:30pm

Looks to me like it’s trying to auto-download/install a new bundle…

bdw429s · July 12, 2019, 4:51pm

That stack isn’t downloading, but it is loading bundles. If you back up in the stack a bit, you’ll see that it appears to be reloading Lucee (like when you hit the restart button in the admin I think)

lucee.runtime.config.XMLConfigWebFactory.reloadInstance(XMLConfigWebFactory.java:336)
lucee.runtime.config.XMLConfigAdmin._reload(XMLConfigAdmin.java:323)
lucee.runtime.config.XMLConfigAdmin.storeAndReload(XMLConfigAdmin.java:306)

You mentioned something about 400 datasources. Are you updating all 400 of them with the cfadmin tag, or just updating a single one? I’m curious is Lucee is being reloaded 400 times. Also, are all the datasources using the same JDBC driver (and therefore the same OSGI bundle)?

Also, the stack shows access to the file system to load zip files. Can you please check the Windows processes that are running while the server is “hung” and sort by CPU descending? Check for Antivirus or Windows Defender (antimalware service executable) at the top of the list. It’s entirely possible that your antivirus has kicked into high gear and is scanning every jar file as Lucee loads it which can slow things to a crawl.

Michael_Muller · July 12, 2019, 5:31pm

Some notes from my buddy:

On dev VM (zero traffic) adding DSN is also slow (image copy of production VM)
Adding the DSN directly in the lucee-server.xml causes no slowdown at all so this doesn’t indicate to me any MSSQL datasource issue or need for upgrade

Zackster · July 12, 2019, 5:32pm

hang on, 15 minutes rings a bell [LDEV-2134] - Lucee

Michael_Muller · July 12, 2019, 5:35pm

You mentioned something about 400 datasources. Are you updating all 400 of them with the cfadmin tag, or just updating a single one?

No, I only run the one command, as shown at top.

Michael_Muller · July 12, 2019, 5:42pm

hang on, 15 minutes rings a bell

We are not on a corp network. It’s running in a VM on a Host Machine I lease, connecting to SQL on another VM in the same box. Private, virtual network connecting them all (four total VMs).

Michael_Muller · July 12, 2019, 5:46pm

If it’s restarting or verifying every DSN, is there a flag or attribute I can add that prevents that? Let’s just assume they’re all working whenever I add a new one.