ColdFusion 9.0.1  -  Bug 3132889

Created on Wednesday, March 7, 2012

Login for more options

Title

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

Description

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();

Test Configuration

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)

App Language(s) English
OS Language(s) English
Platform(s) Windows 7
Browser(s)

Notes (8)

  • mark.mandel

    2:28:22 PM GMT+00:00 Aug 22, 2013

    Just a heads up for everyone:
    We just moved over to 9.0.2 with all fixes - and we are still seeing this issue.

  • carehart

    6:32:59 AM GMT+00:00 Jul 15, 2013

    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.

  • Rupesh Kumar

    5:34:54 AM GMT+00:00 Jul 15, 2013

    === 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.

  • carehart

    12:48:56 PM GMT+00:00 Jul 8, 2013

    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.

  • Jon Briccetti

    6:55:39 PM GMT+00:00 Apr 18, 2013

    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.

  • StevenErat

    6:11:27 PM GMT+00:00 Mar 8, 2012

    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.

  • StevenErat

    5:59:43 PM GMT+00:00 Mar 8, 2012

    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)

  • StevenErat

    5:53:06 PM GMT+00:00 Mar 8, 2012

    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)

Duplicate ID
Reported By StevenErat

Status

State Closed
Status Fixed
Reason

Importance

Priority 3-High
Frequency Some users will encounter
Failure Type Non Functioning
Product Area CFComponent

Build

Found In Build 9.0.1
Fixed In Build 287363

Attachments (0)

No Files Attached

Votes (7)

  • Mitch McKenzie

    6:58:19 AM GMT+00:00 Dec 24, 2013

    Please fix soon. We're seeing this error a lot in our production environment.

  • mark.mandel

    2:27:44 PM GMT+00:00 Aug 22, 2013

    This is a critical bug. Please fix.

  • carehart

    12:47:20 PM GMT+00:00 Jul 8, 2013

    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.

  • Jon Briccetti

    6:56:41 PM GMT+00:00 Apr 18, 2013

    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

  • henrylearn2rock

    11:27:26 AM GMT+00:00 Apr 2, 2013

    Please fix this. This is unacceptable

  • Adam Cameron.

    2:49:19 PM GMT+00:00 Apr 1, 2013

    +1 needs to be fixed.

    --
    Adam

  • TechSTL

    2:39:50 PM GMT+00:00 Aug 22, 2012

    I'm able to replicate this.

Your session has expired! Click to login
Current form data will be preserved

Cancel