ColdBox 4.3 Strange problem

Communities ColdBox HMVC
1

Hi Guys,

I really need help, currently I have an API which is using coldbox 4.3 and coldfusion 11. The APi is working fine, but sometime when I check in fusion reactor, there are API which has process which is like locked. Here is the error info:

coldfusion.runtime.Struct.get(Struct.java:72)

  • waiting on <0x3591d57> (a coldfusion.runtime.Struct held by thread 94030, ajp-bio-8014-exec-3054)
    coldfusion.runtime.ScopeSearchResult.searchForSubkeys(ScopeSearchResult.java:104)
    coldfusion.runtime.LocalScope.search(LocalScope.java:438)
    coldfusion.runtime.NeoPageContext.searchScopes(NeoPageContext.java:766)
    coldfusion.runtime.NeoPageContext.searchScopes(NeoPageContext.java:684)
    coldfusion.runtime.CfJspPage.resolveCanonicalName(CfJspPage.java:1767)
    coldfusion.runtime.CfJspPage._resolve(CfJspPage.java:1726)
    coldfusion.runtime.CfJspPage._resolveAndAutoscalarize(CfJspPage.java:1875)
    coldfusion.runtime.CfJspPage._resolveAndAutoscalarize(CfJspPage.java:1854)
    cfInterceptorService2ecfc458890167$funcPROCESSSTATE.runFunction(/opt/myapp/at2/coldbox/system/web/services/InterceptorService.cfc:161)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)
    coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2483)
    cfInjector2ecfc312652358$funcBUILDINSTANCE.runFunction(/opt/myapp/at2/coldbox/system/ioc/Injector.cfc:285)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)
    coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2483)
    cfNoScope2ecfc766392919$funcGETFROMSCOPE.runFunction(/opt/myapp/at2/coldbox/system/ioc/scopes/NoScope.cfc:31)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)
    coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2483)
    cfInjector2ecfc312652358$funcGETINSTANCE.runFunction(/opt/myapp/at2/coldbox/system/ioc/Injector.cfc:263)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)
    coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2483)
    cfController2ecfc1343300006$funcGETDATAMARSHALLER.runFunction(/opt/myapp/at2/coldbox/system/web/Controller.cfc:131)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)
    coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2483)
    cfBootstrap2ecfc1530537328$funcRENDERDATASETUP.runFunction(/opt/myapp/at2/coldbox/system/Bootstrap.cfc:577)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:533)
    coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2819)
    cfBootstrap2ecfc1530537328$funcPROCESSCOLDBOXREQUEST.runFunction(/opt/myapp/at2/coldbox/system/Bootstrap.cfc:267)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)
    coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2854)
    cfBootstrap2ecfc1530537328$funcONREQUESTSTART.runFunction(/opt/myapp/at2/coldbox/system/Bootstrap.cfc:360)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)
    coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2483)
    cfApplication2ecfc1936685633$funcONREQUESTSTART.runFunction(/opt/myapp/at2/web/go/Application.cfc:104)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)
    coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)
    coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)
    coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
    coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)
    coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)
    coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)
    coldfusion.runtime.AppEventInvoker.invoke(AppEventInvoker.java:108)
    coldfusion.runtime.AppEventInvoker.onRequestStart(AppEventInvoker.java:279)
    coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:463)
    coldfusion.filter.RequestMonitorFilter.invoke(RequestMonitorFilter.java:42)
    coldfusion.filter.MonitoringFilter.invoke(MonitoringFilter.java:40)
    coldfusion.filter.PathFilter.invoke(PathFilter.java:153)
    coldfusion.filter.ExceptionFilter.invoke(ExceptionFilter.java:94)
    coldfusion.filter.ClientScopePersistenceFilter.invoke(ClientScopePersistenceFilter.java:28)
    coldfusion.filter.BrowserFilter.invoke(BrowserFilter.java:38)
    coldfusion.filter.NoCacheFilter.invoke(NoCacheFilter.java:58)
    coldfusion.filter.GlobalsFilter.invoke(GlobalsFilter.java:38)
    coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:22)
    coldfusion.filter.CachingFilter.invoke(CachingFilter.java:62)
    coldfusion.CfmServlet.service(CfmServlet.java:219)
    coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:89)
    org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServletFilter.java:42)
    coldfusion.bootstrap.BootstrapFilter.doFilter(BootstrapFilter.java:46)
    org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    sun.reflect.GeneratedMethodAccessor79.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    java.lang.reflect.Method.invoke(Method.java:483)
    com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:134)
    com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doNext(FusionReactorRequestHandler.java:802)
    com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doHttpServletRequest(FusionReactorRequestHandler.java:339)
    com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doFusionRequest(FusionReactorRequestHandler.java:215)
    com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.handle(FusionReactorRequestHandler.java:839)
    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:483)
    com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:71)
    sun.reflect.GeneratedMethodAccessor78.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    java.lang.reflect.Method.invoke(Method.java:483)
    com.intergral.fusionreactor.agent.filter.FusionReactorStaticFilter.doFilter(FusionReactorStaticFilter.java:53)
    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:220)
    org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
    org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
    org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:450)
    org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:197)
    org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
    org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
  • locked <0x44308842> (a org.apache.tomcat.util.net.SocketWrapper)
    java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    java.lang.Thread.run(Thread.java:745)

