Multiple issues

Topics: User Forum
May 30, 2011 at 5:48 PM

I've got IIRF functioning properly for one site on my server.  It's got 2 rules - one to redirect to the www address, the other to rewrite all file-not-found conditions to /index.php.

Now I'm trying to get it working with a second site on the same server, this time with 2 rewrite rules, and am having a tough time.

False File Not Found:  Just a few seconds apart, a stylesheet is found, and then not found:

Mon May 30 10:56:10 -  2696 - DoRewrites: Url (no decoding): '/admin/image/style.css'
Mon May 30 10:56:10 -  2696 - DoRewrites: No Rewrite
Mon May 30 10:56:19 -  2696 - DoRewrites: Url (no decoding): '/admin/image/style.css'
Mon May 30 10:56:19 -  2696 - EvaluateRules: Last Rule
Mon May 30 10:56:19 -  2696 - DoRewrites: Rewrite Url to: '/admin/index.php'

How should I debug this?

Cached settings?  I've set cache control headers to tell browser, etc., not to cache any page content.  In monitoring my IIRF log, though, I'm sometimes seeing a rewrite to the wrong php module, and it often seems like those incorrect rewrites aren't shown in the log.

Should stopping/restarting IIS clear any cached information at the server, or are there other things to consider?

Simply wrong rewrites.  Here are my rules:

RewriteCond %{REQUEST_FILENAME} !-f
RewriteRule ^/admin/(.*)$ /admin/index.php [L]

RewriteCond %{REQUEST_FILENAME} !-f
RewriteRule ^.*$ /index.php [L]

So, I just want files not found rewritten to /index.php, unless the request is for something under /admin, which goes to /admin/index.php.

But, I can't get the actual rewrites going in the needed directions consistently.  Requests that should go to /admin/index.php go unpredictably to /index.php and vice versa.  When the browser lands in the wrong one, a hard refresh sometimes fixes it, but again not consistently.

I'm a pretty careful and patient person when it comes to debugging, but I've lost 10+ hours to this with no meaningful progress.

Any suggestions as to where to focus next?  All feedback welcome.

Thanks...

Coordinator
May 31, 2011 at 8:09 PM
Edited May 31, 2011 at 8:11 PM
Bose wrote:

False File Not Found:  Just a few seconds apart, a stylesheet is found, and then not found:

Mon May 30 10:56:10 -  2696 - DoRewrites: Url (no decoding): '/admin/image/style.css'
Mon May 30 10:56:10 -  2696 - DoRewrites: No Rewrite
Mon May 30 10:56:19 -  2696 - DoRewrites: Url (no decoding): '/admin/image/style.css'
Mon May 30 10:56:19 -  2696 - EvaluateRules: Last Rule
Mon May 30 10:56:19 -  2696 - DoRewrites: Rewrite Url to: '/admin/index.php'

How should I debug this?

I don't understand what you mean by "found, and then not found." The IIRF log snip that you provided may indicate different actions taken on a particular URL, but that is not necessarily wrong or inconsistent. Imagine the case where your rules test for the presence of a header, then set the header if it is not present, and do no other rewrite.  The 2nd time through, the header is present, and perhaps in that case the rules say to rewrite the URL.  Without seeing the rules and the other conditions, it's hard to provide any insight into what you are seeing.  I also recommend turning the IIRF logging up a few notches when trying to diagnose something like this. Instead of getting 2 lines per request, you will get 20 or so, and that will give you a view into the finer-grained operations and decisions taken by IIRF.

Cached settings?  I've set cache control headers to tell browser, etc., not to cache any page content.  In monitoring my IIRF log, though, I'm sometimes seeing a rewrite to the wrong php module, and it often seems like those incorrect rewrites aren't shown in the log.

I don't get it. You say you see "a rewrite to the wrong php module". I have no idea what that means. What is "the wrong one"? You need to explain it to me in terms that I can understand. I know nothing about your scenario, except what you write here.

If the rewrites are not shown in the IIRF log, then IIRF did not perform the rewrites. There are no two ways about this. If you have IIRF logging turned on, IIRF never performs actions without logging. If it is not being logged in the IIRF log, then IIRF is not doing it. If you see surprising content, it's possible the content is being served from a cache somewhere in the chain, either at the browser or on the server or at some intermediary between the two.

Should stopping/restarting IIS clear any cached information at the server, or are there other things to consider?

No - I don't know enough about IIS caching to confirm that. I'm not sure if a stop/restart on IIS will clear its cache in all cases. It is likely a cache issue though. One thing that may provide some insight - hook up Fiddler to the browser, and observe the responses. If you see 304 responses, that indicates IIS is saying "it's the same content as last time", which tells the browser to use its cache. I know you said you turned off the browser cache. I don't know exactly how to do that, or how such a setting would interact with a 304 Not Modified response. What I would do is use Fiddler to get a closer look.

Simply wrong rewrites.  Here are my rules:

 

RewriteCond %{REQUEST_FILENAME} !-f
RewriteRule ^/admin/(.*)$ /admin/index.php [L]

RewriteCond %{REQUEST_FILENAME} !-f
RewriteRule ^.*$ /index.php [L]

 

So, I just want files not found rewritten to /index.php, unless the request is for something under /admin, which goes to /admin/index.php.

But, I can't get the actual rewrites going in the needed directions consistently.  Requests that should go to /admin/index.php go unpredictably to /index.php and vice versa.  When the browser lands in the wrong one, a hard refresh sometimes fixes it, but again not consistently.

I'm a pretty careful and patient person when it comes to debugging, but I've lost 10+ hours to this with no meaningful progress.

Any suggestions as to where to focus next?  All feedback welcome.

Thanks...

 Sorry you're having so much trouble.

I would turn on IIRF loggign and closely examine the cases that work, and the cases that do not.

It does sound as if you have a cache interfering with your results somehow.  Another way to avoid the cache is to add a parameter to the request that always changes, like _=49849844948 in one request, and _=40940493 in the next.  This makes the URL unique, which can discourage caches from satisfying requests.

 

Jun 1, 2011 at 3:13 AM

Thanks so much for your time.

Here are the rules I'm using:

RewriteCond %{REQUEST_FILENAME} !-f
RewriteRule ^/admin/(.*)$ /admin/index.php [L]

RewriteCond %{REQUEST_FILENAME} !-f
RewriteRule ^.*$ /index.php [L]

I set the log level to 6, and then retrieved pages a few seconds apart.  This time, /site/script/site.js was treated differently for reasons I can't identify.  Here, if I'm reading correctly, it was not found on disk and rewritten to /index.php. 

