Rewritten URL sends query to DB twice

Topics: Developer Forum
Oct 8, 2008 at 4:35 PM
Noticed this a few days ago in development, and confirmed via further testing: when a rewritten URL is accessed, all queries are sent to the DB twice; when URL is accessed in non-rewritten form, the queries are sent just once (as is desired).

For example:

ReWriteRule ^/rewritetest.html       /rewritetest.cfm

where rewritetest.cfm passes simply query "select getdate(), 999" to the DB and includes no references to other files.  There are no other rewrite rules.

Running a DB profiler, it is clear that the query is executed twice in succession, typically less than half a second apart, when .../rewritetest.html is accessed, but just once when .../rewritetest.cfm is hit directly.  Adjustments to iteration limit and filter priority have no impact, nor do [U], [L] and/or [I] flags.

There is no noticeable effect on the user end, and there are no errors in the log file.  However, with logging on high, I see the following:

[...] - DoRewrites: New Url: '/rewritetest.html'
[...] - ApplyRules: depth=0
[...] - ApplyRules: Rule 1 : 1 matches
[...] - ReplaceServerVariables: InputString='/rewritetest.cfm' out='/rewritetest.cfm'
[...] - GenerateReplacementString: src='/rewritetest.html','(null)' ReplacePattern='/rewritetest.cfm' vec=[[  0, 17] [] ] counts=1,0
[...] - ApplyCaseConversion: before '/rewritetest.cfm'
[...] - ApplyCaseConversion: after  '/rewritetest.cfm'
[...] - GenerateReplacementString: result '/rewritetest.cfm'
[...] - ApplyRules: Result (length 16): /rewritetest.cfm
[...] - ApplyRules: depth=1
[...] - ApplyRules: Rule 1 : -1 (No match)
[...] - ApplyRules: returning 0
[...] - ApplyRules: returning 1
[...] - DoRewrites: Rewrite Url to: '/rewritetest.cfm'
[...] - DoRewrites: Finished
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\rewritetest.cfm), in ptr (0x0049e8e0)
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\index.htm), in ptr (0x0049e8e0)
[...] - HttpFilterProc: SF_NOTIFY_LOG
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\rewritetest.cfm), in ptr (0x011c1d48)
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\index.htm), in ptr (0x011c1d48)
[...] - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
[...] - DoRewrites


There are two references to storing the rewritten URL, each as a different variable: I suspect that this is pertinent to the matter at hand.

Adding the [R] flag resolves the issue, and results in the appearance of only one "storing physical path..." variable in the log, but a 302 redirect is not desired.

Specs: issue was first noted in an older version of IIRF, but the behavior in v1.2.14 is identical.  IIS6, ColdFusion 8, Sql 2000.

Any advice?
Coordinator
Oct 8, 2008 at 4:59 PM

Highly unusual!

Which browser?  do you have a way to log HTTP requests?

If you use IE, then you can install Fiddler2 and it will log the outgoing HTTP requests.

You've snipped the log. Is it possible that there is another incoming request being logged?

I'll look in the code, to see if I can find anything that would cause this anomaly.

 

Oct 8, 2008 at 6:18 PM
The issue was first noticed (and all subsequent testing has been conducted) in single-user development environments, so other incoming requests are fairly unlikely.  The results are the same in both Firefox & IE.

Fiddler shows only one request for /rewritetest.html

Below is the full text of a logfile that demonstrates the problem in action:


--------------------------------------------
[...] - New LogFile opened.
[...] - AwaitIniChangeAndReinit:  TerminateWatch = FALSE
[...] - FileChangeWatcher(): Await returns (TerminateWatch= FALSE)
[...] - FileChangeWatcher: Await()...
[...] - AwaitIniChangeAndReinit()...
[...] - AwaitIniChangeAndReinit: watcher got something...
[...] - AwaitIniChangeAndReinit: Detected change in file 'IsapiRewrite4.ini'
[...] - AwaitIniChangeAndReinit: Detected change in the  ini file '[...]\IsapiRewrite4.ini'
[...] - AwaitIniChangeAndReinit: Ionic ISAPI Rewriting Filter (IIRF) v1.2.14 final R3
[...] - ReadConfig
[...] - ReadConfig: line   1: RewriteRule   1 ^/rewritetest.html                             /rewritetest.cfm                                [U]
[...] - ReadConfig: not a duplicate rule...
[...] - ParseRuleModifierFlags: '[U]'
[...] - ParseRuleModifierFlags: token 'U'
[...] - rule: Unmangle URLs
[...] - LogFile re-opened.
[...] - ReadConfig: new log file name: '[...]\iirfLog.out.8256.log'
[...] - ReadConfig: setting LogLevel to 5
[...] - ReadConfig: Done reading, found 1 rules (0 failed) on 13 lines

