Another CFLOG/JSON Tip

Almost a year ago I blogged about how I like to use a combination of cflog and serializeJSON as a way to quickly log complex data. I’ve often said I’m a “log every single darn thing” type of debugger. It may be messy - but it is my preferred way to see what’s going on in my ColdFusion application. Last week I found another interesting use for this technique.

I was trying to diagnose an odd performance issue I was having with Model-Glue. (If you are curious, you can read about it here.) While I was chasing down the issue I was littering Model-Glue code with a bunch of cflog statements. One problem I ran into though was figuring out what a particular CFC instance actually was. So for example, imagine your method looks like this:

<cffunction name="makeCool"> <cfargument name="person" type="person">

In the above method signature, my method takes a person argument. Person just so happens to be an interface with implementors like Geek, Nerd, Supermodel. You get the idea. I ran into code like this and wasn’t quite sure what the actual implementor was. It then occurred to me I could do this:

<cflog file="mylog" text="person=#serializeJSON(getMetadata(arguments.person))#">

Note I’m not serializing the CFC but the call to getMetadata. This returns something like so:

"Information","jrpp-282","09/24/10","11:50:53","MAVERICK","eventRequestPhase: preload {""NAME"":""ModelGlue.gesture.eventrequest.phase.Initialization"",""FULLNAME"":""ModelGlue.gesture.eventrequest.phase.Initialization"",""FUNCTIONS"":[{""ACCESS"":""private"",""NAME"":""load"",""RETURNTYPE"":""void"",""PARAMETERS"":[{""HINT"":""I am the event context to use for loading. Duck typed for speed. Should have no queued events, but this isn't checked (to save time)."",""NAME"":""eventContext""}],""HINT"":""I perform the loading for this phase."",""OUTPUT"":false},{""NAME"":""execute"",""RETURNTYPE"":""void"",""PARAMETERS"":[{""HINT"":""I am the event context to act upon. Duck typed for speed. Should have no queued events when execute() is called, but this isn't checked (to save time)."",""NAME"":""eventContext""}],""HINT"":""Executes the request phase."",""OUTPUT"":false}],""HINT"":""Represents the beginning of the Model-Glue lifecycle. Execution only does work when Model-Glue is not initialized."",""PATH"":""C:\\projects\\newHotness\\frameworks\\modelglue\\ModelGlue\\gesture\\eventrequest\\phase\\Initialization.cfc"",""EXTENDS"":{""NAME"":""ModelGlue.gesture.eventrequest.phase.ModuleLoadingRequestPhase"",""FULLNAME"":""ModelGlue.gesture.eventrequest.phase.ModuleLoadingRequestPhase"",""FUNCTIONS"":[{""ACCESS"":""private"",""NAME"":""load"",""RETURNTYPE"":""void"",""PARAMETERS"":[{""HINT"":""I am the event context to use for loading. Duck typed for speed. Should have no queued events, but this isn't checked (to save time)."",""NAME"":""eventContext""}],""HINT"":""I perform the loading for this phase."",""OUTPUT"":false},{""OUTPUT"":false,""NAME"":""init"",""PARAMETERS"":[{""HINT"":""I am the factory through which module loaders may be attained."",""REQUIRE"":true,""NAME"":""moduleLoaderFactory""},{""HINT"":""I am the list of XML modules to load as part of this phase."",""NAME"":""modules"",""TYPE"":""array"",""REQUIRED"":true}]},{""ACCESS"":""private"",""NAME"":""loadModules"",""PARAMETERS"":[{""NAME"":""modelglue""}],""HINT"":""Loads modules associated with this phase."",""OUTPUT"":false}],""HINT"":""Abstract of an execution phase that loads modules."",""PATH"":""C:\\projects\\newHotness\\frameworks\\modelglue\\ModelGlue\\gesture\\eventrequest\\phase\\ModuleLoadingRequestPhase.cfc"",""EXTENDS"":{""NAME"":""ModelGlue.gesture.eventrequest.EventRequestPhase"",""FULLNAME"":""ModelGlue.gesture.eventrequest.EventRequestPhase"",""FUNCTIONS"":[{""NAME"":""setup"",""RETURNTYPE"":""void"",""PARAMETERS"":[{""HINT"":""I am the event context to use for loading. Duck typed for speed. Should have no queued events, but this isn't checked (to save time)."",""NAME"":""eventContext""},{""HINT"":""Prefix for name of lock to use for setup"",""NAME"":""lockPrefix"",""TYPE"":""string"",""REQUIRED"":true},{""HINT"":""Timeout for setup lock"",""NAME"":""lockTimeout"",""TYPE"":""numeric"",""REQUIRED"":true}],""HINT"":""I make sure the phase is loaded exactly once."",""OUTPUT"":false},{""ACCESS"":""private"",""NAME"":""load"",""RETURNTYPE"":""void"",""PARAMETERS"":[{""HINT"":""I am the event context to use for loading. Duck typed for speed. Should have no queued events, but this isn't checked (to save time)."",""NAME"":""eventContext""}],""HINT"":""I perform the loading for this phase."",""OUTPUT"":false},{""NAME"":""execute"",""RETURNTYPE"":""void"",""PARAMETERS"":[{""HINT"":""I am the event context to act upon. Duck typed for speed. Should have no queued events when execute() is called, but this isn't checked (to save time)."",""NAME"":""eventContext""}],""HINT"":""Executes the request phase."",""OUTPUT"":false}],""HINT"":""I represent a phase inside of an event request. I'm basically a Command script for how this phase should execute."",""PATH"":""C:\\projects\\newHotness\\frameworks\\modelglue\\ModelGlue\\gesture\\eventrequest\\EventRequestPhase.cfc"",""EXTENDS"":{""PATH"":""C:\\ColdFusion9\\wwwroot\\WEB-INF\\cftags\\component.cfc"",""NAME"":""WEB-INF.cftags.component"",""FULLNAME"":""WEB-INF.cftags.component"",""TYPE"":""component""},""OUTPUT"":false,""TYPE"":""component""},""OUTPUT"":false,""TYPE"":""component""},""OUTPUT"":false,""TYPE"":""component""}"

That one is a bit large - but you can see in the beginning the Name value can tell you right away what the CFC actually is. I ran into this 4 or 5 times while digging into Model-Glue and it was pretty darn helpful.

Raymond Camden's Picture

About Raymond Camden

Raymond is a developer advocate. He focuses on JavaScript, serverless and enterprise cat demos. If you like this article, please consider visiting my Amazon Wishlist or donating via PayPal to show your support. You can even buy me a coffee!

Lafayette, LA https://www.raymondcamden.com

Comments