Reinitializing a ModelGlue application under load causes exceptions in XMLModuleLoader.cfc about modelglue-framework HOT 38 OPEN

Tested in my environment (under CF8) and was able to easily generate errors in the helloworld app by manually hitting ?init=true (so I didn't test my major app yet). Note I didn't get this as the person triggering the reinit, but the Jmeter clients did. Here's what they all were:

Model-Glue: There is no known event handler for "page.index".

The error occurred in C:\Users\brian\Documents\web\mg\modelgluesamples\helloworld\ModelGlue3.2.RC2\gesture\eventrequest\phase\Invocation.cfc: line 92
Called from C:\Users\brian\Documents\web\mg\modelgluesamples\helloworld\ModelGlue3.2.RC2\gesture\eventrequest\EventContext.cfc: line 189
Called from C:\Users\brian\Documents\web\mg\modelgluesamples\helloworld\ModelGlue3.2.RC2\gesture\ModelGlue.cfc: line 297
Called from C:\Users\brian\Documents\web\mg\modelgluesamples\helloworld\ModelGlue3.2.RC2\gesture\ModelGlue.cfm: line 97
Called from C:\Users\brian\Documents\web\mg\modelgluesamples\helloworld\index.cfm: line 78
90 : <cfset arguments.eventContext.addEventHandler(modelglue.getEventHandler(modelglue.configuration.missingEvent)) />
91 :
92 : <cfthrow message="Model-Glue: There is no known event handler for ""#initialEventHandlerName#""." />
93 :
94 :

from modelglue-framework.

We are also hitting this bug.

from modelglue-framework.

@russ0519
Can you please try this version and let me know if you still see the issue?

https://github.com/modelglue/modelglue-framework/archive/newScaffolding.zip

We've made some improvements a month ago that should have locked this
under all but very certain conditions

russ0519 wrote:

We are also hitting this bug.

—
Reply to this email directly or view it on GitHub
#1 (comment).

from modelglue-framework.

Seems like when the controllers are created, there is no locking, and since multiple events can be loading at the same time for the same controller, it can cause race conditions.

Also XMLSearch returns the results by reference, so when you modify the resulting variable, it updates the original.

Changing the loadControllersForBroadcastXML function in XMLModuleLoader.cfc seems to have fixed the issue for me.

<cffunction name="loadControllersForBroadcastXML" output="false" hint="Loads controllers from <controllers> block where a controller has been configured to listen to a certain message.">
    <cfargument name="modelglue" />
    <cfargument name="broadcastsXml" />

    <cfset var i = "" />
    <cfset var j = "" />
    <cfset var k = "" />
    <cfset var x = 0>
    <cfset var NumberOfParsedXMLConfigs = arrayLen( variables.parsedXMLArray ) />
    <cfset var controllerDefinitionArray = "" />
    <cfset var controllersToCreate=ArrayNew(1)>

    <cfloop from="1" to="#arrayLen(arguments.broadcastsXml.xmlChildren)#" index="i">
        <cfloop from="1" to="#NumberOfParsedXMLConfigs#" index="j">
            <cfset controllerDefinitionArray = xmlSearch(variables.parsedXMLArray[j], "/modelglue/controllers/controller[message-listener[translate(@message, 'ABCDEFGHIJKLMNOPQRSTUVWXYZ', 'abcdefghijklmnopqrstuvwxyz') = '#lCase(arguments.broadcastsXml.xmlChildren[i].xmlAttributes.name)#']]")>
            <cfloop from="1" to="#arrayLen( controllerDefinitionArray )#" index="k">
                <cfif NOT structKeyExists(controllerDefinitionArray[k].xmlAttributes, "id")>
                    <cfif structKeyExists(controllerDefinitionArray[k].xmlAttributes, "name")>
                        <cfset controllerDefinitionArray[k].xmlAttributes.id = controllerDefinitionArray[k].xmlAttributes.name />
                    <cfelseif structKeyExists(controllerDefinitionArray[k].xmlAttributes, "type")>
                        <cfset controllerDefinitionArray[k].xmlAttributes.id = controllerDefinitionArray[k].xmlAttributes.type />
                    <cfelse>
                         <cfset controllerDefinitionArray[k].xmlAttributes.id = "ctlr_" & createuuid() />
                    </cfif>
                </cfif>
                <cfset controllersToCreate[++x]=controllerDefinitionArray[k]>
            </cfloop>
        </cfloop>
    </cfloop>
    <cfloop from="1" to="#arrayLen(controllersToCreate)#" index="x">
        <cfif arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id) IS false>
            <cflock type="exclusive" name="ControllerIsAlreadyLoadedLock_#controllersToCreate[x].xmlAttributes.id#" timeout="10" throwontimeout="true">
                <cfif arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id) IS false>
                    <cflock type="exclusive" name="ControllerCreationLock_#controllersToCreate[x].xmlAttributes.id#" timeout="10" throwontimeout="true">
                        <cfif arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id) IS false>
                            <cfset makeController(arguments.modelglue, duplicate(controllersToCreate[x])) />
                        </cfif>
                    </cflock>
                </cfif>
            </cflock>
        </cfif>
    </cfloop>
</cffunction>

from modelglue-framework.

russ0519

I just gave this a shot and it doesn't fix the root cause of the issue.
I can still create errors in Invocation.cfc line 92 caused by a missing
event.

I'm still looking into this but it's annoying and this is probably the
most complicated part of Model Glue, so no promises on when I'll have
something totally perfect.

DW

russ0519 mailto:[email protected]
Friday, February 22, 2013 11:26 AM

Seems like when the controllers are created, there is no locking, and
since multiple events can be loading at the same time for the same
controller, it can cause race conditions.

Also XMLSearch returns the results by reference, so when you modify
the resulting variable, it updates the original.

Changing the loadControllersForBroadcastXML function in
XMLModuleLoader.cfc seems to have fixed the issue for me.

<cfset controllerDefinitionArray =
xmlSearch(variables.parsedXMLArray[j],
"/modelglue/controllers/controller[message-listener[translate(@message, 'ABCDEFGHIJKLMNOPQRSTUVWXYZ',
'abcdefghijklmnopqrstuvwxyz') =
'#lCase(arguments.broadcastsXml.xmlChildren[i].xmlAttributes.name)#']]")>

<cfif NOT structKeyExists(controllerDefinitionArray[k].xmlAttributes,
"id")>
<cfif structKeyExists(controllerDefinitionArray[k].xmlAttributes, "name")>
<cfset controllerDefinitionArray[k].xmlAttributes.id =
controllerDefinitionArray[k].xmlAttributes.name />
<cfelseif structKeyExists(controllerDefinitionArray[k].xmlAttributes,
"type")>
<cfset controllerDefinitionArray[k].xmlAttributes.id =
controllerDefinitionArray[k].xmlAttributes.type />

<cfset controllerDefinitionArray[k].xmlAttributes.id = "ctlr_" &
createuuid() />


<cfset controllersToCreate[++x]=controllerDefinitionArray[k]>




<cfif
arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id)
IS false>

<cfif
arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id)
IS false>

<cfif
arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id)
IS false>
<cfset makeController(arguments.modelglue,
duplicate(controllersToCreate[x])) />

—
Reply to this email directly or view it on GitHub
#1 (comment).

from modelglue-framework.

We have fixed this issue and would like others to test the fix in their environments. You can find the newest code in the newScaffolds branch on Github.

from modelglue-framework.

I am still seeing the issue. As mentioned there seems to be a race condition in XMLModuleLoader.cfc. When several events are trying to load the same controller, there is no lock for loading the controller and it tries to load it several times. Not sure if that is what the issue is, but also the xml object is being passed around by reference and different functions modify it.

Here is the stack trace.

from modelglue-framework.

Under what conditions did you get this to occur?
Would it be possible for you to share a test case, we can use to analyze
this?