Locked ownable synchronizers:

  • java.util.concurrent.ThreadPoolExecutor$Worker@1bc7eb36

any idea for this problem?

2

Can’t say I’ve seen that one before. Is your CF11 box fully patched?

The next time this happens, pull a FULL thread dump of the entire JVM. I need to see the other thread that’s blocking this one to see what its doing. In the case below, it was a thread named thread 94030, ajp-bio-8014-exec-3054

Thanks!

~Brad

ColdBox/CommandBox Developer Advocate
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

3

FYI, my coldfusion version is 11,0,12,302575
after I restart my cfserver, I never get this problem now. I will check again later

4

Hi Brad,

I’ve got again this problem in my server, after I trace the thread error. I found the problem is at coldbox logger

[....coldbox/system/logging/Logger.cfc:344](http://admin.app1.be.prosolution.com/fusionreactor/fusionreactor/findex.htm?p=debugUnavailable))

when I open the code in line 344:

thread action="run" name="#threadName#" logEvent="#logEvent#" thisAppender="#thisAppender#"{
     attributes.thisAppender.logMessage( attributes.logEvent );
}

The 2 process which were deadlock run almost at the same time. Maybe you know about this issue already ?

Thanks

Andri
5

Please see my last reply. I need a full thread dump of the JVM to help you. I’m already aware of what line was getting help up-- that information was in your first E-mail, but that line number doesn’t really mean anything. We need to know what thread holds the lock and what that thread is doing. And that is why I asked you to provide a full thread dump. I can’t help you until you do that.

Thanks!

~Brad

ColdBox/CommandBox Developer Advocate
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

6

Hi Brad,

After I check on the thread info, the problem is at the logbox process.
I have logbox appender with RollingFileAppender and with property async=true, and when there are 2 process log run in the same time it will lock each other.

the locked problem is at:

[coldbox/system/logging/Logger.cfc:344](http://admin.app1.be.prosolution.com/fusionreactor/fusionreactor/findex.htm?p=debugUnavailable))

After I change my logbox setting to async=false, everything are ok now.

Thanks

ANdri

7

The problem is unlikely to be with LogBox at all. The thread in your original post was waiting on ColdFusion to search through scopes to find a variable. There’s nothing LogBox could do to affect that. I have a feeling the issue is hitting scopes like cgi after the HTTP thread has completed. This used to cause issues in older versions of ColdFusion but I thought they fixed those bugs. I’d make sure you’re on the latest update of Adobe CF 11 and please provide a full thread dump. If this is still an issue in CF11, we’ll want to report it.

Thanks!

~Brad

ColdBox/CommandBox Developer Advocate
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com