Proxy timeout crashing IIS6 W3SCV

Topics: Developer Forum
Oct 19, 2010 at 9:03 PM

I am using IIRF 2.1.1.23 x86 RELEASE as a reverse proxy for another W2K3 server.  In some unfortunate situations, the destination server does not respond to the request for more than 20 minutes.  When the response from the proxy'd server takes too long, IIRF crashes the W3SVC on the proxy server.  I tried setting the ProxyTimeouts receive explicitly (to 45 seconds) with the same behavoir.  When I set the ProxyTimeouts receive to infinite, the response is returned as expected.

The 20 min response is an error in itself that I'm investigating, but I wouldn't expect IIRF timeout to crash IIS.  Any idea how to fix this?

iirf.ini

RewriteLog c:\logs\iirf
RewriteLogLevel 2
IterationLimit 10
MaxMatchCount 10
RewriteEngine ON
StatusInquiry OFF

# act as a proxy for /PurchaseReview/Notification services
ProxyTimeouts - - - 45
ProxyPass          ^/purchasereview/notification/(.*)$   http://myserver/purchasereview/notification/$1 [I]
ProxyPassReverse   /         http://myserver/ [I]

# Return 404 Not Found for all other requests
RewriteRule        ^/(.*)$   - [NF]

Log detail:

 Tue Oct 19 16:41:35 -   816 - EXCEPTION
Tue Oct 19 16:41:35 -   816 - SymInit: Symbol-SearchPath: 'C:\Program Files\Ionic Shade\IIRF 2.1\;.;c:\windows\system32\inetsrv;c:\windows\system32\inetsrv;C:\WINDOWS;C:\WINDOWS\system32;SRV*C:\websymbols*http://msdl.microsoft.com/download/symbols;', symOptions: 530, UserName: 'IUSR_DEVAPP3'
Tue Oct 19 16:41:35 -   816 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Tue Oct 19 16:41:36 -   816 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 00060000)
Tue Oct 19 16:41:36 -   816 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 00060000)
Tue Oct 19 16:41:36 -   816 - Stack trace:
10007408 module(IIRF): (filename not available): LogMessage
00060000 module((module-name not available)): (filename not available): (function-name not available)
00060000 module((module-name not available)): (filename not available): (function-name not available)

Oct 22, 2010 at 7:04 PM

Set log level to 5 and captured another failure.  This is a single request.

Fri Oct 22 14:57:41 -  3324 - -------------------------------------------------------
Fri Oct 22 14:57:41 -  3324 - Ionic ISAPI Rewriting Filter (IIRF) 2.1.1.23 x86 RELEASE
Fri Oct 22 14:57:41 -  3324 - IIRF was built on: May 30 2010 13:26:57
Fri Oct 22 14:57:41 -  3324 - Cached: DLL_PROCESS_ATTACH
Fri Oct 22 14:57:41 -  3324 - Cached: Process ID: 1076
Fri Oct 22 14:57:41 -  3324 - Cached: ReadServerConfig: C:\Program Files\Ionic Shade\IIRF 2.1\IirfGlobal.ini(23): Filter Priority is now: HIGH (0x80000)
Fri Oct 22 14:57:41 -  3324 - Cached: ReadServerConfig: C:\Program Files\Ionic Shade\IIRF 2.1\IirfGlobal.ini(46): NotifyLog setting is now: OFF
Fri Oct 22 14:57:41 -  3324 - Cached: ReadServerConfig: C:\Program Files\Ionic Shade\IIRF 2.1\IirfGlobal.ini(63): RewriteEngine setting is now: ON
Fri Oct 22 14:57:41 -  3324 - Cached: DLL_PROCESS_ATTACH - complete
Fri Oct 22 14:57:41 -  3324 - Cached: GetFilterVersion
Fri Oct 22 14:57:41 -  3324 - GetLogFile: app:'/LM/W3SVC/1/ROOT'  new log:'c:\MassHousing\logs\iirf.1076.log'
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: actual log file 'c:\MassHousing\logs\iirf.1076.log'
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: ini file: 'c:\inetpub\wwwroot\Iirf.ini'
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: ini file timestamp: 2010/10/22 14:57:34 Eastern Daylight Time
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: cfg(0x01CC45E8)
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: LogLevel = 5
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: pass 2
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(10): IterationLimit 10
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(11): MaxMatchCount 10
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(12): RewriteEngine will be enabled.
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(13): StatusInquiry OFF (--) (--)
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(13): IIRF Status Inquiry is disabled.
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(20): ProxyTimeouts - - - 15
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(20): WARNING: bad value for timeout (-); setting proxy timeout to the default (30)
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(20): WARNING: bad value for timeout (-); setting proxy timeout to the default (30)
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(20): WARNING: bad value for timeout (-); setting proxy timeout to the default (30)
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(20): Proxy Timeout Values IN SECONDS are now: Resolve=30, Connect=30, Send=30, Receive=15
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(21): ProxyPass (rule 1)  '^/purchasereview/notification/(.*)$'  'http://bizdev2/purchasereview/notification/$1'      [I]
Fri Oct 22 14:57:41 -  3324 - ParseRuleModifierFlags: '[I]'
Fri Oct 22 14:57:41 -  3324 - ParseRuleModifierFlags: token 'I'
Fri Oct 22 14:57:41 -  3324 - rule: Case Insensitive match
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(22): ProxyPassReverse   /  http://bizdev2/
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: c:\inetpub\wwwroot\Iirf.ini(25): RewriteRule (rule 2)  '^/(.*)$'  '-'     [NF]
Fri Oct 22 14:57:41 -  3324 - ParseRuleModifierFlags: '[NF]'
Fri Oct 22 14:57:41 -  3324 - ParseRuleModifierFlags: token 'NF'
Fri Oct 22 14:57:41 -  3324 - rule: Not found
Fri Oct 22 14:57:41 -  3324 - ReadVdirConfig: Done reading INI for the root vdir, found 2 rules (0 errors, 3 warnings) on 26 lines
Fri Oct 22 14:57:41 -  3324 - GetVdirConfig: Obtain  vdir '/LM/W3SVC/1/ROOT' (era=0) (rc=1) (Expired=0) (ptr=0x01CC45E8)...
Fri Oct 22 14:57:41 -  3324 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Oct 22 14:57:41 -  3324 - HttpFilterProc: cfg= 0x01CC45E8
Fri Oct 22 14:57:41 -  3324 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
Fri Oct 22 14:57:41 -  3324 - DoRewrites
Fri Oct 22 14:57:41 -  3324 - GetHeader_AutoFree: getting 'url'
Fri Oct 22 14:57:41 -  3324 - GetHeader_AutoFree: 46 bytes   ptr:0x000C2008
Fri Oct 22 14:57:41 -  3324 - GetHeader_AutoFree: 'url' = '/PurchaseReview/Notification/Notification.svc'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_AutoFree: getting 'QUERY_STRING'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_AutoFree: 1 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_AutoFree: result ''
Fri Oct 22 14:57:41 -  3324 - GetHeader_AutoFree: getting 'method'
Fri Oct 22 14:57:41 -  3324 - GetHeader_AutoFree: 5 bytes   ptr:0x000C2118
Fri Oct 22 14:57:41 -  3324 - GetHeader_AutoFree: 'method' = 'POST'
Fri Oct 22 14:57:41 -  3324 - DoRewrites: New Url, before decoding: '/PurchaseReview/Notification/Notification.svc'
Fri Oct 22 14:57:41 -  3324 - DoRewrites: Url (no decoding): '/PurchaseReview/Notification/Notification.svc'
Fri Oct 22 14:57:41 -  3324 - EvaluateRules: depth=0
Fri Oct 22 14:57:41 -  3324 - GetServerVariable: getting 'SCRIPT_NAME'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable: 46 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable: result '/PurchaseReview/Notification/Notification.svc'
Fri Oct 22 14:57:41 -  3324 - EvaluateRules: no RewriteBase
Fri Oct 22 14:57:41 -  3324 - EvaluateRules: Rule 1: pattern: ^/purchasereview/notification/(.*)$  subject: /PurchaseReview/Notification/Notification.svc
Fri Oct 22 14:57:41 -  3324 - EvaluateRules: Rule 1: 2 match
Fri Oct 22 14:57:41 -  3324 - ReplaceServerVariables: alloc 46 bytes
Fri Oct 22 14:57:41 -  3324 - ReplaceServerVariables: in='http://bizdev2/purchasereview/notification/$1' out='http://bizdev2/purchasereview/notification/$1'
Fri Oct 22 14:57:41 -  3324 - GenerateReplacementString: alloc 67 bytes
Fri Oct 22 14:57:41 -  3324 - GenerateReplacementString: result 'http://bizdev2/purchasereview/notification/Notification.svc'
Fri Oct 22 14:57:41 -  3324 - EvaluateRules: Result (length 59): http://bizdev2/purchasereview/notification/Notification.svc
Fri Oct 22 14:57:41 -  3324 - EvaluateRules: returning 999
Fri Oct 22 14:57:41 -  3324 - DoRewrites: Proxy to: 'http://bizdev2/purchasereview/notification/Notification.svc'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_AutoFree: getting 'REQUEST_METHOD'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_AutoFree: 5 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_AutoFree: result 'POST'
Fri Oct 22 14:57:41 -  3324 - IirfProxy_SendRequest: http://bizdev2/purchasereview/notification/Notification.svc
Fri Oct 22 14:57:41 -  3324 - DoRewrites: requires rewrite to: '/proxy.iirf?path=/LM/W3SVC/1/ROOT&url=http://bizdev2/purchasereview/notification/Notification.svc'
Fri Oct 22 14:57:41 -  3324 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Oct 22 14:57:41 -  3324 - HttpFilterProc: cfg= 0x01CC45E8
Fri Oct 22 14:57:41 -  3324 - HttpFilterProc: SF_NOTIFY_URL_MAP
Fri Oct 22 14:57:41 -  3324 - HttpFilterProc: cfg= 0x01CC45E8
Fri Oct 22 14:57:41 -  3324 - GetVdirConfig_FromPath: Obtain  site '/LM/W3SVC/1/ROOT' (era=0) (rc=2) (Expired=0) (ptr=0x01CC45E8)...
Fri Oct 22 14:57:41 -  3324 - HttpExtensionProc: Proxy to 'http://bizdev2/purchasereview/notification/Notification.svc'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: getting 'REMOTE_ADDR'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: 13 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: result '172.19.27.35'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: getting 'LOCAL_ADDR'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: 13 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: result '172.17.3.120'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: getting 'HTTP_REFERER'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: does not exist (HTTP_REFERER)
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: 128 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: result 'HTTP_REFERER'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: getting 'HTTP_USER_AGENT'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: does not exist (HTTP_USER_AGENT)
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: 128 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: result 'HTTP_USER_AGENT'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: getting 'HTTP_ACCEPT'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: does not exist (HTTP_ACCEPT)
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: 128 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: result 'HTTP_ACCEPT'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: getting 'SERVER_NAME'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: 8 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: result 'devapp3'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: getting 'ALL_RAW'
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: 108 bytes
Fri Oct 22 14:57:41 -  3324 - GetServerVariable_EX: result 'Connection: Keep-Alive