DW

russ0519 mailto:[email protected]
Monday, March 04, 2013 11:58 AM

I am still seeing the issue. As mentioned there seems to be a race
condition in XMLModuleLoader.cfc. When several events are trying to
load the same controller, there is no lock for loading the controller
and it tries to load it several times. Not sure if that is what the
issue is, but also the xml object is being passed around by reference
and different functions modify it.

Here is the stack trace.

|
|
|

The error occurred in
/website/components/com/model-glue/ModelGlue/gesture/module/XMLModuleLoader.cfc:
line 221
Called from
/website/components/com/model-glue/ModelGlue/gesture/module/XMLModuleLoader.cfc:
line 553
Called from
/website/components/com/model-glue/ModelGlue/gesture/module/XMLModuleLoader.cfc:
line 469
Called from
/website/components/com/model-glue/ModelGlue/gesture/MemoizedModelGlue.cfc:
line 86
Called from
/website/components/com/model-glue/ModelGlue/gesture/eventrequest/phase/Invocation.cfc:
line 78
Called from
/website/components/com/model-glue/ModelGlue/gesture/eventrequest/EventContext.cfc:
line 189
Called from
/website/components/com/model-glue/ModelGlue/gesture/ModelGlue.cfc:
line 297
Called from
/website/components/com/model-glue/ModelGlue/gesture/ModelGlue.cfm:
line 98
Called from /website/modelglueapp/index.cfm: line 36
Called from /website/wwwroot/app/index.cfm: line 3
Called from /website/wwwroot/Application.cfc: line 360

—
Reply to this email directly or view it on GitHub
#1 (comment).

from modelglue-framework.

Do you need any more details to track this down?

from modelglue-framework.

Yes please.

I've load tested several complex apps with the newest version and the
errors no longer show up when reloading.

So, if you still can replicate this, using the latest code in the New
Scaffold branch on Github, I'd like a test case.
On Mar 27, 2013 1:29 PM, "russ0519" [email protected] wrote:

Do you need any more details to track this down?

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/1#issuecomment-15538565
.

from modelglue-framework.

The last time Dan and I looked at this, we weren't able to replicate this with the latest code from the newScaffolding branch. He tested with jMeter on Windows and I on a Mac and could not get the sample app that Brian put together and we weren't able to trigger any errors in jMeter. I'll try to get my MG environment set back up on my new computer in the next couple of days and see if I get any different results this time.

from modelglue-framework.

We have created a test app that illustrates this issue.

https://github.com/russ0519/modelglue-framework/tree/testMGApp

from modelglue-framework.

Awesome...thanks a bunch! Give us a few days to install and pour through this and we'll see what we can do.

from modelglue-framework.

Do you need any more details?

from modelglue-framework.

At this point, I think we need a spare couple of minutes to look at
this. Sorry for the delay.

russ0519 mailto:[email protected]
Tuesday, April 09, 2013 3:18 PM

Do you need any more details?

—
Reply to this email directly or view it on GitHub
#1 (comment).

from modelglue-framework.

@dskaggs does the commit a month ago address this issue? Because Russ was able to replicate it I have not tried it again. I'm happy to do some testing on my more complex app if the sample app no longer throws errors.

from modelglue-framework.

I don't think that the two issues are related but I'm traveling this week and probably won't have time to run any load testing on the sample app that Russ provided until early next week. If you have the availability and want to report back, I'd happily accept the results :)

from modelglue-framework.

Dan,

Have you had a chance to look into this yet?

from modelglue-framework.

Sort of,

My attempts at fixing this have led to other issues. Are you saying
simply locking the controllers piece will fix this your reported issue?

DW

russ0519 wrote:

Dan,

Have you had a chance to look into this yet?

—
Reply to this email directly or view it on GitHub
#1 (comment).

from modelglue-framework.

I subclassed the XMLModuleLoader component and overrode the loadControllersForBroadcastXML. This seems to be working for us, but I'm sure it's not as efficient as it could be

<cfcomponent output="false" extends="ModelGlue.gesture.module.XMLModuleLoader" hint="I load various bits of the Model Glue config into objects.">

<cffunction name="loadControllersForBroadcastXML" output="false" hint="Loads controllers from <controllers> block where a controller has been configured to listen to a certain message.">
    <cfargument name="modelglue" />
    <cfargument name="broadcastsXml" />

    <cfset var i = "" />
    <cfset var j = "" />
    <cfset var k = "" />
    <cfset var x = 0>
    <cfset var NumberOfParsedXMLConfigs = arrayLen( variables.parsedXMLArray ) />
    <cfset var controllerDefinitionArray = "" />
    <cfset var controllersToCreate=ArrayNew(1)>

    <cfloop from="1" to="#arrayLen(arguments.broadcastsXml.xmlChildren)#" index="i">
        <cfloop from="1" to="#NumberOfParsedXMLConfigs#" index="j">
            <cfset controllerDefinitionArray = xmlSearch(variables.parsedXMLArray[j], "/modelglue/controllers/controller[message-listener[translate(@message, 'ABCDEFGHIJKLMNOPQRSTUVWXYZ', 'abcdefghijklmnopqrstuvwxyz') = '#lCase(arguments.broadcastsXml.xmlChildren[i].xmlAttributes.name)#']]")>
            <cfloop from="1" to="#arrayLen( controllerDefinitionArray )#" index="k">
                <cfif NOT structKeyExists(controllerDefinitionArray[k].xmlAttributes, "id")>
                    <cfif structKeyExists(controllerDefinitionArray[k].xmlAttributes, "name")>
                        <cfset controllerDefinitionArray[k].xmlAttributes.id = controllerDefinitionArray[k].xmlAttributes.name />
                    <cfelseif structKeyExists(controllerDefinitionArray[k].xmlAttributes, "type")>
                        <cfset controllerDefinitionArray[k].xmlAttributes.id = controllerDefinitionArray[k].xmlAttributes.type />
                    <cfelse>
                         <cfset controllerDefinitionArray[k].xmlAttributes.id = "ctlr_" & createuuid() />
                    </cfif>
                </cfif>
                <cfset controllersToCreate[++x]=controllerDefinitionArray[k]>
            </cfloop>
        </cfloop>
    </cfloop>
    <cfloop from="1" to="#arrayLen(controllersToCreate)#" index="x">
        <cfif arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id) IS false>
            <cflock type="exclusive" name="ControllerIsAlreadyLoadedLock_#controllersToCreate[x].xmlAttributes.id#" timeout="10" throwontimeout="true">
                <cfif arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id) IS false>
                    <cflock type="exclusive" name="ControllerCreationLock_#controllersToCreate[x].xmlAttributes.id#" timeout="10" throwontimeout="true">
                        <cfif arguments.modelglue.controllerIsAlreadyLoaded(controllersToCreate[x].xmlAttributes.id) IS false>
                            <cfset makeController(arguments.modelglue, duplicate(controllersToCreate[x])) />
                        </cfif>
                    </cflock>
                </cfif>
            </cflock>
        </cfif>
    </cfloop>
</cffunction>

</cfcomponent>

from modelglue-framework.

Is there a timetable for when this bug might be fixed and committed to the repo?

from modelglue-framework.

@russ0519 - how did you tell MG to use your loader? Did you move the file aside and replace it with a new one using the existing name? I can try your code.

And, normally, my understanding is you only need a double check? E.g.:

<cfif not isloaded>
   <cflock exclusive>
       <cfif not isloaded>
             do the loading - no way for anything to get in here other than one at a time?
       </cfif>
     </cflock>
</cfif>

That would cut out a lock and an extra isloaded check?

from modelglue-framework.