--------------------------------------------
[...] - LogFile re-opened.
[...] - AwaitIniChangeAndReinit:  TerminateWatch = FALSE
[...] - FileChangeWatcher(): Await returns (TerminateWatch= FALSE)
[...] - FileChangeWatcher: Await()...
[...] - AwaitIniChangeAndReinit()...
[...] - DllMain THREAD_DETACH, threadId= 5328
[...] - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
[...] - DoRewrites
[...] - GetServerVariable_AutoFree: getting 'url'
[...] - GetServerVariable_AutoFree - no joy (GetLastError()=1413)
[...] - GetServerVariable_AutoFree: 128 bytes
[...] - GetServerVariable_AutoFree: result ''
[...] - GetHeader_AutoFree: getting 'url'
[...] - GetHeader_AutoFree: 18 bytes
[...] - GetHeader_AutoFree: result '/rewritetest.html'
[...] - GetServerVariable_AutoFree: getting 'QUERY_STRING'
[...] - GetServerVariable_AutoFree: 1 bytes
[...] - GetServerVariable_AutoFree: result ''
[...] - GetHeader_AutoFree: getting 'method'
[...] - GetHeader_AutoFree: 4 bytes
[...] - GetHeader_AutoFree: result 'GET'
[...] - DoRewrites: New Url: '/rewritetest.html'
[...] - ApplyRules: depth=0
[...] - ApplyRules: Rule 1 : 1 matches
[...] - ReplaceServerVariables: InputString='/rewritetest.cfm' out='/rewritetest.cfm'
[...] - GenerateReplacementString: src='/rewritetest.html','(null)' ReplacePattern='/rewritetest.cfm' vec=[[  0, 17] [] ] counts=1,0
[...] - ApplyCaseConversion: before '/rewritetest.cfm'
[...] - ApplyCaseConversion: after  '/rewritetest.cfm'
[...] - GenerateReplacementString: result '/rewritetest.cfm'
[...] - ApplyRules: Result (length 16): /rewritetest.cfm
[...] - ApplyRules: depth=1
[...] - ApplyRules: Rule 1 : -1 (No match)
[...] - ApplyRules: returning 0
[...] - ApplyRules: returning 1
[...] - DoRewrites: Rewrite Url to: '/rewritetest.cfm'
[...] - DoRewrites: Finished
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\rewritetest.cfm), in ptr (0x010bf3c0)
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\index.htm), in ptr (0x010bf3c0)
[...] - HttpFilterProc: SF_NOTIFY_LOG
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\rewritetest.cfm), in ptr (0x001e39d0)
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\index.htm), in ptr (0x001e39d0)
[...] - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
[...] - DoRewrites
[...] - GetServerVariable_AutoFree: getting 'url'
[...] - GetServerVariable_AutoFree - no joy (GetLastError()=1413)
[...] - GetServerVariable_AutoFree: 128 bytes
[...] - GetServerVariable_AutoFree: result ''
[...] - GetHeader_AutoFree: getting 'url'
[...] - GetHeader_AutoFree: 31 bytes
[...] - GetHeader_AutoFree: result '[...]/topdoc.gif'
[...] - GetServerVariable_AutoFree: getting 'QUERY_STRING'
[...] - GetServerVariable_AutoFree: 1 bytes
[...] - GetServerVariable_AutoFree: result ''
[...] - GetHeader_AutoFree: getting 'method'
[...] - GetHeader_AutoFree: 4 bytes
[...] - GetHeader_AutoFree: result 'GET'
[...] - DoRewrites: New Url: '[...]/topdoc.gif'
[...] - ApplyRules: depth=0
[...] - ApplyRules: Rule 1 : -1 (No match)
[...] - ApplyRules: returning 0
[...] - DoRewrites: No Rewrite
[...] - DoRewrites: Finished
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - OnUrlMap: storing physical path ([...]\[...]\topdoc.gif), in ptr (0x010be498)
[...] - HttpFilterProc: SF_NOTIFY_URL_MAP
[...] - HttpFilterProc: SF_NOTIFY_LOG

