tracker issue : CF-4199508

Problem Description:
When servicing a REST request, the various request event handlers are fired twice. The order of function calls is: onRequestStart, onRequestEnd, onRequestStart, CFC function servicing the request, onRequestEnd. As an added perk, the Request scope is shared between all five calls. This is a regression bug introduced with CF 10 Update 22. CF 10 Update 21 is not affected.


Steps to Reproduce:
Use the following code.

Application.cfc:

<cfcomponent>
	<cfset This.name = "restbug">
	<cffunction name="onRequestStart">
		<cfif not StructKeyExists(request, "counter")>
			<cfset request.counter = 0>
		</cfif>
		<cfset request.counter++>
		<cflog file="#Application.applicationName#" text="start [#request.counter#]">
	</cffunction>
	<cffunction name="onRequestEnd">
		<cflog file="#Application.applicationName#" text="end [#request.counter#]">
	</cffunction>
</cfcomponent>

main.cfc:

<cfcomponent rest="true">
	<cffunction name="test" access="remote" httpmethod="GET" returntype="string">
		<cflog file="#Application.applicationName#" text="test [#request.counter#]">
		<cfreturn "Hello Test">
	</cffunction>
</cfcomponent>

To reproduce the bug:
1) Create Application.cfc and main.cfc in the same folder.
2) Register that folder in CF Admin as a REST service with the name 'restbug'.
2) Use a browser to navigate to: http://localhost/rest/restbug/main/
3) Open restbug.log and examine the logged entries.


Actual Result:
restbug.log contains:
"Information","ajp-bio-8012-exec-8","08/18/17","15:21:26","RESTBUG","start [1]"
"Information","ajp-bio-8012-exec-8","08/18/17","15:21:26","RESTBUG","end [1]"
"Information","ajp-bio-8012-exec-8","08/18/17","15:21:26","RESTBUG","start [2]"
"Information","ajp-bio-8012-exec-8","08/18/17","15:21:26","RESTBUG","test [2]"
"Information","ajp-bio-8012-exec-8","08/18/17","15:21:26","RESTBUG","end [2]"


Expected Result:
restbug.log contains:
"Information","ajp-bio-8012-exec-8","08/18/17","15:21:26","RESTBUG","start [1]"
"Information","ajp-bio-8012-exec-8","08/18/17","15:21:26","RESTBUG","test [1]"
"Information","ajp-bio-8012-exec-8","08/18/17","15:21:26","RESTBUG","end [1]"


Any Workarounds:
As the Request scope is shared between the function calls, and is not reset, an indicator such as the request.counter variable in the example above could be used to detect the additional calls to onRequestStart etc.


Cause Analysis:
I have examined the Java code of the CF server to try and find the cause of the bug. I found this difference between CF10 U21 and U22:

CF10 U21, chf10000021.jar, coldfusion.rest.component.CFComponentProvider class contains:
    private FusionFilter getFilterChain(final String calledPagePath) {
        FusionFilter filter = (FusionFilter)new EndFilter();
        filter = (FusionFilter)new PathFilter(filter, calledPagePath);
        return filter;
    }

CF10 U22, chf10000022.jar, coldfusion.rest.component.CFComponentProvider class contains:
    private FusionFilter getFilterChain(final String calledPagePath) {
        FusionFilter filter = (FusionFilter)new EndFilter();
        filter = new ApplicationFilter(filter, 1);
        if (RequestMonitorFilter.isFilterEnabled()) {
            filter = (FusionFilter)new RequestMonitorFilter(filter);
        }
        filter = (FusionFilter)new MonitoringFilter(filter, "WEB SERVICE REQUEST");
        filter = (FusionFilter)new PathFilter(filter, calledPagePath);
        return filter;
    }

Additionally, going back further, see bug #CF-3506757. In one of the comments, Paul Nibin writes: "The Application filter were not running when invoking the webservice method. It was used when we were creating the instance of the service class. [...] Moved the application and other required filters while invoking the method." This change that Paul refers to was released in CF10 Update 14.

CF at release, cfusion.jar, coldfusion.rest.component.CFComponentProvider class contains:
    private FusionFilter getFilterChain(final String calledPagePath) {
        FusionFilter filter = new EndFilter();
        filter = new ApplicationFilter(filter, 1);
        if (RequestMonitorFilter.isFilterEnabled()) {
            filter = new RequestMonitorFilter(filter);
        }
        filter = new MonitoringFilter(filter, "WEB SERVICE REQUEST");
        filter = new PathFilter(filter, calledPagePath);
        return filter;
    }

CF10 U14, chf10000014.jar, coldfusion.rest.component.CFComponentProvider class contains:
    private FusionFilter getFilterChain(final String calledPagePath) {
        FusionFilter filter = (FusionFilter)new EndFilter();
        filter = (FusionFilter)new PathFilter(filter, calledPagePath);
        return filter;
    }

It appears to me that the the current regression bug is related to a reversal in U22 of the change made in U14.


Additional Comments:
I understand that CF10 is technically not under support anymore. However, it is a big problem for us that a regression bug is introduced in one of the last CF10 updates. This is preventing us from updating to U22 or U23 and taking advantage of the last set of bug fixes released for CF10. I am submitting this ticket in the hope that the CF team will consider releasing a fix for this bug for CF10, especially as I have done some of the work of tracking down the offending code in the CF server.

Attachments:

Comments: