tracker issue : CF-3132879

select a category, or use search below
(searches all categories and all time range)
Title:

True application exception is masked by CF's built-in Exception Handler code, resulting in Error while reading header

| View in Tracker

Status/Resolution/Reason: Closed/Withdrawn/

Reporter/Name(from Bugbase): Steven Erat / Steven Erat (StevenErat)

Created: 03/07/2012

Components: Core Runtime

Versions: 9.0.1

Failure Type: Non Functioning

Found In Build/Fixed In Build: 9.0.1 /

Priority/Frequency: Major / Some users will encounter

Locale/System: English / Windows 7

Vote Count: 1

Problem Description:
ColdFusion's default exception handler WEB-INF\exception\coldfusion\runtime\ApplicationException.cfm (and TemplateNotFoundException.cfm) make use of WEB-INF/exception/exception_en.xml and in turn WEB-INF/cftags/savecontent.cfm, which are all built-in to ColdFusion.

When an unhandled exception occurs and ColdFusion's built-in exception handler code is triggered in order to present the familiar blue screen showing the Robust Exception details, the CF exception handler attempts to  report on a variety of request information such as the date and time, or the referrer, or the stack trace as well as many other fields.  Part of that handling includes calls to cfsavecontent which is implemented as the custom tag in WEB-INF/cftags/.    The way in which the content is generated in the savecontent tag may cause ColdFusion to try to resolve some of those important error keys like browser, referrer, and stack trace by looking them up in various scopes including the CGI scope.

However, if the user has closed their browser, clicked away, or a network interruption occured, the TCP connection between the browser and the webserver connector may have been broken.   When ColdFusion attempts to resolve a CGI variable the request will ask the connector, and the connector will try to make use of the TCP handle back to the browser.  If the connection was terminated, then the connector may report an "Error while reading header <headername>" back to the request, which in turn gets logged by CF.

The problem there is that the original application error that was being handled by CF's built-in exception handlers is thrown away when ColdFusion tries to resolve one of the exception variables and tries to look in the CGI scope but instead encounters a dead TCP connection still held by the connector stub.  The original application exception is never logged, only the downstream "Error while reading header".

Users may never see this because the problem typically occurs with  a broken or closed browser session.

Related links about this issue:

http://stackoverflow.com/questions/9473252/why-does-a-coldfusion-implicit-setter-end-up-making-networking-calls/9607378#9607378
    http://corfield.org/blog/index.cfm/do/blog.entry/entry/isDefined_vs_structKeyExists
    http://www.coldfusionmuse.com/index.cfm/2009/8/6/examining.isDefined
    http://www.mail-archive.com/cf-talk@houseoffusion.com/msg196119.html
http://mail.pukkasoft.com/archives/?0::16828
http://www.houseoffusion.com/groups/cf-talk/thread.cfm/threadid:37354
http://forums.adobe.com/thread/790175

Steps to Reproduce:
Create a long running request.  It could just do something like sleep(120000) to sleep for 2 minutes. 
Make sure the page or cfadmin timeout permits it run that long.
After the sleep, do an isDefined on a key known to not exist in any scope, like isDefined("myUniqueKeyFoundNowhere");
Enable robust exceptions in CF Admin debug page.
Request that long running page from a browser.
Close the browser while request is sleeping.
Check the logs when the request is finished.

Actual Result:
Exception handler code built into CF blocks logging of true application error

Expected Result:
Application error is logged and handled properly with the built-in exception handler

----------------------------- Additional Watson Details -----------------------------

Watson Bug ID:	3132879

Deployment Phase:	Release Candidate

External Customer Info:
External Company:  
External Customer Name: StevenErat
External Customer Email:  
External Test Config: Reproduces on any platform with ColdFusion 7.x, 8.x, and 9.x.

Attachments:

Comments:

Stack Trace: # Created by JRun on 03/06 13:26:51 03/06 13:26:51 error Error while reading header S_UNABLE java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) ... at coldfusion.runtime.CgiScope.resolve(CgiScope.java:221) at coldfusion.runtime.CgiScope.containsName(CgiScope.java:301) at coldfusion.runtime.CgiScope.search(CgiScope.java:334) at coldfusion.runtime.NeoPageContext.searchScopes(NeoPageContext.java:766) ... at cfsavecontent2ecfm1472308084.runPage(E:\cf9_final\cfusion\wwwroot\WEB-INF\cftags\savecontent.cfm:11) at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:231) at coldfusion.filter.CFVariablesScopeFilter.invoke(CFVariablesScopeFilter.java:56) at coldfusion.tagext.lang.ModuleTag.doAfterBody(ModuleTag.java:352) at cfexception_en2exml1502993924.runPage(D:\JRun4\servers\cfusion\cfusion.ear\cfusion.war\WEB-INF\exception\exception_en.xml:52) at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:231) at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:416) ... at cfdetail2ecfm1809038875.runPage(D:\JRun4\servers\cfusion\cfusion.ear\cfusion.war\WEB-INF\exception\detail.cfm:35) ... at cfApplicationException2ecfm797577125.runPage(D:\JRun4\servers\cfusion\cfusion.ear\cfusion.war\WEB-INF\exception\coldfusion\runtime\ApplicationException.cfm:2) at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:231)
Comment by External U.
20256 | March 07, 2012 03:48:04 PM GMT
Note: I HAD TO REMOVE LINES FROM STACK TRACE BECAUSE WATSON WON"T LET ME ADD IT WITH MORE THAN 4000 CHARACTERS.
Comment by External U.
20257 | March 07, 2012 03:48:45 PM GMT
Cross reference #CF-3132889
Comment by External U.
20258 | March 07, 2012 04:06:52 PM GMT
Here's a small sample of searching through the logs for errors like this, all referencing variables in the error message that are part of the error handling template built-in to CF: Line 2185: 03/02 12:19:21 error Error while reading header S_ERROR_TITLE Line 2264: 03/02 12:19:21 error Error while reading header S_USER_MESSAGE Line 2343: 03/02 12:19:21 error Error while reading header S_DEBUGGING_MESSAGE Line 2422: 03/02 12:19:21 error Error while reading header S_ERROR_IN Line 2501: 03/02 12:19:21 error Error while reading header S_CALLED_FROM Line 2580: 03/02 12:19:21 error Error while reading header S_CANNOT_DETERMINE Line 2659: 03/02 12:19:21 error Error while reading header S_TRY_THE_FOLLOWING Line 22: 03/02 12:19:21 error Error while reading header S_ENABLE_ROBUST Line 101: 03/02 12:19:21 error Error while reading header S_OTHER_TRY Line 180: 03/02 12:19:21 error Error while reading header S_BROWSER Line 259: 03/02 12:19:21 error Error while reading header S_REMOTE_ADDRESS Line 338: 03/02 12:19:21 error Error while reading header S_REFERRER Line 417: 03/02 12:19:21 error Error while reading header S_DATE_TIME Line 496: 03/02 12:19:21 error Error while reading header S_STACK_TRACE
Comment by External U.
20259 | March 08, 2012 08:10:50 PM GMT
Its interesting that the original request template is not shown in the stack trace for any of these. I suspect that what is happening is that the request in error was forwarded to the exception handling template, thus leaving the context of the request template, showing only the exception handler templates in the stack.
Comment by External U.
20260 | March 08, 2012 08:13:48 PM GMT
ABLE TO REPRODUCE ON DEMAND WITH THESE STEPS: 1) Create a simple template with these 2 lines: <cfset sleep(120000)> <cfset x = isDefined('__FIND_ME___')> 2) On Windows, edit the configured IIS connector settings. recvtimeout=75 Uncomment recvtimeout and make it a shorter, unique value like 75. Enable verbose connector logging too. Restart the webserver to make it take effect. 3) Open Windows Services. Find World Wide Web Service. Prepare to stop it, but do not yet. 4) Open a new single instance of a browser and request the URL thru IIS to the template you saved in step 1 above. 5) About 10 seconds after the request starts to run (it will be in the sleep), stop the World Wide Web Publishing Service. (This forces a disconnect in the connection between CF and Connector) 6) Wait 3 minutes (more than the 120 seconds of sleep). Check the verbose connector log and the coldfusion-event.log. The event log will show the stack trace for "Error while reading Header" upstream of the CGI lookup. 03/08 22:49:44 error Error while reading header REMOTE_USER java.net.SocketException: Connection reset by peer: socket write error at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92) at java.net.SocketOutputStream.write(SocketOutputStream.java:136) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123) at jrun.servlet.jrpp.ProxyEndpoint.getHeader(ProxyEndpoint.java:760) at javax.servlet.http.HttpServletRequestWrapper.getHeader(HttpServletRequestWrapper.java:124) at javax.servlet.http.HttpServletRequestWrapper.getHeader(HttpServletRequestWrapper.java:124) at coldfusion.runtime.CgiScope.resolve(CgiScope.java:221) at coldfusion.runtime.CgiScope.resolveName(CgiScope.java:274) at coldfusion.runtime.Scope.get(Scope.java:60) at coldfusion.runtime.CfJspPage.ArrayGetAt(CfJspPage.java:941) at coldfusion.runtime.CfJspPage._arrayGetAt(CfJspPage.java:972) at coldfusion.runtime.CfJspPage._arrayGetAt(CfJspPage.java:967) at coldfusion.runtime.CfJspPage._arrayGetAt(CfJspPage.java:786) at coldfusion.runtime.CfJspPage._arrayGetAt(CfJspPage.java:770) at cfclassic2ecfm1779930769$funcSORTEDSCOPE.runFunction(C:\ColdFusion901\wwwroot\WEB-INF\debug\classic.cfm:876) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:472) at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47) at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:368) at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:55) at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:321) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:220) at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2582) at cfclassic2ecfm1779930769._factor16(C:\ColdFusion901\wwwroot\WEB-INF\debug\classic.cfm:699) at cfclassic2ecfm1779930769._factor20(C:\ColdFusion901\wwwroot\WEB-INF\debug\classic.cfm:685) at cfclassic2ecfm1779930769._factor27(C:\ColdFusion901\wwwroot\WEB-INF\debug\classic.cfm:568) at cfclassic2ecfm1779930769._factor30(C:\ColdFusion901\wwwroot\WEB-INF\debug\classic.cfm:10) at cfclassic2ecfm1779930769.runPage(C:\ColdFusion901\wwwroot\WEB-INF\debug\classic.cfm:1) at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:231) at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:416)
Comment by External U.
20261 | March 08, 2012 10:33:41 PM GMT
In my reproducible case, the stack points to the classic.cfm debug template, line 876, which corresponds to the last line here: <cffunction name="sortedScope" output="false"> <cfargument name="scope"> <cfset retVal=""> <cfset keys = structKeyArray(scope)> <cfset arraySort(keys,"text")> <cfloop index="x" from=1 to="#arrayLen(keys)#"> <cfset keyName = keys[x]> <cfset retVal = retVal & keyName & "="> <cftry> <cfset keyValue = CFDebugSerializable(scope[keyname])>
Comment by External U.
20262 | March 08, 2012 10:36:28 PM GMT
The verbose connector log shows: 1) Request started at 22:47:44 2012-03-08 22:47:44 jrISAPI[4600:4992] filtering /scratch/error_header.cfm (/scratch/error_header.cfm) HOST=cf9:98 2) The connector logging paused for 75 seconds (my rcvtimeout) then at 22:48:59 logged a jrConnect and jrRecv: 2012-03-08 22:47:44 jrISAPI[4600:4992] PROXY_GET_HEADER <- [908] 2012-03-08 22:47:44 jrISAPI[4600:4992] read/len/total 4/4/4 2012-03-08 22:47:44 jrISAPI[4600:4992] read/len/total 15/15/15 2012-03-08 22:47:44 jrISAPI[4600:4992] Acrobat-Version: <null> 2012-03-08 22:47:44 jrISAPI[4600:4992] sent/avail/result 4/4/4 2012-03-08 22:48:59 jrISAPI[4600:4992] 127.0.0.1 jrConnect [176] 2012-03-08 22:48:59 jrISAPI[4600:4992] sent/avail/result 4/4/4 2012-03-08 22:48:59 jrISAPI[4600:4992] 127.0.0.1:51011 is reachable 2012-03-08 22:48:59 jrISAPI[4600:4992] 127.0.0.1:51011 returned socket [176] to pool 2012-03-08 22:48:59 jrISAPI[4600:4992] jrRecv [908] timeout but server reachable so recv again And the event log showed an "Error while reading header" logged at "22:49:44", exactly 120 seconds after the request started where it entered the 120 second sleep.
Comment by External U.
20263 | March 08, 2012 10:45:26 PM GMT
We are having this problem daily in our production environment
Vote by External U.
20267 | January 18, 2013 10:40:27 AM GMT
Akhila, please add the test cases and relevant info..
Comment by Awdhesh K.
20264 | December 18, 2013 05:34:42 AM GMT
I have verified this on CF 11, and haven't found any issue. Can you try this on CF10 or 11 and let me know, if you are still facing this issue?
Comment by HariKrishna K.
20265 | December 10, 2014 01:21:57 AM GMT
Closing this bug, as i haven't heard back. We can re-open if you still hit this issue.
Comment by HariKrishna K.
20266 | July 08, 2015 09:42:14 PM GMT