Tue May 31 19:46:52 -  2852 - DoRewrites: New Url, before decoding: '/site/script/site.js' 
Tue May 31 19:46:52 -  2852 - DoRewrites: Url (no decoding): '/site/script/site.js'
Tue May 31 19:46:52 -  2852 - EvaluateRules: depth=0
Tue May 31 19:46:52 -  2852 - GetServerVariable: getting 'SCRIPT_NAME'
Tue May 31 19:46:52 -  2852 - GetServerVariable: 22 bytes
Tue May 31 19:46:52 -  2852 - GetServerVariable: result '/admin/script/site.js'
Tue May 31 19:46:52 -  2852 - EvaluateRules: no RewriteBase
Tue May 31 19:46:52 -  2852 - EvaluateRules: Rule 1: pattern: ^/admin/(.*)$  subject: /site/script/site.js
Tue May 31 19:46:52 -  2852 - EvaluateRules: Rule 1: -1 (No match)
Tue May 31 19:46:52 -  2852 - EvaluateRules: Rule 2: pattern: ^.*$  subject: /site/script/site.js
Tue May 31 19:46:52 -  2852 - EvaluateRules: Rule 2: 1 matches
Tue May 31 19:46:52 -  2852 - EvaluateRules: Rule 2: evaluating condition
Tue May 31 19:46:52 -  2852 - EvalCondition: cond 0x01276D10
Tue May 31 19:46:52 -  2852 - GetServerVariable: getting 'REQUEST_FILENAME'
Tue May 31 19:46:52 -  2852 - GetServerVariable: special variable name
Tue May 31 19:46:52 -  2852 - GetServerVariable: 58 bytes
Tue May 31 19:46:52 -  2852 - GetServerVariable: result 'D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js'
Tue May 31 19:46:52 -  2852 - ReplaceServerVariables: alloc 59 bytes
Tue May 31 19:46:52 -  2852 - GetServerVariable: getting 'REQUEST_FILENAME'
Tue May 31 19:46:52 -  2852 - GetServerVariable: special variable name
Tue May 31 19:46:52 -  2852 - GetServerVariable: 58 bytes
Tue May 31 19:46:52 -  2852 - GetServerVariable: result 'D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js'
Tue May 31 19:46:52 -  2852 - ReplaceServerVariables: vName(REQUEST_FILENAME) value(D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js)
Tue May 31 19:46:52 -  2852 - ReplaceServerVariables: in='%{REQUEST_FILENAME}' out='D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js'
Tue May 31 19:46:52 -  2852 - EvalCondition: ts1 'D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js'
Tue May 31 19:46:52 -  2852 - GenerateReplacementString: src='/site/script/site.js','(null)' ReplacePattern='D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js' vec=[[  0, 20] [] ] counts=1,0
Tue May 31 19:46:52 -  2852 - GenerateReplacementString: alloc 60 bytes
Tue May 31 19:46:52 -  2852 - ApplyCaseConversion: before 'D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js'
Tue May 31 19:46:52 -  2852 - ApplyCaseConversion: after  'D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js'
Tue May 31 19:46:52 -  2852 - GenerateReplacementString: result 'D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js'
Tue May 31 19:46:52 -  2852 - EvalCondition: t(D:\Home\WWW\NicolletCountyFair\Htdocs\admin\script\site.js) op(f) p(!-f)
Tue May 31 19:46:52 -  2852 - EvalCondition: cond->SpecialConditionType= 'f'
Tue May 31 19:46:52 -  2852 - EvalCondition: Special: it is not a file
Tue May 31 19:46:52 -  2852 - EvalCondition: File variant, retVal= false
Tue May 31 19:46:52 -  2852 - EvalCondition: Cond t(%{REQUEST_FILENAME}) op(f) p(!-f) => TRUE
Tue May 31 19:46:52 -  2852 - EvalCondition: Child is NULL
Tue May 31 19:46:52 -  2852 - EvalConditionList: rule 2, TRUE, Rule will apply
Tue May 31 19:46:52 -  2852 - ReplaceServerVariables: alloc 11 bytes
Tue May 31 19:46:52 -  2852 - ReplaceServerVariables: in='/index.php' out='/index.php'
Tue May 31 19:46:52 -  2852 - GenerateReplacementString: src='/site/script/site.js','(null)' ReplacePattern='/index.php' vec=[[  0, 20] [] ] counts=1,0
Tue May 31 19:46:52 -  2852 - GenerateReplacementString: alloc 12 bytes
Tue May 31 19:46:52 -  2852 - ApplyCaseConversion: before '/index.php'
Tue May 31 19:46:52 -  2852 - ApplyCaseConversion: after  '/index.php'
Tue May 31 19:46:52 -  2852 - GenerateReplacementString: result '/index.php'
Tue May 31 19:46:52 -  2852 - EvaluateRules: Result (length 10): /index.php
Tue May 31 19:46:52 -  2852 - EvaluateRules: Last Rule
Tue May 31 19:46:52 -  2852 - EvaluateRules: returning 1
Tue May 31 19:46:52 -  2852 - DoRewrites: Rewrite Url to: '/index.php'

It's not clear to me why the log keeps referring to ...\admin\script\site.js when the requested URL is /site/script/site.js.  But, am I reading the log correctly, that the request for /site/script/site.js was rewritten to /index.php because /admin/script/site.js was not found?

And yet, a few seconds later, it looks like a request for /site/script/site.js was not rewritten:

Tue May 31 19:46:59 -  3296 - DoRewrites: New Url, before decoding: '/site/script/site.js' 
Tue May 31 19:46:59 -  3296 - DoRewrites: Url (no decoding): '/site/script/site.js'
Tue May 31 19:46:59 -  3296 - EvaluateRules: depth=0
Tue May 31 19:46:59 -  3296 - GetServerVariable: getting 'SCRIPT_NAME'
Tue May 31 19:46:59 -  3296 - GetServerVariable: 21 bytes
Tue May 31 19:46:59 -  3296 - GetServerVariable: result '/site/style/menu.css'
Tue May 31 19:46:59 -  3296 - EvaluateRules: no RewriteBase
Tue May 31 19:46:59 -  3296 - EvaluateRules: Rule 1: pattern: ^/admin/(.*)$  subject: /site/script/site.js
Tue May 31 19:46:59 -  3296 - EvaluateRules: Rule 1: -1 (No match)
Tue May 31 19:46:59 -  3296 - EvaluateRules: Rule 2: pattern: ^.*$  subject: /site/script/site.js
Tue May 31 19:46:59 -  3296 - EvaluateRules: Rule 2: 1 matches
Tue May 31 19:46:59 -  3296 - EvaluateRules: Rule 2: evaluating condition
Tue May 31 19:46:59 -  3296 - EvalCondition: cond 0x01276D10
Tue May 31 19:46:59 -  3296 - GetServerVariable: getting 'REQUEST_FILENAME'
Tue May 31 19:46:59 -  3296 - GetServerVariable: special variable name
Tue May 31 19:46:59 -  3296 - GetServerVariable: 57 bytes
Tue May 31 19:46:59 -  3296 - GetServerVariable: result 'D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css'
Tue May 31 19:46:59 -  3296 - ReplaceServerVariables: alloc 58 bytes
Tue May 31 19:46:59 -  3296 - GetServerVariable: getting 'REQUEST_FILENAME'
Tue May 31 19:46:59 -  3296 - GetServerVariable: special variable name
Tue May 31 19:46:59 -  3296 - GetServerVariable: 57 bytes
Tue May 31 19:46:59 -  3296 - GetServerVariable: result 'D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css'
Tue May 31 19:46:59 -  3296 - ReplaceServerVariables: vName(REQUEST_FILENAME) value(D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css)
Tue May 31 19:46:59 -  3296 - ReplaceServerVariables: in='%{REQUEST_FILENAME}' out='D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css'
Tue May 31 19:46:59 -  3296 - EvalCondition: ts1 'D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css'
Tue May 31 19:46:59 -  3296 - GenerateReplacementString: src='/site/script/site.js','(null)' ReplacePattern='D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css' vec=[[  0, 20] [] ] counts=1,0
Tue May 31 19:46:59 -  3296 - GenerateReplacementString: alloc 59 bytes
Tue May 31 19:46:59 -  3296 - ApplyCaseConversion: before 'D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css'
Tue May 31 19:46:59 -  3296 - ApplyCaseConversion: after  'D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css'
Tue May 31 19:46:59 -  3296 - GenerateReplacementString: result 'D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css'
Tue May 31 19:46:59 -  3296 - EvalCondition: t(D:\Home\WWW\NicolletCountyFair\Htdocs\site\style\menu.css) op(f) p(!-f)
Tue May 31 19:46:59 -  3296 - EvalCondition: cond->SpecialConditionType= 'f'
Tue May 31 19:46:59 -  3296 - EvalCondition: Special: is it a file? (yes)
Tue May 31 19:46:59 -  3296 - EvalCondition: File variant, retVal= True
Tue May 31 19:46:59 -  3296 - EvalCondition: Cond t(%{REQUEST_FILENAME}) op(f) p(!-f) => FALSE
Tue May 31 19:46:59 -  3296 - EvalCondition: Child is NULL
Tue May 31 19:46:59 -  3296 - EvalConditionList: rule 2, FALSE, Rule does not apply
Tue May 31 19:46:59 -  3296 - EvaluateRules: returning 0
Tue May 31 19:46:59 -  3296 - DoRewrites: No Rewrite

Here, it's not clear to me why references to \site\style\menu.css are interspersed with the handling of /site/script/site.js, except that both are being retrieved at about the same time because of this HTML code:

<head>
  <link rel="stylesheet" href="/site/style/layout.css" type="text/css" />
  <link rel="stylesheet" href="/site/style/content.css" type="text/css" />
  <link rel="stylesheet" href="/site/style/menu.css" type="text/css" />
  <link rel="stylesheet" href="/site/style/form.css" type="text/css" />
  <script type="text/javascript" src="/site/script/site.js"></script>
  <link rel="shortcut icon" href="/site/image/layout/favicon.ico" type="image/x-icon" />
</head>
/site/script/site.js

Again, thanks so much for any insights/feedback you can offer.

--Bose