We added the following to ColdSpring.xml

    <bean id="modelglue.ModuleLoaderFactory" class="ModelGlue.gesture.module.XMLModuleLoaderFactory">
        <constructor-arg name="modelGlueConfiguration"><ref bean="modelglue.modelGlueConfiguration" /></constructor-arg>
        <constructor-arg name="registeredClasses">
            <map>
                <entry key="XML">
                    <map><entry key="class"><value>com.companyName.ModelGlue.gesture.module.XMLModuleLoader</value></entry></map>
                </entry>
            </map>
        </constructor-arg>
    </bean>

from modelglue-framework.

Did you do this against the latest new Scaffolds branch, 3.2 RC X or 3.1.299?

from modelglue-framework.

@dskaggs @sipacate - what code should we be running (in production)? Ignoring this error, there are 3.2 RCXs, there is a newScaffolding branch (which is both ahead and behind of master), etc. Can something be released as gold so we know what the current good version is? And then we can patch from there if needed?

from modelglue-framework.

Sorry for dropping this. It's amazing what 2 small kids can do to my free time.

@dskaggs and I are going to put our heads together on this tomorrow and see where this died off. I'll post back with a status report after that.

from modelglue-framework.

Those kids still terrorizing you? ;)

from modelglue-framework.

I put Russ' fix into my local copy of the core framework late last week and all tests passed. I also took Dan W's modified version of it with one less lock/check pair and all tests passed with that version too. He and I were talking about this over the weekend and have some time scheduled today to do the same on his system to make sure we're both seeing the same test results. Assuming all the tests pass for him as they did for me, we'll get this change merged into newScaffolding branch for you to try out.

from modelglue-framework.

While the unit tests pass, the code that Russ and Brian pasted into the comments above still causes errors when I tested with the ModelGlue app that Russ set up to demonstrate the error. Dan and I will have to get together and figure out where the actual issue is on this. I'll let you guys know when we get a timeline together.

from modelglue-framework.

@russ0519: @sipacate and I did a little more digging with your sample app a bit ago. As it exists in your Git repo, the MG reload config setting is set to true. We were able to see errors coming back on most of the 20 requests kicked off by the home event.

However, when we set that setting to false, all 20 requests returned a valid timestamp with no errors. We even went so far as to kick off the process in one browser tab, and while that one was executing, issue a request with init=true in the URL in another tab. Both tabs had no errors.

All this was done with no changes having been made to the ModelGlue files in the newScaffolding branch.

At this point, we need some clarification on what you think needs to be fixed with regard to your sample app. Since the sample app appears to work when production settings are used (reload=false), we're sort of in no-man's land on how to proceed.

from modelglue-framework.

So what you are saying is that when we are developing we should not have it set to reload=true?

Or are you saying that when you are in development mode, you should not have multiple requests at once?

For us, we have some pages that kick off several ajax requests at once and as such break when in development mode.

I guess what we want is that even though the app is reloading the configuration, it should not get into a state in which it errors out - which is what seems to be happening. Basically, since reloading the configuration cause the MG to be in an unstable state, such reloading should not be allowed to occur while other requests are running, hence the locks that we've added.

from modelglue-framework.

Hmm. Well, I am going to take another look at this, but what's going on is deep inside the plumbing of MG. I need to get a good block of uninterrupted hours to figure out how to make this work.

from modelglue-framework.

@ghidinelli Yeah, out of the last 2 weeks, 4 or 5 have been snow days, so the kids are home and I can't get much done. As such, I'm more behind in my other 2 companies than usual. It's hard to get time for open source work these days.

Plus, my youngest got pinkeye, so he was home today.

This should begin to level out over the next few months. Honestly, I'm glad people are bringing this back up. It needs to be fixed permanently.

from modelglue-framework.

@dskaggs - if reload=false, do you believe this issue is fixed or do you and @sipacate need to investigate further? I can live without multiple requests locally under development if I can run safely in production.

from modelglue-framework.

From what I saw, I am inclined to believe that is correct. I got no errors whatsoever when the reload was set to false. I ran Russ' sample app in one window several times. On a couple of runs, I had a second window open that I ran the main event with a manual init=true to reload ModelGlue while the requests in the first window were executing. Neither of those windows produced any errors.