Coordinator
Oct 8, 2008 at 7:44 PM

I hear what you are saying about single-user environment.

There is another request coming into the filter, somehow.   The multiple calls to NOTIFY_URL_MAP indicate that.  It's curious that one of them is mappnig to /index.htm.  Do you have a doc called index.htm?  If so, what is in that file?

Can you try this test for me?  Suppose you change the rule for rewritetest.html and rewrite it to Cheeso.htm.   And then you create a document called Cheeso.htm that just returns a "Hello" or something like that.

Run the request again.  Do you see 2 calls to NOTIFY_URL_MAP in that case?

The fact that you get 2 different pointers in those calls to NOTIFY_URL_MAP leads me to conclude that there are 2 distinct  HTTP sessions opened with the server.  It's odd because  there is only a single AUTH_COMPLETE.  IIRF does the rewrite during the AUTH_COMPLETE event.   Look in the log you will see a NOTIFY_AUTH_COMPLETE, followed by DoRewrites.  This happens once per request.  You have two of them, one for rewritetest.html ,and another for topdoc.gif.  (Where is that coming from anyway?)

The NOTIFY_URL_MAP can happen multiple times per request, but there is logic within IIRF to check for this and only store the pathname once, as necessary.  If that logic path were followed you would not see the two messages stating "Storing physical path".  

It sure seems like the filter is getting a NOTIFY_URL_MAP with no preceding NOTIFY_AUTH_COMPLETE.  What I mean is, there are two sessions open with the IIS Server, and IIRF is getting notified on both of them.  The first session is the request for rewritetest.html, and gets authorized.  The second session is.. I don't know what... it does not get an AUTH_COMPLETE event. 

Actually it is a bit more complicated - you are getting 2 NOTIFY_URL_MAP events for the NOTIFY_AUTH_COMPLETE event  - the request for rewritetest.html.  And you are also getting two additional NOTIFY_URL_MAP events with no preceding NOTIFY_AUTH_COMPLETE.  That is the secret second session. 

It is not going through the AUTH_COMPLETE - is there some different server or website or application that has Authorization turned off?

Is this a HTTP POST or is ait an HTTP GET ?

Oct 9, 2008 at 4:36 PM
Edited Oct 9, 2008 at 4:57 PM
This is an HTTP GET.

Sorry about including the references to topdoc.gif.  It is an image that appears in ColdFusion's debug code.  The results (i.e. the duplicate NOTIFY_URL_MAP calls and multiple DB queries) are the same with debugging off, so the last 23 lines of the logfile copied above can be disregarded.

Index.htm does not exist.  I have removed it from the IIS Default Documents, which is the only place in which I could find any reference to it, but the issue persists.  Disabling the Defaults similarly made no difference, nor did any changes that I made to Authentication in IIS.

I have tested your recommendation - that the rewrite redirect to an HTM/L file rather than a CFM - and the results are correct: there is a 1:1 balance of NOTIFY_URL to NOTIFY_AUTH.  I could provide the logging of this event, but I don't imagine that you need it in this case.

Does this suggest that ColdFusion is somehow responsible for the phantom session/call?  I have examined and changed my CF settings without finding anything that corrects the problem.

EDIT: also, is it of any relevance that the [R] flag resolves the issue but cannot be used as a solution, as I mentioned in my initial post?
Coordinator
Oct 14, 2008 at 5:45 AM
No, I don't think the [R] flag is helping me understand the situation.

It feels to me like a security thing - there is some additional HTTP Request happening for authorization purposes, something like that.

Can you try a different .Cfm file - something really braindead simple with no database access.  Does a totally simple .cfm file still cause the anomalous behavior?
Does .cfm have a global.asax -type capability, application-wide code that runs for every session or request?  Could it be that this logic is running and causing an additional request?

