Understanding The IIS Mod-Rewrite Log File And Work Flow

As I have just started experimenting with URL rewriting in ColdFusion using IIS Mod-Rewrite, I have a lot of learning to do. While some of my experiments are working, I am getting some very unexpected (and frustrating) results which clearly indicate that I need to get a stronger hold on the work flow executing behind each URL rewrite. To gather some insight, I turned on logging for the rewrite process. This has to be done in the main (server-wide) configuration file, not in the override configuration files:

In order for IIS to be able to write to this log file, I needed to grant the IIS Windows user "write permissions" on the directory in which the log was be stored. Because I am running IIS6, this user showed up as IIS_WPG:

Once I had IIS Mod-Rewrite successfully logging web requests (which is, ALL requests on the server, by the way), I started to try different RewriteRule's to see how they were operating under the hood. The first one I set up was a simple rule that rewrites all incoming request to point to index.cfm:

As you can see, no matter what request comes from the outside, all traffic will be directed to index.cfm. Furthermore, the requested sub-file path will be appended to the request as the query string parameter, "original." I have also included the QSA (Query String Append) flag such that any query string values made in the original request will also be included in the rewritten URL.

With this rule in place, I called the following URL:

./foo/bar.cfm

Now, before we go into what happens, let me tell you what I would expect to happen as someone new to URL rewriting. I would expect that I'd execute the index.cfm page and my URL scope would contain the following name-value pair:

original: foo/bar.cfm

Now, here's what really happens: Yes, the index.cfm file is executed, but my URL scope has the following unexpected name-value pair:

original: index.cfm,foo/bar.cfm

Funky! Not only am I getting the original URL in the query string, I'm also getting the rewrite URL as well (or so I think).

So what happened? If you look at my regular expression and my rewrite, it would make you think that the entire string "index.cfm,foo/bar.cfm" is what is being captured; but that can't be as index.cfm was not part of the original request! To find out more, I took a look at the log file. Here is the relevant excerpt from it (with unnecessary data removed):

init rewrite engine
with requested uri

applying pattern
'/\.htaccess$' to uri '/iis_mod_rewrite2/foo/bar.cfm'

pass through
/iis_mod_rewrite2/foo/bar.cfm

init rewrite engine
with requested uri

applying pattern
'^(.+)$' to uri 'foo/bar.cfm'

rewrite
'foo/bar.cfm' -> 'index.cfm?original=foo/bar.cfm'

split
uri=index.cfm?original=foo/bar.cfm -> uri=index.cfm, args=original=foo/bar.cfm

internal redirect
with /iis_mod_rewrite2/index.cfm [INTERNAL REDIRECT]

init rewrite engine
with requested uri

applying pattern
'^(.+)$' to uri 'index.cfm'

rewrite
'index.cfm' -> 'index.cfm?original=index.cfm'

split
uri=index.cfm?original=index.cfm -> uri=index.cfm, args=original=index.cfm

internal redirect
with /iis_mod_rewrite2/index.cfm [INTERNAL REDIRECT]

Having never seen a log file like this before, it took me a good hour (and plenty of Twitter help from Emmet McGovern) to really wrap my head around what was going on. Immediately, however, I noticed that there were two calls to something marked [INTERNAL REDIRECT]. That probably had something to do with my funky resultant query string, but how? After all, I only had one rewrite rule - how could two redirects be executing? I was especially perplexed considering that I was using the "L" (Last Rule) flag on my rewrite condition.

What I came to realize was that each rewrite performed by IIS Mod-Rewrite gets reprocessed using the rewritten URL. As such, the first rewrite rule was executed on the original URL:

foo/bar.cfm

At the end of the first pass, it was rewritten to the URL:

index.cfm?original=foo/bar.cfm

At this point, the newly rewritten URL was reprocessed (sub-requested??) by the rules engine and ends up creating this new URL:

index.cfm?original=index.cfm

While this URL only has the one, "original," query string parameter, because I am using the QSA (Query String Append) flag, the query string created in the first URL rewrite (original=foo/bar.cfm) is now appended to the query string created by the second rewrite rule such that I end up with this URL:

index.cfm?original=index.cfm&original=foo/bar.cfm

Now, because I have a query parameter named, "original," showing up twice in the resultant query string, the two query parameter values get collapsed into a single, comma-delimited list:

original: index.cfm,foo/bar.cfm

As a note, if I removed the QSA (Query String Append) flag, I ended up with the name-value pair:

original: index.cfm

This happens because only the final query string created by the second rewrite rule is kept.

Ok, so tracing the logged rewrites helps us understand where the unexpected query string value comes from; but, it doesn't really help us understand why there are specifically two redirects being executed. After all, if there are no RewriteCond (rewrite conditions) on the RewriteRule, why execute 2 times, but not 3 times - or 4 times - or N times?

After some more reading and some back and forth on Twitter, I came up with a theory as to what was going on. Normally, with a URL rewriting system, something like this would create an endless loop of rewriting. To stop this from happening, you might set a limit to the number of rewrites that can take place using the MaxRewrites condition. From what I can gather, however, IIS Mod-Rewrite does not support this rewrite option; as such, I have to assume that it has built its rewrite engine with enough intelligence to see that it was about to enter an endless loop (rewrite result matches incoming URL) and halts the process. That would explain the two rewrite executions, but not a third.

In my experimentation, I tried using the NS (Do Not allow internal Subrequests) flag to prevent the first rewritten rule from being re-evaluated; but, from the IIS Mod-Rewrite documentation, it would appear that ISAPI does not support custom control flow at this level. If that interpretation is correct, then it makes even more sense as to why the rewrite engine was built to One) Always re-evaluate and, Two) Halt immediately at the beginning of an endless loop.

I am simultaneously new to all of the URL rewriting concepts as well as the IIS Mod-Rewrite product, so forgive me if there are any blatant misunderstandings in this explanation of the rewrite log file. It took me a number of hours and a lot of help to even get this far, so any constructive criticism would be greatly appreciated. From what I have concluded thus far, however, I have been able to more accurately predict other rewrite outcomes, which I'll address in later blog posts.

NOTE: Always remember to turn Off logging when you are not using it. Since every single web request (including IMG, CSS, and SCRIPT files) gets logged to this text file, it gets very big, very fast.

What Other People Are Searching For

[ local search ] rewriting urls in a coldfusion application
[ local search ] how to use url rewriting
[ local search ] how to use mod rewrite with iis
[ local search ] iis mod rewrite application

You Might Also Be Interested In: