"Sorry about that Adam, we'll have to take a deeper look at it. Uh-huh. Yeah. No, I totally understand. Okay then, I'll give you a call if I still can't replicate the problem."
Many of you recognize this phone call: the client has an issue and now you have to figure out why. I usually find issues like this much more frustrating than a cold hard error. At least with an error you get something concrete, you get facts about the problem. But these types of bugs, often problems with the application's logic, are the ones that sneak through to the client and are difficult to track down. I call this kind of bug No-see-ums, named after the teeny tiny mosquitoes commonly found in the Everglades.
Luckily for me, ColdFusion provides great tools for tracking down bugs like these. So armed with a fly swatter (error handling) and a can of Off (debugging), away I work at tracking down Adam's problem.
Off
I liken debugging to Off bug spray. Debugging tools will help you keep the bugs away, but they can still get through and bite you. ColdFusion provides two great ways to debug applications. The first is code based, through the use of tags like <cfdump>, <cftrace>, and <cftimer> and the function isDebugMode(); the second is through site-wide debugging.
Any developer who uses ColdFusion and another language no doubt misses the <cfdump> functionality in their other development environment. <cfdump> provides a color-coded graphical representation of complex objects, as well as the standard output of simple ones. This includes red components, blue structures, green arrays, purple queries, orange functions, gray XML, and black WDDX packets. <cftrace> displays and logs debugging data about an application at runtime. It can track logic flow, variable values, and execution time. <cftrace> can display its output at the end of the request or in the debugging section at the end of the request, or in Dreamweaver MX, in the Server Debug tab of the Results window. ColdFusion also logs all <cftrace> output to the file logs\cftrace.log, in the ColdFusion installation directory. <cftimer> calculates execution time for any chunk code and displays it along with any output produced by said code. isDebugMode() is a simple function that returns a Boolean expression indicating whether site-wide debugging is enabled or not.
ColdFusion makes it easy for developers to turn on site-wide debugging information. When site-wide debugging is enabled, pertinent information is appended to the end of every request, allowing the developer to see much of what is going on under the surface. What information the debugger will show can be set in the ColdFusion Administrator.
Even though ColdFusion debugging gives developers an enormous head start on creating bug-free applications, it's only a good defense. Many times you will still need to anticipate and take action to accurately eliminate bugs.
Ray Romano
Ray Romano has said, "I don't care how brave you are; you don't just rush in and kill an unknown bug. You got to figure it out first. I don't know if it has the gift of flight. What if it's a flyer? Then you got to close up hatches and stuff."
Bugs that generate a ColdFusion error are actually easy to identify, you just have to know what to look for.
When there is a ColdFusion error, it provides information about the error in an easy-to-access structure. The structure contains many keys, a lot of which are optional. (So be sure to check for their existence before referencing them.) The most recognizable key in the structure is the message key. It contains the default error message, usually shown in bold on a default error screen. If no error message is available, the key will contain an empty string. The detail key contains a detailed HTML message from ColdFusion and will help you determine which tag caused the error. ErrorCode will most likely contain an empty string, but you can supply a value for it through the errorCode attribute of <cfthrow> tags. ExtendedInfo is similar to ErrorCode in that it's usually an empty string. The exception to this rule is when the Type key, which contains the error's type, is the string application. Since ColdFusion is running Java under the hood, all errors are really Java errors. When an error is thrown, the Java Virtual Machine reports a servlet exception, which is stored in the RootCause key.
TagContext is one of the most robust error keys. It contains a stack of structures, where each element in the stack represents an open tag, and the structure in that element contains more detailed information about that tag. This structure will contain an ID key that represents the open tag. If the open tag is a custom tag, the value will read cfmodule, and if it is <cfscript>, it will read "??". The structure will also tell you which line of code the open tag can be found on, the Line key, and in which ColdFusion file it is in, the Template key. The raw Java stack trace for the error can be found in the Raw_Trace key. The structure also contains two peculiar keys. The first is Column, which is always 0, but is retained for compatibility with older versions of ColdFusion. The second is Type, which is always a string equal to CFML.
Other keys in the error structure show up depending on the type of error that has been thrown. For database errors, an additional five keys may be present. NativeErrorCode contains an error code submitted by the database driver. Because of the varying drivers that ColdFusion supports, the values for this will vary. However, if the driver does not submit a value, the default is -1, and if the query is a query of queries, the value will be 0. SQLState is very similar to NativeErrorCode in that it is derived from the database driver. It is code given to assist in the diagnosis of failing database operations, and its default is also -1. Sql contains the parsed SQL statement that was sent to the DBMS, while the string representation of the DBMS error is stored in the QuerryError key. If <cfqueryparam> tags were used in the query, the Where key will contain the name-value pair of each.
Another special key that may appear is the ErrNumber key, only found for expression exceptions. It represents an internal expression error number. Missing include errors add a MissingFileName key that gives the name of the missing file. Locking errors add an additional two keys: LockName and LockOperation. LockName contains the name of the affected lock. If the affected lock is unnamed, the value will be anonymous. LockOperation will contain the operation that failed or unknown.
Now that we know what we are dealing with (read "All hatches closed"), we can get offensive.
The Fly Swatter
ColdFusion provides a handful of mechanisms for handling errors. There are tags in the form of <cferror>, <cftry>, <cfcatch>, <cfthrow>, and <cfrethrow>; site-wide management in the ColdFusion Administrator; and (new to CFMX 7.0) there is an onError() function in the Application.cfc. Each method of error handling has its own strengths and weaknesses, but a combination of the methods provides the most complete solution.
Tags
While the scope of this article will not cover the ins and outs of the tags ColdFusion gives us to handle errors, a quick overview is necessary. <cferror> allows you to tell ColdFusion to run a particular template when an error of any given type is thrown. This is a great way to beautify the default error screen and give all pages, even ones that error, a consistent look and feel. <cftry> and <cfcatch> are used hand in hand. If an error occurs within a <cftry> construct, ColdFusion will immediately run the code in the corresponding <cfcatch> construct. Inside of a <cfcatch> construct you may also call <cfrethrow>, which will continue to throw the error as if there was no <cftry> and <cfcatch> clause at all. To make your own custom errors occur at any time, you can use the <cfthrow> tag. This is great for creating errors that pertain to just your application, not all applications in general, such as a business logic error. The attributes that make up <cfthrow> allow you to control all the main parts of an error, as explained earlier.
Administrator
ColdFusion also provides a site-wide error handler, set in the ColdFusion Administrator (under Server Settings/Settings at the bottom of the page). This setting allows you to provide a relative template path, which ColdFusion will execute when an error occurs. This template could do things such as send the sites administrator an e-mail with the error details, or just be used to dumb-down the errors that an end user sees.
Application.cfc
In ColdFusion MX 7.0 Macromedia introduced us to the Application.cfc. This upgrade to the Application.cfm/onRequestEnd.cfm also gave us developers ways to control many aspects of our applications. This control is implemented through specially named functions that ColdFusion automatically calls at the appropriate time. Of the most interest to us today is onError(). Any code placed in the onError() function in Application.cfc will run when the application errors. From this central location, developers can forward errors to the appropriate parties, redirect users to superficial error pages, and log errors. ColdFusion passes two arguments to the onError() function when it calls it (thus you should always have two <cfargument> tags in your onError() function). The first argument is an error structure, just like the one described earlier. The second argument is a string that contains the name of the Application.cfc method, if any, in which the error occurred. This argument has special implications for errors that happen in the onSessionEnd() and onApplicationEnd() functions. onSessionEnd() is fired when a session time-out setting is reached for a user's session, or, if using J2EE sessions, the user closes the browser. The onApplicationEnd() function is run when the server times out or is shut down. Because users are not requesting data from ColdFusion when these functions run, they cannot see any errors the functions may throw, and, because of this, logging errors that come from these functions is crucial.
In addition to onSessionEnd() and onApplicationEnd(), Application.cfc implements their opposites, onSessionStart() and onApplicationStart(). onSessionStart() fires when a new session is created by a user, including ColdFusion event gateway sessions. onApplicationStart() is triggered when the application first starts - either when the first request for a page is processed or the first CFC method is invoked by an event gateway instance, Flash Remoting request, or a Web service invocation. It's great for setting application-wide variables, such as the names of data sources or the location of mail servers.
As stated before, Application.cfc contains a replacement for Application.cfm and onRequestEnd.cfm. The onRequestStart() function runs when ColdFusion receives an HTTP request, a message to an event gateway, a SOAP request, or a Flash Remoting request. Following the completion of onRequestStart(), onRequest() will run. This function can contain the main display of a page. For example, this would be a good place to put all the core files for a Fusebox application. (For more information on Fusebox see www.fusebox.org/.) onRequestEnd() runs after all pages and CFCs in the request have been processed.
Order of Operations
Between all the new functions of the Application.cfc, error handling techniques, and debugging, it gets a little difficult to follow what ColdFusion is going to process and when. Here is a quick rundown of how ColdFusion processes requests:
- CFC initialization code at the top of Application.cfc
- onApplicationStart(), if not run before for current application
- onSessionStart(), if not run before for current session
- onRequestStart()
- onRequest(), or the requested page if there is no onRequest() method
- onRequestEnd()
Also ColdFusion could have an error at anytime. ColdFusion executes its error handling in the following order:
- <cfcatch>, if present and if an error happens within a <cftry>
- onError(), if the application has an Application.cfc file with onError() within it
- <cferror>, if present and if exception type is not "request"
- ColdFusion Administrator's Site-wide Error Handler, if defined
- <cferror>, if present, with exception type of "request"
- Display standard error
I have finally found the bug that Adam called me about earlier. Let me tell you, it was difficult to track down. Among all the tools I have in ColdFusion, it still took me a long time to find the problem.
The reason Adam's problem was difficult to track down was because of what I will refer to as a "chain with nesting." I call it that because I found the error in a sequence of CFC function calls (many of which make a request to the database based on the value passed into them) in which each function receives arguments that are part of the results of a previous function call. To make matters worse, some of the functions in the chain call upon other functions internally, which are located in different components and sometimes create their own chain of calls. If one function returns the wrong result due to a bad query or perhaps some bad math, it could completely throw off everything all the way down the chain. This scenario often happens in large projects, especially those that are object-oriented or pseudo object-oriented.
To help myself out of these predicaments, I have put together a little framework using many of the components we have learned about today. The end result is a stack (array) of each function call, placed in the order they were processed. Each function call gets its passed-in arguments logged (important because ColdFusion, as does many programming languages, destroys a functions arguments once the function finishes executing), its results logged, as well as basic information such as when the function was executed and how long it took to execute.
Since Adam's application is very complex, I have created a much smaller, simpler version of the problem, one you can look at, and, if so desire, easily implement in your own application.
This example randomly picks one of 10 phrases and reverses it. It's actually quite silly, much like all my bug jokes so far, but should give you a good idea of where I'm coming from.
Listing 1 shows the file the user will request. It's very straightforward and creates a small chain of function calls on line 4; it also instantiates the CFC shown in Listing 2.
Listing 2 is a component with two functions. The first, getPhrase(), will return a phrase based on the passed-in phraseNumber. If no phraseNumber is passed in, it will randomly pick a number. reversePhrase() asks getPhrase() for five random phrases and reverses and returns the fifth. The code of interest is the super.onCall() calls on lines 6 and 30, as well as the super.onResult() calls on lines 23 and 36. In this case "super" is a keyword that refers to Application.cfc (see Listing 3), since test.cfc extends Application.cfc (line 1, Listing 2).
Listing 3 is where the magic happens. When the user makes a request, based on the order of operations discussed before, the first bit of code ColdFusion processes is the onRequestStart() function. This creates an empty one-dimensional array called the cfcStack that will be accessed later in the request. Next index.cfm is run, which calls on my getPhrase() and reversePhrase() functions. Each of those functions call onCall() and onResult(), which log and stack what is going on in each function call. ColdFusion then processes the onRequestEnd() function, which checks to see if debugging is enabled and, if so, <cfdump>s the cfcStack.
This allows me to see each function that was called, in the order that it was called, what parameters it had to work with, and what results it returned. Notice the use of reserved functions described above onRequestStart() and onRequestEnd() as well as my own functions onCall() and onResult() within the Application.cfc.
I also added an onError() function, which in the case of an error would e-mail me the cfcStack as well as all the error information, and, if debugging is on, <cfrethrow> the error so I can see it immediately on the screen.
Just by taking a quick look at the cfcStack that is being dumped at the end of the request, I can tell if each function individually is behaving properly, as well as see if each one is fitting in with the parts of the whole request.
This simple <cfdump> is what led to this phone call: "Hey Adam, yeah, should be good to go. Alright man, thanks a lot. I hope you have a good weekend. Oh you're going there? Well have fun, and bring your bug spray; it can be pretty nasty this time of year."