REQUEST_FILENAME is empty for many requests

Jan 8, 2010 at 9:14 PM

I'm working on XP (IIS 5.1) using IIRF 2.0.1.15 and just starting to try to get it working. I've copied a basic IIRF.ini file as follows (this is prep for a WordPress blog):

RewriteLog  c:\temp\iirfLog.out
RewriteLogLevel 5
StatusUrl   /iirfStatus
RewriteEngine On
RewriteCond %{REQUEST_FILENAME}     !-f                                    
RewriteCond %{REQUEST_FILENAME}     !-d                                    
RewriteRule . /index.php [L]

When I request a CSS file that exists, the IIRF log reports that it doesn't exist because the ServerVariable REQUEST_FILENAME returns '' (see log below) and hence the URL is rewritten. Any idea why REQUEST_FILENAME is empty for some requests for files that do exist? The log below lists the request for the file while RewriteEngine is On, then the second request that properly returns the CSS with RewriteEngine Off. This happens not just for some (but not all) *.css but also for *.js, *.png, *.php and more.

I've seen another post where someone reported that their homepage was returned for every request and suspect this is the same symptom.

Here is the log:

Fri Jan 08 14:43:00 - 37984 - -------------------------------------------------------
Fri Jan 08 14:43:00 - 37984 - Ionic ISAPI Rewriting Filter (IIRF) 2.0.1.15 RELEASE
Fri Jan 08 14:43:00 - 37984 - IIRF was built on: Dec  3 2009 11:49:15
Fri Jan 08 14:43:00 - 37984 - Cached: DLL_PROCESS_ATTACH
Fri Jan 08 14:43:00 - 37984 - Cached: Process ID: 29152
Fri Jan 08 14:43:00 - 37984 - Cached: DLL_PROCESS_ATTACH - complete
Fri Jan 08 14:43:00 - 37984 - Cached: GetFilterVersion
Fri Jan 08 14:43:00 - 37984 - GetLogFile: app:'/LM/W3SVC/1/ROOT'  new log:'c:\temp\iirfLog.out.29152.log'
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: actual log file 'c:\temp\iirfLog.out.29152.log'
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: ini file: '............\Web sites\simmonsconsulting.com\Iirf.ini'
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: ini file timestamp: 2010/01/08 14:41:48 Central Standard Time
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: line  16: LogLevel = 5
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: pass 1
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: line  21: StatusUrl /iirfStatus
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: line  21: StatusUrl is enabled for local requests only.
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: line  29: RewriteRule (rule 1)  '^/sitemap.xml$'  '-'      [L]
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: not a duplicate rule...
Fri Jan 08 14:43:00 - 37984 - ParseRuleModifierFlags: '[L]'
Fri Jan 08 14:43:00 - 37984 - ParseRuleModifierFlags: token 'L'
Fri Jan 08 14:43:00 - 37984 - rule: Last
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: line  53: RewriteCond   %{REQUEST_FILENAME}  !-f
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: line  54: RewriteCond   %{REQUEST_FILENAME}  !-d
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: line  55: RewriteRule (rule 2)  '.'  '/index.php'      [L]
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: not a duplicate rule...
Fri Jan 08 14:43:00 - 37984 - ParseRuleModifierFlags: '[L]'
Fri Jan 08 14:43:00 - 37984 - ParseRuleModifierFlags: token 'L'
Fri Jan 08 14:43:00 - 37984 - rule: Last
Fri Jan 08 14:43:00 - 37984 - ReadSiteConfig: Done reading, found 2 rules (0 errors, 0 warnings) on 56 lines
Fri Jan 08 14:43:00 - 37984 - GetSiteConfig: Obtain  site '/LM/W3SVC/1/ROOT' (era=0) (rc=1) (Expired=0) (ptr=0x01925128)...
Fri Jan 08 14:43:00 - 37984 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 37984 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 37984 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
Fri Jan 08 14:43:00 - 37984 - DoRewrites
Fri Jan 08 14:43:00 - 37984 - GetServerVariable_AutoFree: getting 'url'
Fri Jan 08 14:43:00 - 37984 - GetServerVariable_AutoFree: 128 bytes
Fri Jan 08 14:43:00 - 37984 - GetServerVariable_AutoFree: result ''
Fri Jan 08 14:43:00 - 37984 - GetHeader_AutoFree: getting 'url'
Fri Jan 08 14:43:00 - 37984 - GetHeader_AutoFree: 72 bytes   ptr:0x0011C7D0
Fri Jan 08 14:43:00 - 37984 - GetHeader_AutoFree: 'url' = '/wp-content/themes/simmonsconsultingweathered/resize-textarea/style.css'
Fri Jan 08 14:43:00 - 37984 - GetServerVariable_AutoFree: getting 'QUERY_STRING'
Fri Jan 08 14:43:00 - 37984 - GetServerVariable_AutoFree: 1 bytes
Fri Jan 08 14:43:00 - 37984 - GetServerVariable_AutoFree: result ''
Fri Jan 08 14:43:00 - 37984 - GetHeader_AutoFree: getting 'method'
Fri Jan 08 14:43:00 - 37984 - GetHeader_AutoFree: 4 bytes   ptr:0x0011C8E0
Fri Jan 08 14:43:00 - 37984 - GetHeader_AutoFree: 'method' = 'GET'
Fri Jan 08 14:43:00 - 37984 - DoRewrites: New Url, before decoding: '/wp-content/themes/simmonsconsultingweathered/resize-textarea/style.css' 
Fri Jan 08 14:43:00 - 37984 - DoRewrites: Url (no decoding): '/wp-content/themes/simmonsconsultingweathered/resize-textarea/style.css'
Fri Jan 08 14:43:00 - 37984 - EvaluateRules: depth=0
Fri Jan 08 14:43:00 - 37984 - EvaluateRules: Rule 1 : -1 (No match)
Fri Jan 08 14:43:00 - 37984 - EvaluateRules: Rule 2 : 1 matches
Fri Jan 08 14:43:00 - 37984 - GetServerVariable: getting 'REQUEST_FILENAME'
Fri Jan 08 14:43:00 - 37984 - GetServerVariable: special variable name
Fri Jan 08 14:43:00 - 37984 - GetServerVariable: 150 bytes
Fri Jan 08 14:43:00 - 37984 - GetServerVariable: result ''
Fri Jan 08 14:43:00 - 37984 - ReplaceServerVariables: VariableName='REQUEST_FILENAME' Value=''
Fri Jan 08 14:43:00 - 37984 - ReplaceServerVariables: in='%{REQUEST_FILENAME}' out=''
Fri Jan 08 14:43:00 - 37984 - EvalCondition: ts1 ''
Fri Jan 08 14:43:00 - 37984 - GenerateReplacementString: result ''
Fri Jan 08 14:43:00 - 37984 - EvalCondition: checking '' against pattern '!-f'
Fri Jan 08 14:43:00 - 37984 - EvalCondition: cond->SpecialConditionType= 'f'
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Special: it is not a file
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Special, retVal= false
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Cond %{REQUEST_FILENAME} !-f => TRUE
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Child is non NULL (parent= 0x019226C0) (child= 0x019224C8)
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Current condition evaluates to TRUE
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Logical AND, ergo we evaluate the Child
Fri Jan 08 14:43:00 - 37984 - GetServerVariable: getting 'REQUEST_FILENAME'
Fri Jan 08 14:43:00 - 37984 - GetServerVariable: special variable name
Fri Jan 08 14:43:00 - 37984 - GetServerVariable: 150 bytes
Fri Jan 08 14:43:00 - 37984 - GetServerVariable: result ''
Fri Jan 08 14:43:00 - 37984 - ReplaceServerVariables: VariableName='REQUEST_FILENAME' Value=''
Fri Jan 08 14:43:00 - 37984 - ReplaceServerVariables: in='%{REQUEST_FILENAME}' out=''
Fri Jan 08 14:43:00 - 37984 - EvalCondition: ts1 ''
Fri Jan 08 14:43:00 - 37984 - GenerateReplacementString: result ''
Fri Jan 08 14:43:00 - 37984 - EvalCondition: checking '' against pattern '!-d'
Fri Jan 08 14:43:00 - 37984 - EvalCondition: cond->SpecialConditionType= 'd'
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Special: it is not a directory
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Special, retVal= false
Fri Jan 08 14:43:00 - 37984 - EvalCondition: Cond %{REQUEST_FILENAME} !-d => TRUE
Fri Jan 08 14:43:00 - 37984 - EvalConditionList: rule 2, TRUE, Rule will apply
Fri Jan 08 14:43:00 - 37984 - ReplaceServerVariables: in='/index.php' out='/index.php'
Fri Jan 08 14:43:00 - 37984 - GenerateReplacementString: result '/index.php'
Fri Jan 08 14:43:00 - 37984 - EvaluateRules: Result (length 10): /index.php
Fri Jan 08 14:43:00 - 37984 - EvaluateRules: Last Rule
Fri Jan 08 14:43:00 - 37984 - EvaluateRules: returning 1
Fri Jan 08 14:43:00 - 37984 - DoRewrites: Rewrite Url to: '/index.php'
Fri Jan 08 14:43:00 - 37984 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 37984 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 37984 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 37984 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 31328 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 31328 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 31328 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 31328 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 31328 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 31328 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 37524 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 37524 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 37524 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 37524 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 37524 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 14:43:00 - 37524 - HttpFilterProc: cfg= 0x01925128
Fri Jan 08 14:43:00 - 35884 - HttpFilterProc: SF_NOTIFY_LOG
Fri Jan 08 14:43:00 - 35884 - ReleaseOrExpireSiteConfig: site '/LM/W3SVC/1/ROOT' (era=0) (rc=0) (Expired=0) (ptr=0x01925128)...

(Updated ini to turn RewriteEngine Off ... the request returned the CSS as expected)

Fri Jan 08 15:06:30 - 35884 - Cached: DLL_THREAD_DETACH
Fri Jan 08 15:06:30 - 35884 - Cached: DLL_THREAD_DETACH
Fri Jan 08 15:06:30 - 35884 - Cached: DLL_THREAD_DETACH
Fri Jan 08 15:06:30 - 35884 - Cached: DLL_THREAD_DETACH
Fri Jan 08 15:06:30 - 35884 - Cached: DLL_THREAD_DETACH
Fri Jan 08 15:06:30 - 35884 - Cached: DLL_THREAD_DETACH
Fri Jan 08 15:06:30 - 35884 - IsIniFileUpdated: ............\Web sites\simmonsconsulting.com\Iirf.ini YES
Fri Jan 08 15:06:30 - 35884 - GetSiteConfig: Obtain  site '/LM/W3SVC/1/ROOT' , Ini file has been updated.
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: actual log file 'c:\temp\iirfLog.out.29152.log'
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: ini file: '............\Web sites\simmonsconsulting.com\Iirf.ini'
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: ini file timestamp: 2010/01/08 15:06:11 Central Standard Time
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: line  16: LogLevel = 5
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: pass 1
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: line  21: StatusUrl /iirfStatus
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: line  21: StatusUrl is enabled for local requests only.
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: line  25: Rewriting will be disabled.
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: line  29: RewriteRule (rule 1)  '^/sitemap.xml$'  '-'      [L]
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: not a duplicate rule...
Fri Jan 08 15:06:30 - 35884 - ParseRuleModifierFlags: '[L]'
Fri Jan 08 15:06:30 - 35884 - ParseRuleModifierFlags: token 'L'
Fri Jan 08 15:06:30 - 35884 - rule: Last
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: line  53: RewriteCond   %{REQUEST_FILENAME}  !-f
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: line  54: RewriteCond   %{REQUEST_FILENAME}  !-d
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: line  55: RewriteRule (rule 2)  '.'  '/index.php'      [L]
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: not a duplicate rule...
Fri Jan 08 15:06:30 - 35884 - ParseRuleModifierFlags: '[L]'
Fri Jan 08 15:06:30 - 35884 - ParseRuleModifierFlags: token 'L'
Fri Jan 08 15:06:30 - 35884 - rule: Last
Fri Jan 08 15:06:30 - 35884 - ReadSiteConfig: Done reading, found 2 rules (0 errors, 0 warnings) on 56 lines
Fri Jan 08 15:06:30 - 35884 - ReleaseOrExpireSiteConfig: site '/LM/W3SVC/1/ROOT' (era=0) (rc=0) (Expired=1) (ptr=0x01925128)...
Fri Jan 08 15:06:30 - 35884 - GetSiteConfig: Obtain  site '/LM/W3SVC/1/ROOT' (era=1) (rc=1) (Expired=0) (ptr=0x01924DC0)...
Fri Jan 08 15:06:30 - 35884 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Jan 08 15:06:30 - 35884 - HttpFilterProc: cfg= 0x01924DC0
Fri Jan 08 15:06:30 - 35884 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
Fri Jan 08 15:06:30 - 35884 - DoRewrites
Fri Jan 08 15:06:30 - 35884 - GetServerVariable_AutoFree: getting 'url'
Fri Jan 08 15:06:30 - 35884 - GetServerVariable_AutoFree: 128 bytes
Fri Jan 08 15:06:30 - 35884 - GetServerVariable_AutoFree: result ''
Fri Jan 08 15:06:30 - 35884 - GetHeader_AutoFree: getting 'url'
Fri Jan 08 15:06:30 - 35884 - GetHeader_AutoFree: 72 bytes   ptr:0x0011E510
Fri Jan 08 15:06:30 - 35884 - GetHeader_AutoFree: 'url' = '/wp-content/themes/simmonsconsultingweathered/resize-textarea/style.css'
Fri Jan 08 15:06:30 - 35884 - GetServerVariable_AutoFree: getting 'QUERY_STRING'
Fri Jan 08 15:06:30 - 35884 - GetServerVariable_AutoFree: 1 bytes
Fri Jan 08 15:06:30 - 35884 - GetServerVariable_AutoFree: result ''
Fri Jan 08 15:06:30 - 35884 - GetHeader_AutoFree: getting 'method'
Fri Jan 08 15:06:30 - 35884 - GetHeader_AutoFree: 4 bytes   ptr:0x0010D4E0
Fri Jan 08 15:06:30 - 35884 - GetHeader_AutoFree: 'method' = 'GET'
Fri Jan 08 15:06:30 - 35884 - DoRewrites: New Url, before decoding: '/wp-content/themes/simmonsconsultingweathered/resize-textarea/style.css' 
Fri Jan 08 15:06:30 - 35884 - DoRewrites: Url (no decoding): '/wp-content/themes/simmonsconsultingweathered/resize-textarea/style.css'
Fri Jan 08 15:06:30 - 35884 - EvaluateRules: depth=0
Fri Jan 08 15:06:30 - 35884 - DoRewrites: No Rewrite
Fri Jan 08 15:06:30 - 35884 - HttpFilterProc: SF_NOTIFY_LOG
Fri Jan 08 15:06:30 - 35884 - ReleaseOrExpireSiteConfig: site '/LM/W3SVC/1/ROOT' (era=1) (rc=0) (Expired=0) (ptr=0x01924DC0)...

