[wirebox-1.5+] Error related to system/aop/tmp files

Communities ColdBox HMVC
1

Hmm, I’m getting this same error: “missingInclude”: “/ram/9a414ea6-1783-4e09-8e81-e9ab8cbc4ab5.cfm” “Page /9a414ea6-1783-4e09-8e81-e9ab8cbc4ab5.cfm [ram:///9a414ea6-1783-4e09-8e81-e9ab8cbc4ab5.cfm] not found”

I was getting the same error as wade (/aop/tmp) but I moved to ram:// to try and rectify the issue.

I’m running Railo 4.2.1.001 - Coldbox 3.8.

Some of my aspects are working, some not. Is there a way to try and catch this error and force the aspect include to be regenerated? It’s basically preventing some of my functions running (if the aspect isn’t applied it’s not the end of the world, but the function needs to run as huge parts of my app are falling over).

If I reinit (which I don’t like doing in production) it goes away (temporarily it seems).

I’m running reasonably heavy load (2000 RPM).

Thanks,

Tom.

2

Wirebox basically writes out the stub file, then immediately includes it. It’s possible your hard drives are caching the write and reporting it finished before it actually is. That would be difficult to debug since any debugging code would mostly likely create a pause long enough that the file would then exist. It would be interesting to get some stats on your hard disk’s IOPS, IO latencies, and disk write queue length at the time of the error. What OS and file system are you using?

If that is the issue, the only thing I can really think of is to loop for up to a couple seconds waiting for the file to appear. Though I wouldn’t expect that behavior from RAM, so it’s always possible that there is a concurrency bug in Wirebox.

On a related note, one of the issues, WireBox AOP has is that every new cfm file creates a Java class which can slowly fill up your permgen. If you are only binding aspects to singletons, there’s really no issue since the stubs are only created and included once. However aspects bound to transient objects have to be mixed in every time a new object is created. So if you have a user list that creates 100 user objects on each page request, and each user object has an AOP aspect mixed in-- that’s 100 .cfm files that are written, read, and deleted, and 100 new Java class files that go into permgen space every request.

A while back I thought about an idea of creating a pool of local temp files that could be reused over and over so new cfms didn’t have to be written. I’m not sure how Adobe CF works, but in Railo, an edit to a .cfm file simply overwrites the bytecode in memory without creating a new class so you can change the same cfm 1000 times and no new classes are created. That idea may also help this sort of issue since the files would already exist once the pool had warmed up.

Another thought that just came to me after poking at the temp files is that every temp file for the same method has the same code in it. There’s probably some caching we could do to optimize that.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

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

3

I’m running on elasticbeanstalk, linux - a AWS M3.Large instances…

I do have “Never ( Best Performance )” set under Inspect Templates (CFM/CFC) in the Railo Settings - Performance/Caching. menu. I’d be reluctant to turn that off, as it’s delivered noticeable performance gains…

I’m using the AOP method matcher aspect - only on singletons. Which, is actually the issue - it never recreates the the missing include as, as you pointed out, it only does it once. So once it’s “done it”, it never tries again, and the function with the method matcher aspect will never complete successfully until I reinit.

4

I’m not sure if I followed that. If your objects are singletons, it should only need to create it once since the object is only created once. When you reinit, the injector is shut down and a new one created which means your singletons are re-created and it should write a new temp file then.

There really should be no way it looks for a file without it being written because the code in Mixer.cfc looks like this:

// Write it out to the generation space
instance.mixerUtil.writeAspect( expandedFile, udfOUt.toString() );
// Mix In generated aspect
arguments.target.$wbAOPInclude( tmpFile );
// Remove Temp Aspect from disk
instance.mixerUtil.removeAspect( expandedFile );

Basically, writes the temp file, includes it, and deletes it all at once.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

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

5

My AOP object isn’t a singleton thought - I guess it should be? Perhaps that’s the issue?

My app works fine, until a method that is matched in my aspect is called - that’s when it falls over.

So, as a crude example,

Wirebox:
map(“UserService”).to(“model.UserService”).asSingleton();

mapAspect(“Monitor”).to(“aop.Monitor”);

aop.Monitor.cfc:
component classMatcher=“any” methodMatcher=“annotatedWith:loggable” implements=“coldbox.system.aop.MethodInterceptor” {
function invokeMethod(invocation) {
arguments.invocation.proceed();
logger.log(“User Saved”);
}
}

UserService.cfc:
function saveUser() loggable {
// do something
}

handlers/user.cfc:
property name=“user” inject=“id:UserService”;

function saveUser() {
user.save() // ERROR! missing include is thrown.
}
function deleteUser() {
user.delete() // not matched in method matcher aspect, as it’s not annotated - works fine…
}

6

EDIT:
user.saveUser() // ERROR! missing include is thrown. NOTE: It is continually thrown each time the method is called, without fail, until I reinit.

7

Aspects are always singletons. If you look at the mapAspect method in the binder.cfc you’ll see it actually just does this:

map(arguments.aspect).asEagerInit().asSingleton();

Are you saying the example below happens every single time, or occasionally? Can you provide a full stack trace?

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

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

8

Interesting. Please provide a stack trace. It would have to be re-creating, or at least remixing the AOP advice on every request. Do you have handler caching enabled? Also, is your UserService a singleton?

Are there any other errors related to writing files. Perhaps permission-related?

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

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

9

Also, I think it might be all methods that are matched - they all die basically. It’s not just one or two.

Here’s a stack trace:

"Page /9a414ea6-1783-4e09-8e81-e9ab8cbc4ab5.cfm [ram:///9a414ea6-1783-4e09-8e81-e9ab8cbc4ab5.cfm] not found
at railo.runtime.PageSourceImpl.loadPage(PageSourceImpl.java:158):158
at railo.runtime.type.util.ComponentUtil.getPage(ComponentUtil.java:713):713
at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:92):92
at railo.runtime.type.UDFImpl._call(UDFImpl.java:306):306
at railo.runtime.type.UDFImpl.call(UDFImpl.java:207):207
at railo.runtime.ComponentImpl._call(ComponentImpl.java:588):588
at railo.runtime.ComponentImpl._call(ComponentImpl.java:506):506
at railo.runtime.ComponentImpl.call(ComponentImpl.java:1738):1738
at railo.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:724):724
at railo.runtime.PageContextImpl.getFunction(PageContextImpl.java:1554):1554
at modules.egroup.handlers.figures_cfc$cf.udfCall1(/modules/eGroup/handlers/figures.cfc:165):165
at modules.egroup.handlers.figures_cfc$cf.udfCall(/modules/eGroup/handlers/figures.cfc):-1
at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:92):92
at railo.runtime.type.UDFImpl._call(UDFImpl.java:306):306
at railo.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:194):194
at railo.runtime.ComponentImpl._call(ComponentImpl.java:589):589
at railo.runtime.ComponentImpl._call(ComponentImpl.java:506):506
at railo.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1751):1751
at railo.runtime.tag.Invoke.doComponent(Invoke.java:203):203
at railo.runtime.tag.Invoke.doEndTag(Invoke.java:176):176
at system.web.controller_cfc$cf.udfCall6(/coldbox/system/web/Controller.cfc:764):764
at system.web.controller_cfc$cf.udfCall(/coldbox/system/web/Controller.cfc):-1
at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:92):92
at railo.runtime.type.UDFImpl._call(UDFImpl.java:306):306
at railo.runtime.type.UDFImpl.call(UDFImpl.java:207):207
at railo.runtime.type.scope.UndefinedImpl.call(UndefinedImpl.java:748):748
at railo.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:724):724
at railo.runtime.PageContextImpl.getFunction(PageContextImpl.java:1554):1554
at system.web.controller_cfc$cf.udfCall5(/coldbox/system/web/Controller.cfc:648):648
at system.web.controller_cfc$cf.udfCall(/coldbox/system/web/Controller.cfc):-1
at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:92):92
at railo.runtime.type.UDFImpl._call(UDFImpl.java:306):306
at railo.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:194):194
at railo.runtime.ComponentImpl._call(ComponentImpl.java:589):589
at railo.runtime.ComponentImpl._call(ComponentImpl.java:506):506
at railo.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1755):1755
at railo.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:755):755
at railo.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1564):1564
at coldbox.system.coldbox_cfc$cf.udfCall1(/coldbox/system/Coldbox.cfc:236):236
at coldbox.system.coldbox_cfc$cf.udfCall(/coldbox/system/Coldbox.cfc):-1
at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:92):92
at railo.runtime.type.UDFImpl._call(UDFImpl.java:306):306
at railo.runtime.type.UDFImpl.call(UDFImpl.java:207):207
at railo.runtime.ComponentImpl._call(ComponentImpl.java:588):588
at railo.runtime.ComponentImpl._call(ComponentImpl.java:506):506
at railo.runtime.ComponentImpl.call(ComponentImpl.java:1738):1738
at railo.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:724):724
at railo.runtime.PageContextImpl.getFunction(PageContextImpl.java:1554):1554
at application_cfc$cf.udfCall(/Application.cfc:61):61
at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:92):92
at railo.runtime.type.UDFImpl._call(UDFImpl.java:306):306
at railo.runtime.type.UDFImpl.call(UDFImpl.java:207):207
at railo.runtime.ComponentImpl._call(ComponentImpl.java:588):588
at railo.runtime.ComponentImpl._call(ComponentImpl.java:506):506
at railo.runtime.ComponentImpl.call(ComponentImpl.java:1738):1738
at railo.runtime.listener.ModernAppListener.call(ModernAppListener.java:388):388
at railo.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:114):114
at railo.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:18):18
at railo.runtime.PageContextImpl.execute(PageContextImpl.java:2218):2218
at railo.runtime.PageContextImpl.execute(PageContextImpl.java:2185):2185
at railo.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:332):332
at railo.loader.servlet.CFMLServlet.service(CFMLServlet.java:29):29
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728):728
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305):305
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210):210
at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:749):749
at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:487):487
at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:412):412
at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:339):339
at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:213):213
at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:171):171
at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145):145
at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92):92
at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:394):394
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243):243
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210):210
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222):222
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123):123
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171):171
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100):100
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:680):680
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953):953
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118):118
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408):408
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041):1041
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:603):603
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310):310
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145):1145
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615):615
at java.lang.Thread.run(Thread.java:744):744

Here’s the tag context (it’s in JSON):

    "ERRORDETAIL": {
      "missingInclude": "/ram/9a414ea6-1783-4e09-8e81-e9ab8cbc4ab5.cfm"
    },
    "EVENT": "eGroup:figures.flag",
    "STAMP": "20140620T122348Z",
    "TAGCONTEXT": [
      {
        "Raw_Trace": "modules.egroup.handlers.figures_cfc$cf.udfCall1(/modules/eGroup/handlers/figures.cfc:165)",
        "codePrintPlain": "163:     <cfset rc.pID = event.getValue(\"pID\",0)>\n164:     <cfset rc.flag = event.getValue(\"flag\",\"false\")>\n165:     <cfset figures.flag(rc.pID,rc.flag)>\n166:     <cfset event.noRender()>\n167:   </cffunction>\n",
        "column": 0,
        "line": 165,
        "template": "/modules/eGroup/handlers/figures.cfc",
        "id": "??",
        "type": "cfml",
        "codePrintHTML": "163:     &lt;cfset rc.pID = event.getValue(&quot;pID&quot;,0)&gt;<br>\n164:     &lt;cfset rc.flag = event.getValue(&quot;flag&quot;,&quot;false&quot;)&gt;<br>\n<b>165:     &lt;cfset figures.flag(rc.pID,rc.flag)&gt;</b><br>\n166:     &lt;cfset event.noRender()&gt;<br>\n167:   &lt;/cffunction&gt;<br>\n"
      },
      {
        "Raw_Trace": "system.web.controller_cfc$cf.udfCall6(/coldbox/system/web/Controller.cfc:764)",
        "codePrintPlain": "762: \t\t\t\t\t  method=\"#arguments.method#\"\n763: \t\t\t\t\t  returnvariable=\"refLocal.results\"\n764: \t\t\t\t  \t  argumentcollection=\"#arguments.argCollection#\">\n765: \t\t</cfif>\n766: \n",
        "column": 0,
        "line": 764,
        "template": "/coldbox/system/web/Controller.cfc",
        "id": "??",
        "type": "cfml",
        "codePrintHTML": "762: \t\t\t\t\t  method=&quot;#arguments.method#&quot;<br>\n763: \t\t\t\t\t  returnvariable=&quot;refLocal.results&quot;<br>\n<b>764: \t\t\t\t  \t  argumentcollection=&quot;#arguments.argCollection#&quot;&gt;</b><br>\n765: \t\t&lt;/cfif&gt;<br>\n766: <br>\n"
      },
      {
        "Raw_Trace": "system.web.controller_cfc$cf.udfCall5(/coldbox/system/web/Controller.cfc:648)",
        "codePrintPlain": "646: \t\t\t\t\telse{\n647: \t\t\t\t\t\t// Normal execution\n648: \t\t\t\t\t\tloc.results = invoker(oHandler, ehBean.getMethod(), loc.argsMain, arguments.private);\n649: \t\t\t\t\t}\n650: \t\t\t\t}\n",
        "column": 0,
        "line": 648,
        "template": "/coldbox/system/web/Controller.cfc",
        "id": "??",
        "type": "cfml",
        "codePrintHTML": "646: \t\t\t\t\telse{<br>\n647: \t\t\t\t\t\t// Normal execution<br>\n<b>648: \t\t\t\t\t\tloc.results = invoker(oHandler, ehBean.getMethod(), loc.argsMain, arguments.private);</b><br>\n649: \t\t\t\t\t}<br>\n650: \t\t\t\t}<br>\n"
      },
      {
        "Raw_Trace": "coldbox.system.coldbox_cfc$cf.udfCall1(/coldbox/system/Coldbox.cfc:236)",
        "codePrintPlain": "234: \t\t\t\t<!--- Run Default/Set Event not executing an event --->\n235: \t\t\t\t<cfif NOT event.isNoExecution()>\n236: \t\t\t\t\t<cfset refResults.results = cbController.runEvent(default=true)>\n237: \t\t\t\t</cfif>\n238: \n",
        "column": 0,
        "line": 236,
        "template": "/coldbox/system/Coldbox.cfc",
        "id": "??",
        "type": "cfml",
        "codePrintHTML": "234: \t\t\t\t&lt;!--- Run Default/Set Event not executing an event ---&gt;<br>\n235: \t\t\t\t&lt;cfif NOT event.isNoExecution()&gt;<br>\n<b>236: \t\t\t\t\t&lt;cfset refResults.results = cbController.runEvent(default=true)&gt;</b><br>\n237: \t\t\t\t&lt;/cfif&gt;<br>\n238: <br>\n"
      },
      {
        "Raw_Trace": "application_cfc$cf.udfCall(/Application.cfc:61)",
        "codePrintPlain": "59:     //Process a ColdBox request only\n60:     if( findNoCase('index.cfm',listLast(arguments.targetPage,\"/\")) ){\n61:      application.cbBootStrap.processColdBoxRequest();\n62:     }\n63: \n",
        "column": 0,
        "line": 61,
        "template": "/Application.cfc",
        "id": "??",
        "type": "cfml",
        "codePrintHTML": "59:     //Process a ColdBox request only<br>\n60:     if( findNoCase('index.cfm',listLast(arguments.targetPage,&quot;/&quot;)) ){<br>\n<b>61:      application.cbBootStrap.processColdBoxRequest();</b><br>\n62:     }<br>\n63: <br>\n"
      }
    ],