Does the problem occur on a fresh .cfm server?  Do you have a .cfm expert you can ask for insight into this?  (Sorry, I don't know CFM and don't know what more to ask there)
Oct 16, 2008 at 3:30 PM
It seems to be specific to the interactions between ColdFusion and IIRF and/or IIS.  Testing the basic braindead simple CFM produced the same undesirable results in logging - even with all of application.cfm (/.cfc) commented out, as well as in an entirely new test project with no application-wide code - while testing HTML and ASPX on the same machine results in the correct output.

On an IIS7 setup using the URL Rewriting Module, there is no problem.  IIRF's behavior does not change when used in conjunction with IIS7.

That seems to be all there is to it.  I will continue examining this issue from a CF angle.  Please let me know if you have any further insights, and thanks for your assistance.
Coordinator
Oct 16, 2008 at 5:57 PM

I agree - seems to be an interaction between IIRF and CFM.

Very odd. I know that there are lots of other users of IIRF out there who use IIRF.

Is there a free version of ColdFusion that I could use to try to reproduce the behavior on my machine?

 

Feb 24, 2010 at 12:14 PM

 

Few important tips and notes about Application.cfm/cfc:

  

This is the first ColdFusion file that gets executed by the ColdFusion Application server even if we request for some other file. Example: When we type http://www.mySite.com/index.cfm, Application.cfm/cfc gets executed first and then index.cfm. Application.cfc/cfm and all objects gets instantiated for each server page request.
We may or may not have Application.cfc/cfm inside one project web root.
Application files are mainly used to set application (global) level objects before executing the server files of the project.
What if we are requesting for a ColdFusion file present inside a deep subfolder level? If we have Application.cfc/cfm inside the same folder (where our requested file resides) then the same Application.cfc/cfm will be executed. If we do not have Application.cfm/cfm inside the same folder (where our requested file resides) then ColdFusion application server will search for the Application files in the next higher folder level (backward), it still does not find then one level up till the web root. At any level if it finds the Application files then it will execute that.
What if we have both Application.cfc and Application.cfm present in the same folder? Application.cfc will be given more priority (Application.cfm will be ignored) if the ColdFusion version is ColdFusion MX 7 +. If it is any version less that ColdFusion MX 7 then Application.cfm will be given more priority (Application.cfc will be ignored). Reason: Application.cfc got introduced in CFMX 7 version onwards and given more priority over Application.cfm.
Linux is case sensitive. If it is a Linux box then, Application.cfc/cfm will be executed by the ColdFusion application server NOT application.cfc/cfm. So it is always a good habit to use "A" instead of "a" for Application.cfc/cfm.
 

This is the first ColdFusion file that gets executed by the ColdFusion Application server even if we request for some other file. Example: When we type http://www.mySite.com/index.cfm, Application.cfm/cfc gets executed first and then index.cfm. Application.cfc/cfm and all objects gets instantiated for each server page request.

We may or may not have Application.cfc/cfm inside one project web root.

Application files are mainly used to set application (global) level objects before executing the server files of the project.

What if we are requesting for a ColdFusion file present inside a deep subfolder level? If we have Application.cfc/cfm inside the same folder (where our requested file resides) then the same Application.cfc/cfm will be executed. If we do not have Application.cfm/cfm inside the same folder (where our requested file resides) then ColdFusion application server will search for the Application files in the next higher folder level (backward), it still does not find then one level up till the web root. At any level if it finds the Application files then it will execute that.

What if we have both Application.cfc and Application.cfm present in the same folder? Application.cfc will be given more priority (Application.cfm will be ignored) if the ColdFusion version is ColdFusion MX 7 +. If it is any version less that ColdFusion MX 7 then Application.cfm will be given more priority (Application.cfc will be ignored). Reason: Application.cfc got introduced in CFMX 7 version onwards and given more priority over Application.cfm.

Linux is case sensitive. If it is a Linux box then, Application.cfc/cfm will be executed by the ColdFusion application server NOT application.cfc/cfm. So it is always a good habit to use "A" instead of "a" for Application.cfc/cfm.

 Eliza