Thanks so much for your help!

Cheers,
Toby

 

Coordinator
Jan 8, 2010 at 9:37 PM

I don't know why REQUEST_FILENAME is not always being set.   You could also try PATH_TRANSLATED.  That may give you what you want.

ps: do you really ahve the date on your machine set to "2 years ago". ? 

To avoid buying a license?   Really?  

Jan 8, 2010 at 9:44 PM

I'll try PATH_TRANSLATED but my computer date is set for today ... I don't know why you think it's not but that was just damn rude. I believe in paying for software, I develop software and fully expect to be compensated for it so I pay for what I use.

Really, indeed ...

Coordinator
Jan 8, 2010 at 10:04 PM

sorry - I misread the date ?? tired I guess

 

Jan 8, 2010 at 10:12 PM

No problem. :-)

Thanks for the reply. It appears that PATH_TRANSLATED resolves to the physical root of the web site for every request (based on the log file) so this is a no go as well. Any other ideas?

Coordinator
Jan 9, 2010 at 10:15 AM

That's Curious - I thought PATH_TRANSLATED would resolve to the path of the script or resource.  What's the full URL in your case? 

That may be irrelevvant - why don't you just put a RewriteRule in there for .css resources (and whatever else you need to rewrite)?

# Don't rewrite any .css URLs
RewriteRule   \.css$  -  [L]

 

 

