tracker issue : CF-3132889

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

Implicit Setters on Entities are sometimes unresolved and CF searches CGI scope causing Error while reading header

| View in Tracker

Status/Resolution/Reason: Closed/Fixed/

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

Created: 03/07/2012

Components: Language, CF Component

Versions: 9.0.1

Failure Type: Non Functioning

Found In Build/Fixed In Build: 9.0.1 / CF10_Update14

Priority/Frequency: Major / Some users will encounter

Locale/System: English / Windows 7

Vote Count: 7

Problem Description:

Discussed at length here: 
http://stackoverflow.com/questions/9473252/why-does-a-coldfusion-implicit-setter-end-up-making-networking-calls/9607378#9607378



I have found that in ColdFusion 9.01, sometimes calls to implicit setters causes ColdFusion to try to resolve the setter method as though it were a property, and it will look into the CGI scope to try to find it.  If the user browser has disconnected, closed, clicked-away, etc, then  the CGI lookup may produce "error Error while reading header <property>", as described in issue 3132879.

EXAMPLE (Mock Code):
I have the following entity shown here (partly):

component persistent="true" table="myTable" output="false" extends="myBaseClass" {
property name="myProperty" column="myProperty" type="date" ormtype="timestamp";

Notice that it extends myBaseClass, which is shown (partly) here:

component {
public void function doSomething(){
    if (hasProperty('myProperty'))
        setMyProperty(now());
}

On some occasions when a template is requested which uses the entity, the template request appears to hang in the browser indefinitely with address bar spinning. Later when viewing the logs, I would find a related entry for the request showing the "error while reading header".

                03/06 13:45:52 error Error while reading header SETMYPROPERTY
            java.net.SocketTimeoutException: Read timed out
            at java.net.SocketInputStream.socketRead0(Native Method)
            ...
            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 cfmybaseclass2ecfc1915167844$funcDOSOMETHING.runFunction(X:\MyApp\myBaseClass.cfc:8)
            ...                
            at coldfusion.orm.hibernate.HibernateEventHandler.onFlushDirty(HibernateEventHandler.java:130)
            ...                
            at coldfusion.orm.hibernate.HibernatePersistenceManager.onCommit(HibernatePersistenceManager.java:950)
            ...
            at cfsomecomp2ecfc1707726523$funcRUN.runFunction(X:\MyApp\SomeComp.cfc:131)

This stack trace tells me that ColdFusion was trying to resolve an implicit setter and tried to find it in the CGI scope by asking the connector for an HTTP request header of the same name.

To me, trying to resolve an implicit getter by searching the CGI scope for the Request Header seems like a ColdFusion defect.

 
Any Workarounds:

Set the entity property directly, don't use the implicit setter.  In the above example code replace setMyProperty(now()); with myProperty = now();

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

Watson Bug ID:	3132889

Deployment Phase:	Release Candidate

External Customer Info:
External Company:  
External Customer Name: StevenErat
External Customer Email:  
External Test Config: Here is a truncated stack trace.  The entity has a property modifiedOn, and the implicit setter is called in the base class in an implicit setter SetModifiedOn, and the setter is shown in the error

regarding header after a CGI lookup after ORM.   



03/06 13:45:52 error Error while reading header SETMODIFIEDON



java.net.SocketTimeoutException: Read timed out



                at java.net.SocketInputStream.socketRead0(Native Method)



                at java.net.SocketInputStream.read(SocketInputStream.java:129)



...



                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 cfbase2ecfc1915167844$funcPREUPDATE.runFunction(D:\PRIVATE\base.cfc:8)

...



                at coldfusion.orm.hibernate.HibernateEventHandler.invokeMethod(HibernateEventHandler.java:245)



                at coldfusion.orm.hibernate.HibernateEventHandler.invokeInterceptorMethod(HibernateEventHandler.java:190)



                at coldfusion.orm.hibernate.HibernateEventHandler.onFlushDirty(HibernateEventHandler.java:130)



                at org.hibernate.event.def.DefaultFlushEntityEventListener.invokeInterceptor(DefaultFlushEntityEventListener.java:372)

...



                at org.hibernate.event.def.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:219)



                at org.hibernate.event.def.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:99)



                at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)



                at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1206)