10

Interesting-- that error is not coming from the AOP mixer-- that’s coming from Railo while trying to compile the code. Are you clearing template cache at the same time that you reinit? Railo may be trying to go back to the disk to find the original file that function came from.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

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

11

No I’m just reiniting. I mean, I only do that when it bawks. My App is built from a war, and I don’t have access to the server (well, I do, I can get access to it - but because it’s elasticbeanstalk it spins up on it’s own free will when it needs to).

Are you talking about the cacheBox template cache? or the Railo Page Pool Cache?

12

Right, I commented out // instance.mixerUtil.removeAspect( expandedFile );, changed the tmp file location back to the default, restarted Railo, and the aop/tmp directory is filled with files…so I don’t think it’s permission related…

13

The Railo cache. That’s the only reason I can imagine that Railo would go looking for a .cfm file long after it’s been included. Perhaps this is a good question for Micha on the Railo list. I’m looking at the Java code in Railo, but it’s often time difficult to follow exactly what’s going on.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

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

14

Yeah, once I saw the stack trace, I could tell it wasn’t related to the actual Wirebox code. I assumed the wirebox include was failing-- but it’s actually something internal to Railo that is looking for the file after it’s been deleted.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

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

15

I started this thread on the Railo group:

https://groups.google.com/d/topic/railo/tlGl_SeeHzo/discussion

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

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

16

Awesome thanks Brad!

17

I guess I could, for now, keep the remove aspect commented out, so that Railo can (although why it should, as you said, is a mystery) find the include again. My servers rarely last more than a few days at the moment as I’m regularly patching them with new versions, and seeing as I’m only running one app, with all singletons, it won’t create that many tmp files.

But that’s not a solution for anyone else!

Thanks,

TOm.

18

For anyone following this, Micha got back to me today on my Railo thread and told me to put in a ticket for it. That ticket is here:

https://issues.jboss.org/browse/RAILO-3114

Please vote or place a comment to encourage it to get fixed :slight_smile:

Thanks!

~Brad