Content-Length: 5867

Content-Type: text/xml

Expect: 100-continue

Host: devapp3

'
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: http://bizdev2/purchasereview/notification/Notification.svc
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: url(http://bizdev2/purchasereview/notification/Notification.svc)
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: host(bizdev2)  path+query(/purchasereview/notification/Notification.svc)
Fri Oct 22 14:57:41 -  3324 - ParseAllRaw: Connection: Keep-Alive

Content-Length: 5867

Content-Type: text/xml

Expect: 100-continue

Host: devapp3

Fri Oct 22 14:57:41 -  3324 - ParseAllRaw: hdr Connection: Keep-Alive
Fri Oct 22 14:57:41 -  3324 - ParseAllRaw: hdr Content-Length: 5867
Fri Oct 22 14:57:41 -  3324 - ParseAllRaw: hdr Content-Type: text/xml
Fri Oct 22 14:57:41 -  3324 - ParseAllRaw: hdr Expect: 100-continue
Fri Oct 22 14:57:41 -  3324 - ParseAllRaw: hdr Host: devapp3
Fri Oct 22 14:57:41 -  3324 - ParseAllRaw: found 5 headers
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: rh(0x01CC45D0) nh(bizdev2) sn(devapp3) la(172.17.3.120) ra(172.19.27.35) ts(5867)
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header Host: bizdev2
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header Via: 1.1 172.17.3.120 (IIRF v2.1)
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header X-Forwarded-Server: devapp3
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header X-Forwarded-For: 172.19.27.35
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header Connection: Keep-Alive
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header Content-Length: 5867
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header Content-Type: text/xml
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header Expect: 100-continue
Fri Oct 22 14:57:41 -  3324 - GenProxyRequestHeadersString: header X-Forwarded-Host: devapp3
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: varAccept 0x01CC4EB0 (HTTP_ACCEPT)
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: WinHttpConnect bizdev2 80
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: WinHttpOpenRequest POST /purchasereview/notification/Notification.svc
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: WinHttpAddRequestHeaders
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: WinHttpSendRequest  totalLength(5867/5867)
Fri Oct 22 14:57:41 -  3324 - Cached: DLL_THREAD_DETACH
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: WinHttpWriteData  bytes(5867)
Fri Oct 22 14:57:41 -  3324 - ProxyPostRequest: WinHttpReceiveResponse
Fri Oct 22 14:57:57 -  3324 - GetServerVariable_EX: getting 'SERVER_PORT'
Fri Oct 22 14:57:57 -  3324 - GetServerVariable_EX: 3 bytes
Fri Oct 22 14:57:57 -  3324 - GetServerVariable_EX: result '80'
Fri Oct 22 14:57:57 -  3324 - GetServerVariable_EX: getting 'HTTPS'
Fri Oct 22 14:57:57 -  3324 - GetServerVariable_EX: 4 bytes
Fri Oct 22 14:57:57 -  3324 - GetServerVariable_EX: result 'off'
Fri Oct 22 14:57:57 -  3324 - Proxy_SetResponseHeaders: starting status 10408
Fri Oct 22 14:57:57 -  3324 - Proxy_SetResponseHeaders: status TIMEOUT?
Fri Oct 22 14:57:57 -  3324 - Proxy_SetResponseHeaders: status string '408 Request Time-out'
Fri Oct 22 14:57:57 -  3324 - EXCEPTION
Fri Oct 22 14:57:57 -  3324 - SymInit: Symbol-SearchPath: 'C:\Program Files\Ionic Shade\IIRF 2.1\;.;c:\windows\system32\inetsrv;c:\windows\system32\inetsrv;C:\WINDOWS;C:\WINDOWS\system32;SRV*C:\websymbols*http://msdl.microsoft.com/download/symbols;', symOptions: 530, UserName: 'IUSR_DEVAPP3'
Fri Oct 22 14:57:57 -  3324 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Fri Oct 22 14:57:57 -  3324 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 00060000)
Fri Oct 22 14:57:57 -  3324 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 00060000)
Fri Oct 22 14:57:57 -  3324 - Stack trace:
10007408 module(IIRF): (filename not available): LogMessage
00060000 module((module-name not available)): (filename not available): (function-name not available)
00060000 module((module-name not available)): (filename not available): (function-name not available)

Coordinator
Oct 23, 2010 at 8:38 PM

ok that's helpful.

From that it looks like there's a bad call to LogMessage(), or a bad call within LogMessage(), that occurs after a proxy timeout. If that's the case I should be able to find it based on a simple code inspection.

 

Coordinator
Oct 23, 2010 at 8:42 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.