...



                at coldfusion.tagext.sql.TransactionTag.doEndTag(TransactionTag.java:300)



                at cfivansProcessor2ecfc1707726523$funcPROCESSPOLICYREQUESTS.runFunction(D:\PRIVATE\myProcessor.cfc:131)

...



                at cfmyProcessor2ecfc1707726523$funcPROCESSBATCH.runFunction(D:\PRIVATE\myProcessor.cfc:44)

...



                at cfmyThreadManager2ecfc1645989653$func_CFFUNCCFTHREAD_CFMYTHREADMANAGER2ECFC16459896531.runFunction(D:\PRIVATE\myThreadManager.cfc:57)

Attachments:

Comments:

Today we are also seeing this behavior with implicit getters too, in a template that uses implicit setters/getters, but is not an ORM entity. Again, the stack is trying to resolve an implicit getter to the CGI scope, and tries going back to the connector stub request handle. In this particular example for the stack below, the browser received an immediate response from the webserver with a 503. The request was initiated anyway, but the 503 had already disconnected the TCP connection from the browser. 03/08 15:07:32 error Error while reading header GETXSDDOC java.net.SocketException: Software caused connection abort: 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 javax.servlet.http.HttpServletRequestWrapper.getHeader(HttpServletRequestWrapper.java:124) at coldfusion.thread.HttpServletRequestWrapper.getHeader(HttpServletRequestWrapper.java:295) 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 coldfusion.runtime.NeoPageContext.findAttribute(NeoPageContext.java:638) at coldfusion.runtime.CfJspPage._get(CfJspPage.java:296) at coldfusion.runtime.CfJspPage._get(CfJspPage.java:283) at coldfusion.runtime.CfJspPage._get(CfJspPage.java:271) at cfmyXmlValidator2ecfc1015952179$funcVALIDATEXML.runFunction(X:\PRIVATE\myXmlValidator.cfc:24)
Comment by External U.
20240 | March 08, 2012 08:23:06 PM GMT
This evening we were able to reproduce the problem. We observed these errors getting logged in correlation with a request that should run in less than 15 seconds, but sometimes takes almost exactly 5 minutes. Every time it rungs longer than the 15 seconds, it runs 5 minutes. We generated a thread dump during that 5 minutes, and found one of our cfthreads in BLOCKED state. "cfthread-4" prio=5 tid=115 BLOCKED at java.io.BufferedInputStream.read(Unknown Source) at jrun.servlet.jrpp.ProxyEndpoint.readFully(ProxyEndpoint.java:581) at jrun.servlet.jrpp.ProxyEndpoint.readFully(ProxyEndpoint.java:573) at jrun.servlet.jrpp.ProxyEndpoint.readInt(ProxyEndpoint.java:591) at jrun.servlet.jrpp.ProxyEndpoint.readString(ProxyEndpoint.java:620) at jrun.servlet.jrpp.ProxyEndpoint.getHeader(ProxyEndpoint.java:762) at javax.servlet.http.HttpServletRequestWrapper.getHeader(HttpServletRequestWrapper.java:124) at javax.servlet.http.HttpServletRequestWrapper.getHeader(HttpServletRequestWrapper.java:124) at coldfusion.thread.HttpServletRequestWrapper.getHeader(HttpServletRequestWrapper.java:295) 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 coldfusion.runtime.NeoPageContext.findAttribute(NeoPageContext.java:638) .. at coldfusion.runtime.CfJspPage._get(CfJspPage.java:271) at cfbase2ecfc946922667$funcPREUPDATE.runFunction(X:\PRIVATE\PATH\entities\base.cfc:8) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:472) at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:405) ... at coldfusion.orm.hibernate.HibernateEventHandler.onFlushDirty(HibernateEventHandler.java:130) at org.hibernate.event.def.DefaultFlushEntityEventListener.invokeInterceptor(DefaultFlushEntityEventListener.java:372) .. at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1206) ... at coldfusion.tagext.sql.TransactionTag.doEndTag(TransactionTag.java:300) at cfmyProcessor2ecfc777518073$funcPROCESSPOLICYREQUESTS.runFunction(X:\PRIVATE\PATH\myProcessor.cfc:126) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:472) .. at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2582) at cfmyProcessor2ecfc777518073$funcPROCESSBATCH.runFunction(X:\PRIVATE\PATH\myProcessor.cfc:44) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:472) .. at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2360) at cfmyThreadManager2ecfc1596809465$func_CFFUNCCFTHREAD_CFMYTHREADMANAGER2ECFC15968094651.runFunction(X:\PRIVATE\PATH\myThreadManager.cfc:59) ... at coldfusion.thread.Task.run(Task.java:140) at coldfusion.scheduling.ThreadPool.run(ThreadPool.java:211) at coldfusion.scheduling.WorkerThread.run(WorkerThread.java:71)
Comment by External U.
20241 | March 08, 2012 08:29:43 PM GMT
Putting the pieces of the picture together, I believe what is happening is the request is executing an implicit getter or setter, but somehow CF is unable to resolve the the object scope having it, so it starts looking up in the other scopes. It hits the CGI scope, and the server tries to get request header information from the connector, but the connector has already broken the TCP communication, but CF waits for a response from the connector for 5 minutes (300 seconds). When that 5 minutes is reached, the "Error while reading header" message is reported as part of an exception. It could be that the 300 seconds is coming from the connector property: #recvtimeout=300 <number of seconds to wait on a socket receive to a jrun server> The only other setting with default value of 300 seconds I found was from the jrun.xml setting: <attribute name="threadWaitTimeout">300</attribute> But that is not likely the timeout being encountered since that setting only regards queued requests waiting to run, not executing requests.
Comment by External U.
20242 | March 08, 2012 08:41:27 PM GMT
I'm able to replicate this.
Vote by External U.
20248 | August 22, 2012 04:09:50 PM GMT
+1 needs to be fixed. -- Adam
Vote by External U.
20249 | April 01, 2013 04:19:19 PM GMT
Please fix this. This is unacceptable
Vote by External U.
20250 | April 02, 2013 12:57:26 PM GMT
i confirmed a similar issue however i think i resolved it. running on CF 9,0,1,274733 enterprise on windows 2008 r2 i discovered the failed calls to getters; these same calls worked fine on 9,0,2,282541 enterprise on windows 7. the getter errors only occured however if they were directly in a <cfreturn call in a method being called from the constructor. so my init method called a few setters, then called a few methods that were using getter calls directly in the <cfreturn statement like this: <cfreturn loadItem(uri=getArchiveUri()) /> If i changed this call to: local.result = loadItem(uri=getArchiveUri()); and then called <cfreturn local.result /> everything was fine. FWIW i am using the createObject() .init old school call to fire the contstructor i am not using the new operator.
Comment by External U.
20243 | April 18, 2013 08:25:39 PM GMT
while i would prefer to just have my client upgrade to 9.0.2 where i have confirmed this doesn't seem to be an issue, i cannot get everyone to upgrade. please fix
Vote by External U.
20251 | April 18, 2013 08:26:41 PM GMT
Jon B indicates that he does not find the problem to happen in 9.0.2. Does anyone know if it has in fact been fixed? The status here still says "to fix". Also, John, do you know if it was in the base 9.0.2 or have you applied the CHF1 for it? (There's no mention of this bug being fixed either in the original 9.0.2 release notes nor in the CHF1.) For those who may be tempted to consider that (before or after that confirmation), do note that 9.0.2 is a complete installer, not an updater. So you would have to uninstall 9.0 or 9.0.1, then install 9.0.2 (and then do any needed hotfixes, cumulative hotfixes, and security fixes for 9.0.2 since it was release in May 2012). Also, if you're on CF Enterprise, be sure to export your CF Admin settings with the ColdFusion Archive (CAR) mechanism provided in the CF Admin. Those on Standard have no such option, so be aware that you will need to document and manually migrate the 9.0/9.0.1 admin settings into 9.0.2 if you make that upgrade--and don't do it if you use Verity. That's the main reason 9.0.2 was created, as a new installer of CF9 that did not include it (but did include all the hotfixes for 9.0.1 as of May 2012, when CF10 was released, where Verity was also removed.) Hope that extra info may help someone who sees this and thinks, "oh, ok. we'll just get 9.0.2 and see if that solves it." Until we get confirmation from Adobe and/or others, just beware that taking that step will not be trivial. If 9.0.2 DOES have the needed fix for this, then it will certainly be worth the effort to upgrade, for those with the problem.
Vote by External U.
20252 | July 08, 2013 02:17:20 PM GMT
Doh, I realize now that I should have put my comment (with the vote) in here instead. Would be a lot easier to read and not full the right nav bar. Sorry. If someone from Adobe can do that for me, removing that text from there and placing it here, I'd appreciate it. It doesn't seem I can edit the vote text once posted.
Comment by External U.
20244 | July 08, 2013 02:18:56 PM GMT
=== Copying the comment by Charlie from Votes section === Jon B indicates that he does not find the problem to happen in 9.0.2. Does anyone know if it has in fact been fixed? The status here still says "to fix". Also, John, do you know if it was in the base 9.0.2 or have you applied the CHF1 for it? (There's no mention of this bug being fixed either in the original 9.0.2 release notes nor in the CHF1.) For those who may be tempted to consider that (before or after that confirmation), do note that 9.0.2 is a complete installer, not an updater. So you would have to uninstall 9.0 or 9.0.1, then install 9.0.2 (and then do any needed hotfixes, cumulative hotfixes, and security fixes for 9.0.2 since it was release in May 2012). Also, if you're on CF Enterprise, be sure to export your CF Admin settings with the ColdFusion Archive (CAR) mechanism provided in the CF Admin. Those on Standard have no such option, so be aware that you will need to document and manually migrate the 9.0/9.0.1 admin settings into 9.0.2 if you make that upgrade--and don't do it if you use Verity. That's the main reason 9.0.2 was created, as a new installer of CF9 that did not include it (but did include all the hotfixes for 9.0.1 as of May 2012, when CF10 was released, where Verity was also removed.) Hope that extra info may help someone who sees this and thinks, "oh, ok. we'll just get 9.0.2 and see if that solves it." Until we get confirmation from Adobe and/or others, just beware that taking that step will not be trivial. If 9.0.2 DOES have the needed fix for this, then it will certainly be worth the effort to upgrade, for those with the problem.
Comment by Rupesh K.
20245 | July 15, 2013 07:04:54 AM GMT
Thanks for bringing that over, Rupesh. (Hopefully you'll be able to next remove it from the "vote" also.) So on the topic, I want to add as well that in speaking with Rupesh separately, he indicated that the bug is still marked as "to fix" because they have not been able to reproduce it. So while Jon B suggested it seemed not to happen for him in 9.0.2, it doesn't seem anything was done specifically in 9.0.2 to address this. So Jon, can you report if it ever happened again? If not, are you sure you still had getter/setters which you had not tweaked per Steven's recommendation here? If you do, and they no longer fail, then we just don't know if the solution is indeed 902 or just that the condition to cause the failure hasn't happened again for you. I do so wish we could get to the bottom of this. I have a client who is hit by it a couple of times a month, and with very high traffic, it can be a real sore spot when it starts hanging up threads.
Comment by External U.
20246 | July 15, 2013 08:02:59 AM GMT
This is a critical bug. Please fix.
Vote by External U.
20253 | August 22, 2013 03:57:44 PM GMT
Just a heads up for everyone: We just moved over to 9.0.2 with all fixes - and we are still seeing this issue.
Comment by External U.
20247 | August 22, 2013 03:58:22 PM GMT
Please fix soon. We're seeing this error a lot in our production environment.
Vote by External U.
20254 | December 24, 2013 09:28:19 AM GMT