Obviously test this with your app before you put it on your production server to see if you see the same behavior with your app that we saw with Russ' sample app.

from modelglue-framework.

Good news - while I can reliably generate the original errors using the RC2 newScaffolding branch from a year ago, I am unable to trigger it using the current newScaffolding branch! I'm running the same jMeter test back to back against RC2 and the latest with 10 clients on the test app and me performing ?reinit=true in the browser.

I went one step further and did a full ?reset=true which clears out the App scope and recreates my beanfactory and model-glue. In those tests I'm still able to kick off some errors as the currently executing requests lose access to values as they are blown away. The errors are around the views/includes:

The template (test.cfm) was not found in any registered view mappings (/views,/views/generated).


The error occurred in C:/Users/brian/Documents/web/trunk-main/mgtest/ModelGlue3.2.RC4/gesture/view/ViewRenderer.cfc: line 81
Called from C:/Users/brian/Documents/web/trunk-main/mgtest/ModelGlue3.2.RC4/gesture/eventrequest/EventContext.cfc: line 689
Called from C:/Users/brian/Documents/web/trunk-main/mgtest/ModelGlue3.2.RC4/gesture/eventrequest/EventContext.cfc: line 286
Called from C:/Users/brian/Documents/web/trunk-main/mgtest/ModelGlue3.2.RC4/gesture/eventrequest/phase/Invocation.cfc: line 96
Called from C:/Users/brian/Documents/web/trunk-main/mgtest/ModelGlue3.2.RC4/gesture/eventrequest/EventContext.cfc: line 189
Called from C:/Users/brian/Documents/web/trunk-main/mgtest/ModelGlue3.2.RC4/gesture/ModelGlue.cfc: line 297
Called from C:/Users/brian/Documents/web/trunk-main/mgtest/ModelGlue3.2.RC4/gesture/ModelGlue.cfm: line 98
Called from C:/Users/brian/Documents/web/trunk-main/mgtest/index.cfm: line 74
79 :    <cfif not includeFound>
80 :        <cfthrow type="ViewRenderer.includeNotFound"
81 :                         message="The template (#arguments.view.template#) was not found in any registered view mappings (#arrayToList(_viewMappings)#)." />
82 :    </cfif>
83 :    

Overall this seems like it solves the problem of reiniting Model-Glue while under load. Passing the load test makes me confident enough to try it in production. I will report back after some pushes and let you know if it seems 100%.

Thanks for the hard work on this over the last year; I know solving these edge performance issues is not the most productive fun you could be having and I appreciate your help. Assuming all is well, I hope you can merge newScaffolding back into master and release an official 3.2!

from modelglue-framework.

One more bit - I ran @russ0519 sample app from a year ago with the Ajax calls and it does generate errors immediately when reload is true. If I set reload=false, it returns successfully even if I reinit in another browser window.

Does it make sense that manually passing a ?reinit would have different results than each request running reinit?

from modelglue-framework.

I spent 4 full days working on this. MAN there is a lot going on internally.

What I found is a fairly simple solution to the problem raised by @russ0519 . In the ModelGlue.cfm file located at /gesture/ModelGlue.cfm, there is a line (for me it was on line 85) that has the following statement:
<cfset mg.reset() />

If you remove this line, Russ's sample app with the concurrent ajax calls loads just fine with reload off.

The failures invoked during concurrent requests with reload=true, boiled down to the reset() function cutting the MG internal datastructures off at the knees.

While looking through this issue, I found that MG shipped with the Memoized functionality off. I spent a fair amount of time debugging this section and have made some improvements. At this point, 12 of the unit tests fail for Memoization. I understand why, but I need to get back to paying work for a minute. Next week. I'll circle back to updating Memoization such that all the unit tests pass, and Russ's sample app also passes. Then we'll have a release. Thanks for your patience.

from modelglue-framework.