Jan 10, 2010 at 11:21 PM

I could put in a rule for .css, .js, .jpg, .png ... etc. But I'd rather not try to figure out every possible extension that should be served statically if I can figure out why REQUEST_FILENAME isn't being set properly for each request. I'm digging into the code to see what's up.

Thanks.

Jan 11, 2010 at 12:46 AM
Edited Jan 11, 2010 at 12:54 AM

Okay, I think I've figured it out. On line 2339 of Rewriter.c is where you get the value for what will become the REQUEST_FILENAME from the request context. The statement is:

            strcpy_s(pszBuf,SERVER_VAR_BUFFER_SIZE_DEFAULT,ctx->PhysicalPath);

This is fine so long as the length of the value for PhysicalPath doesn't exceed SERVER_VAR_BUFFER_SIZE_DEFAULT which is defined in IirfConstants.h to be 128. Every request for an item whose PhysicalPath value is longer than 128 characters will be reported as '' (since strcpy_s() will ignore the copy if the value of the source is larger than the destination, at least I belive that is the case.)

I don't know how you would want to handle paths longer than this value (we have tons of documents to be served whose physical path would be longer than 128 characters!) I could propose a routine that tries to remalloc pszBuf to the size of the PhysicalPath value but you might want to handle it a different way. What do you think?

**edit** Come to think of it, what if the value of any ServerVariable is larger than 128 bytes? Shouldn't you malloc() the amount needed depending on the strlen() of the requested variable, otherwise *ANY* value over 128 characters will be returned as ''?

**edit II** Duh, you do handle the resizing of the destination if the ServerVariable is larger than the default, but less than the _MAX. Ignore my last edit, but I think the REQUEST_FILENAME needs the same treatment. :-)

Thanks & Cheers,

Toby

Coordinator
Jan 11, 2010 at 2:57 AM

That sounds right - good catch. I can fix this pretty easily.

 

Jan 11, 2010 at 8:23 PM
Edited Jan 11, 2010 at 8:46 PM

I've created a diff that includes using similar logic as the block below it. It's listed below. Dunno if this is the way you want to handle it or not but, FWIW, this seems to work.

2339c2339
<             strcpy_s(pszBuf,SERVER_VAR_BUFFER_SIZE_DEFAULT,ctx->PhysicalPath);
---
>             // Check for enough space for the full value
2340a2341,2365
>             LogMessage(cfg, 5,"Value (size): '%s' (%d bytes) from context", ctx->PhysicalPath, cbBuf);
>             if(cbBuf<SERVER_VAR_BUFFER_SIZE_DEFAULT) {
>                 LogMessage(cfg, 5,"cbBuf is less than the default buffer, just copy");
>                 strcpy_s(pszBuf,SERVER_VAR_BUFFER_SIZE_DEFAULT,ctx->PhysicalPath);
>             }
>             else if (cbBuf+1 < SERVER_VAR_BUFFER_SIZE_MAX) {
>                 //
>                 // Buffer is not large enough.
>                 // Reallocate but bound it to MAX_BUFFER_SIZE.
>                 // We could try to use cbBuf as the buffer size, but I have a hard limit at MAX_B_SIZE
>                 // just to be safe.
>                 //
>                 free(pszBuf);
>                 pszBuf = (CHAR *) malloc(cbBuf+1);
>                 if ( pszBuf == NULL ) {
>                     SetLastError( ERROR_NOT_ENOUGH_MEMORY );
>                     goto GSV2_Finished;
>                 }
>
>                 pszBuf[0]='\0';
>                 strcpy_s(pszBuf,cbBuf+1,ctx->PhysicalPath);
>             }
>             else {
>                 LogMessage(cfg, 5,"Length of REQUEST_FILENAME would exceed maximum allowed: %d bytes needed", cbBuf);
>             }

BTW, this is against the source zip I downloaded, not what is in SVN.

Coordinator
Jan 11, 2010 at 10:19 PM

Thanks, that works.