ORM interception in M6 kills my app

Communities ColdBox HMVC
1

I just upgraded from M5 to M6. Portions of my service layer extend the
new VirtualEntityService (hence BaseORMService) to be able to play
with ORM entities nicely, hence I hit the issues quickly that I
detailed in my the earlier post on ORM Helper changes.

My service layer architecture worked like a charm in M5 but one of the
ORM helper changes I just mentioned for M6 appears to spin my app out
of control. In M6, BaseORMService is now tying ORM event interception
to coldbox.system.orm.hibernate.EventHandler, and is enabling this
interception by default.

Now upon any Hibernate usage, I see Tracer messages for
announceInterception on preLoad and postLoad on any entity loaded. It
is dumping the arguments for those interceptions so is attempting to
utilize Hibernate entities well after I use them in my codebase. Any
lazy relationships generate a slew of Hibernate errors that "Session
is closed" (as it should) as it attempts to dump the dumped
output.

A simple user get screen just became 40megs to download with this
fully tracer dump mode on in Debug mode with the way I'm eager loading
data. Yikes! Needless to say my list screens listing 10-50 objects
just killed Coldfusion altogether (went into la la land, required
restart).

I turned off tracer panel to immediately fix my app from hanging,
however Tracer is essential in my situation as I use it for debugging
purposes during development. FOR NOW my immediate fix is edit core
codebase to turn off the default event handler in BaseORMService.cfc
by setting the default property = false and the init() param = false
as well. This has worked around the issue for now. (That way I don't
have to go to each CFC in my service layer to add the new init() param
to set it to false.)

1) I haven't much used announced interception so am unsure how to turn
off having those interceptions dump to Tracer panel. Is there a way
to prevent AnnounceInterception from doing this without disabling
Tracer panel altogether? It's nice to know about the custom intercept
points getting triggered but not nice to dump every single entity
repeatedly.

2) I'm not sure having event handling on by default in M6 was the
proper choice. I was already using event handler via the method set
up in M5 (via ormsettings.eventHandler calling the earlier provided
ORMEventHandler.cfc). This new technique seems to completely override
that earlier handler. Having this as default behavior really threw a
wrench into my existing application given their default behavior of
CFDUMPing each object to screen twice minimally (pre & post
events).

Luis - What is the best way to get not have these ORM events dumping
to Tracer panel w/o changing core Coldbox? I will eventually be tying
into these interception points so want them -- but absolutely cannot
be dumping the entire entity on each interception in Tracer!

Thanks,

-m

2

m,

I am a little at a loss of what is causing the issue, I am a little slow today :slight_smile:

Can you reword your entry as to why the event handling does this to your app?

Luis F. Majano
President
Ortus Solutions, Corp

ColdBox Platform: http://www.coldbox.org
Linked In: http://www.linkedin.com/pub/3/731/483
Blog: http://www.luismajano.com
IECFUG Manager: http://www.iecfug.com

3

I am a little at a loss of what is causing the issue, I am a little slow
today :slight_smile:

Hehe, it's that kind of day. Lemme boil it down.

My service layer:
UserService extends VirtualEntityService extends BaseORMService...
UserService.init() calls super.init( entityname = "user" ).

Upon upgrading to M6, all Hibernate events are now triggering
announceInterception on ORM events like preLoad / postLoad. This
happens either because: 1) BaseORMService by default set
eventHandling=true, so all ORM events are now Coldbox interception
points through coldbox/system/orm/hibernate/EventHandler.cfc
(regardless or ormsetting.eventHandler). OR 2) if ORM event handling
is enabled in ormsettings.eventhandler = that same EventHandler.cfc .

However, Tracer Debug panel is dumping each one of these
announceInterceptions, so is dumping the Hibernate entity on each
interception (which in turn causes session errors when dumping lazy
loaded relationships as the Hibernate session is long over).

Question:
For now I have disabled event handling altogether (both in ormsettings
and to BaseORMService init() call so eventhandling=false. However I
will soon be needing these custom interceptions AS WELL AS still want
my Tracer panel to be functional. Can I set it so the custom
interception point that is reported on Tracer not dump its arguments?
I'd like to know the custom interceptions were triggered but having
every Hibernate entity be dumped to Tracer panel twice (on each pre /
postLoad) is a quick way to kill the application.

For example, my user edit page normally is 315K w/ all Coldbox and
Coldfusion debugging on. With ORM interception and dumps on each
interception in Tracer, it is 42Megs on that same page request due to
42 announced interceptions (on 21 entities loading aka 21 rows of
data). Yikes.

Hope that is clearer...
-m

4

So the quetion then is what is dumping into the tracers? From where is this coming from would be the key here?

5

I experienced the same thing when I upgraded from M5 to M6. I ran back
to M5 and planned to wait for Gold but I'll try to look into it as
well next week unless it's figured out by then.

- Gabriel

6

Luis - After some additional study, let me retry boiling it all down
w/ some history. Apologies for being long winded but this seems to
be a rather big issue (and seems others have hit it) so I want to be
clear about it.

1) In my M5 application, I had enabled Hibernate events (via
ormsettings.eventHandling/eventHandler config options) to use a custom
CFC (model.ORMEventHandler) that extended the your original
coldbox.orm.hibernate.EventHandler. If you look at M5's version of
EventHandler, it had base methods for ORM events that were blank
except for your Autowire injection routines in preLoad(). Any methods
to trap ORM events needed to be overridden methods in the inheriting
class (my model.ORMEventHandler), meaning nothing was trapping ORM
events by default.

