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.