2) In M6, the new ORM event handler
(coldbox.orm.hibernate.EventHandler) now sends custom interception
messages for ORM events instead of blank methods. Great idea to tie
Hibernate events directly into Coldbox ones! Every ORM event now
triggers a custom interceptor message via AnnounceInterception().
All ORM events now have an interceptor message being sent by default,
and event handling is also enabled by default in BaseORMHandler as
well for some custom ORM events.

3) AnnounceInterception() happens to dump all arguments to Tracer in
ExtraInfo parameter (line 140 in coldbox.system.remote.ColdboxProxy,
passing arguments as second parameter). FYI, my application LogBox
logs to ColdboxTracerAppender in my Coldbox.cfc settings.

4) Because I had on Hibernate event handling to a CFC extending this
new EventHandler I immediately got hit with all the
announceInterception events for every Hibernate object loaded, with
preLoad and postLoad ORM events (triggered via announceInterception)
showing up in Tracer debug panel for every Hibernate object loaded
(meaning 2 ORM events were triggered for every row in a Hibernate
query).

5) All arguments (in this case, the ORM entities themselves) passed to
announceInterception got CFDUMPed to my Tracer panel in Debug mode.
Each entity loaded triggered two interceptor messages minimally
(ORMPreLoad & ORMPostLoad). This adds up to a lot of ORM entities
being dumped to Tracer panel.

6) Typical Hibernate entities have relationships to other entities
(lazily or eagerly loaded). Dumping a Hibernate entity is generally a
bad idea as all fetches are then performed recursively through the
relationships. (Kind of a short coming of CFDUMP on ORM entities, I
feel.)

7) Dumping every single entity multiples times (on both pre & postLoad
events) is basically CFDUMPing massive amounts of data for the most
basic of Hibernate queries. My Hibernate objects aren't particularly
complex but involve different multi-layer bi-directional relationships
that are eagerly loaded in a single query. CFDUMPing a single User
entity in my case turned a 300k page request into a *40meg* reguest as
CFDUMP recursively traversed the eagerly-fetched ORM relationships.

8) In addition, because these were ORM entities being utilized in an
interceptor message but outside of the original call, I would get a
stream of silent Coldfusion errors from Hibernate saying "lazy load
could not be performed - session is closed." triggered by the CFDUMP
on all lazy-fetched ORM relationships.

9) I want Tracer panel, I want ORM event handling, I do not want every
single ORM entity loaded dumped to Tracer panel repeatedly. Something
needs to change in this equation as it is unusable for what I consider
a pretty standard Coldbox developer setup (Hibernate with event
handling tied into Coldbox, Debug mode on, Tracer panel enabled).

Luis - Long story short, basically ColdboxProxy should not be passing
arguments to Tracer() if they are ORM entities. I'll try to write a
code snippit to try to identify a ORM object on the fly to insert
there if possible. I feel like you should trace the object name (that
this is entity "User") but not the entire ORM entity itself - unless
the user desires it.

Gabriel and any others using Hibernate event handling in M6 - to stop
the onslaught of dumped entities to Tracer panel, you can 1) disable
the tracer panel (debug settings in Coldbox.cfc), or 2) disable all
ORM event handling via ormsettings.eventhandler=false (most important)
plus pass eventhandling=false to all BaseORMService/
VirtualEntityService objects (has some add'l custom announcements like
postNew, preSave, postSave), or 3) comment out line 140 in
coldbox.system.remote.ColdboxProxy.cfc [core change], or 4) comment
out all methods in coldbox.orm.hibernate.EventHandler [core change].

For now I have ORM event handling off but will likely reenable it (as
I want to use them), so instead will comment out or modify line 140 in
ColdboxProxy core code.

-m

7

Getting something similar - page takes ages to load and then CF9.01 runs out of memory and falls over for me. Turn off debugging panel and everything is fine (but I miss it!!)

8

Ok, guys, blame me blame me!!

This has been tracked and squashed!! The thing here is that tracers where being pushed for everysingle interception via the proxy, which in my opinion it should not have. But anyways, that has been there since phew, who knows. I have removed it and it should all be good now. Now this side-effect is only seen on development debug mode.

Try now please and then I’ll make a 6.1 release

Luis F. Majano
President
Ortus Solutions, Corp

ColdBox Platform: http://www.coldbox.org
Linked In: http://www.linkedin.com/pub/3/731/483
Blog: http://www.luismajano.com
IECFUG Manager: http://www.iecfug.com

9

Ok, please confirm this bug is squashed so I can release M6.1

10

Issue is gone for me.

- Gabriel

11

Sorry Luis - been away for a few days, it’s squashed for me

12

M6.1 released, with little critical fixes, please try it.

Thanks

Luis F. Majano
President
Ortus Solutions, Corp

ColdBox Platform: http://www.coldbox.org
Linked In: http://www.linkedin.com/pub/3/731/483
Blog: http://www.luismajano.com
IECFUG Manager: http://www.iecfug.com

13

Everything seems to running smoothly - thanks :slight_smile: