2.1.1.23 crashing app pool

Jun 17, 2010 at 1:23 PM
Edited Jun 17, 2010 at 3:47 PM

Hi-

I tried the latest 2.1.1.23 binary because it solves a ProxyPass issue I was having, however I am running into larger issues with IIRF errors and the application pool resetting.  I am using the 32 bit version on both IIS 6 and IIS 7 and have similar results on both servers.

I get no errors or warnings parsing the config (which works on 2.1.1.8), just while it is running.  The event log on IIS 6 reports "A process serving application pool 'DNN' suffered a fatal communication error with the World Wide Web Publishing Service." and IIS 7 "Faulting application w3wp.exe, version 7.0.6001.18000, time stamp 0x47919413, faulting module ntdll.dll, version 6.0.6001.18000, time stamp 0x4791a783, exception code 0xc0000374, fault offset 0x000aada3, process id 0x1938, application start time 0x01cb0d82df706610."

After these errors, the app pool will restart and I will get the errors again over and over.

The IIRF log shows errors like the following (IIS 6):

Wed Jun 16 14:48:29 -  6588 - EXCEPTION
Wed Jun 16 14:48:29 -  6588 - SymInit: Symbol-SearchPath: 'C:\WINDOWS\system32\inetsrv\ionic\;.;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: '*******'
Wed Jun 16 14:48:29 -  6588 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Wed Jun 16 14:48:29 -  6588 - Stack trace:
5A397636 module(w3core): (filename not available): (function-name not available)
5A398A0A module(w3core): (filename not available): (function-name not available)
1000B30C module(IIRF): (filename not available): Iirf_EvaluateRules
1000B30C module(IIRF): (filename not available): Iirf_EvaluateRules

and

Wed Jun 16 14:16:14 -  7040 - EXCEPTION
Wed Jun 16 14:16:14 -  7040 - SymInit: Symbol-SearchPath: 'C:\WINDOWS\system32\inetsrv\ionic\;.;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: '*******'
Wed Jun 16 14:16:14 -  7040 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Wed Jun 16 14:16:14 -  7040 - EXCEPTION
Wed Jun 16 14:16:14 -  7040 - SymInit: Symbol-SearchPath: 'C:\WINDOWS\system32\inetsrv\ionic\;.;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: '*******'
Wed Jun 16 14:16:14 -  7040 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Wed Jun 16 14:16:15 -  7040 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 2E30386D)
Wed Jun 16 14:16:15 -  7040 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 2E30386D)
Wed Jun 16 14:16:15 -  7040 - Stack trace:
7C82A774 module(ntdll): (filename not available): wcslen
7C82A84B module(ntdll): (filename not available): wcslen
1001883E module(IIRF): (filename not available): Iirf_EvaluateRules
1000C146 module(IIRF): (filename not available): Iirf_EvaluateRules
2E30386D module((module-name not available)): (filename not available): (function-name not available)
2E30386D module((module-name not available)): (filename not available): (function-name not available)

and

Wed Jun 16 13:30:29 -  3868 - ReadVdirConfig: Done reading INI for the root vdir, found 4 rules (0 errors, 0 warnings) on 290 lines
Wed Jun 16 13:30:49 -  3868 - EvalCondition: WARNING: match result: -4 (unknown error)
Wed Jun 16 13:30:49 -  3868 - EvalCondition: WARNING: match result: -4 (unknown error)

and

Wed Jun 16 13:30:11 -  4356 - EXCEPTION
Wed Jun 16 13:30:11 -  4356 - SymInit: Symbol-SearchPath: 'C:\WINDOWS\system32\inetsrv\ionic\;.;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: '*******'
Wed Jun 16 13:30:11 -  4356 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Wed Jun 16 13:30:11 -  4356 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 646E756F)
Wed Jun 16 13:30:11 -  4356 - ERROR: StackWalk64-Endless-Callstack!, GetLastError: 0 (Address: 001002EE)
Wed Jun 16 13:30:11 -  4356 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 646E756F)
Wed Jun 16 13:30:11 -  4356 - ERROR: StackWalk64-Endless-Callstack!, GetLastError: 0 (Address: 001002EE)
Wed Jun 16 13:30:11 -  4356 - Stack trace:
10017035 module(IIRF): (filename not available): Iirf_EvaluateRules
646E756F module((module-name not available)): (filename not available): (function-name not available)

over and over again.

IIS 7 shows differently in the log:

Wed Jun 16 14:27:47 -  9796 - EXCEPTION
Wed Jun 16 14:27:47 -  9796 - SymInit: Symbol-SearchPath: 'C:\Program Files\Ionic\;.;C:\Windows\SysWOW64\inetsrv;C:\Windows\SysWOW64\inetsrv;C:\Windows;C:\Windows\system32;SRV*C:\websymbols*http://msdl.microsoft.com/download/symbols;', symOptions: 530, UserName: '*******'
Wed Jun 16 14:27:47 -  9796 - OS-Version: 6.0.6001 (Service Pack 1) 0x110-0x3
Wed Jun 16 14:27:47 -  9796 - EXCEPTION
Wed Jun 16 14:27:47 -  9796 - SymInit: Symbol-SearchPath: 'C:\Program Files\Ionic\;.;C:\Windows\SysWOW64\inetsrv;C:\Windows\SysWOW64\inetsrv;C:\Windows;C:\Windows\system32;SRV*C:\websymbols*http://msdl.microsoft.com/download/symbols;', symOptions: 530, UserName: '*******'
Wed Jun 16 14:27:47 -  9796 - OS-Version: 6.0.6001 (Service Pack 1) 0x110-0x3
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 01CBC3B0)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 550974ED)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 00C67DE8)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 04C48300)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: CC248C8B)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 8B000006)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 5F102444)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: CC335D5E)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: 00BCCCE8)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: C4C48100)
Wed Jun 16 14:27:48 -  9796 - ERROR: SymGetModuleInfo64, GetLastError: 1114 (Address: C2000006)
7779F8F4 module(ntdll): (filename not available): RtlTryEnterCriticalSection
7779F26C module(ntdll): (filename not available): RtlDeactivateActivationContextUnsafeFast
75923621 module(kernel32): (filename not available): HeapFree
7480883E module(IIRF): (filename not available): Iirf_EvaluateRules
747FC146 module(IIRF): (filename not available): Iirf_EvaluateRules
01CBC3B0 module((module-name not available)): (filename not available): (function-name not available)
550974ED module((module-name not available)): (filename not available): (function-name not available)
00C67DE8 module((module-name not available)): (filename not available): (function-name not available)
04C48300 module((module-name not available)): (filename not available): (function-name not available)
CC248C8B module((module-name not available)): (filename not available): (function-name not available)
8B000006 module((module-name not available)): (filename not available): (function-name not available)
5F102444 module((module-name not available)): (filename not available): (function-name not available)

 

I have replaced the release binary with the debug one and the pdb to attempt to get a better stack trace - right now the app pool is just resetting without logging anything but the above error in the event log.

Oh and sorry this post is so long - I hope the error logs can give some insight

Jun 17, 2010 at 2:12 PM

There is a locking issue it seems:

 

Detected a possible critical section related problem in w3wp.exe__DNN__PID__5216__Date__06_17_2010__Time_08_57_31AM__328__Manual Dump.dmp
Lock at ntdll!LdrpLoaderLock is Unlocked
Impact analysis

36.36% of threads blocked

Detected a possible critical section related problem in w3wp.exe__DNN__PID__5216__Date__06_17_2010__Time_08_57_31AM__328__Manual Dump.dmp
Lock at IIRF!TerminateFilter+b2ef5 is Unlocked
Impact analysis

18.18% of threads blocked

 

A number of threads that look like this:

Thread 6 - System ID 5372

This thread is waiting on critical section IIRF!TerminateFilter+b2ef5

Function   Source
ntdll!KiFastSystemCallRet   
ntdll!ZwWaitForSingleObject+c   
ntdll!RtlpWaitOnCriticalSection+1a3   
ntdll!RtlEnterCriticalSection+a8   
IIRF!TerminateFilter+362c2   
IIRF!TerminateFilter+3141c   
IIRF!TerminateFilter+31364   
IIRF!TerminateFilter+31311   
IIRF!TerminateFilter+24730   
IIRF!TerminateFilter+125dd   
IIRF!TerminateFilter+11a06   
IIRF!TerminateFilter+effe   
IIRF!TerminateFilter+f629   
IIRF!TerminateFilter+fa3f   
w3core!W3_FILTER_CONTEXT::NotifyFilters+52d   
w3core!W3_FILTER_CONTEXT::NotifyAuthComplete+39   
w3core!W3_MAIN_CONTEXT::NotifyFilters+d0   
w3core!W3_STATE_AUTHENTICATION::DoWork+967   
w3core!W3_MAIN_CONTEXT::DoWork+a6   
w3core!W3_MAIN_CONTEXT::OnNewRequest+55   
w3dt!UL_NATIVE_REQUEST::DoStateProcess+48   
w3dt!UL_NATIVE_REQUEST::DoWork+7f   
w3dt!OverlappedCompletionRoutine+1a   
w3tp!THREAD_POOL_DATA::ThreadPoolThread+73   
w3tp!THREAD_POOL_DATA::ThreadPoolThread+24   
w3tp!THREAD_MANAGER::ThreadManagerThread+39   

kernel32!BaseThreadStart+34

 

Then the rest are waiting for the ntdll lock to release:

Thread 17 - System ID 6520

This thread is waiting on critical section ntdll!LdrpLoaderLock

Function   Source
ntdll!KiFastSystemCallRet   
ntdll!ZwWaitForSingleObject+c   
ntdll!RtlpWaitOnCriticalSection+1a3   
ntdll!RtlEnterCriticalSection+a8   
ntdll!LdrpInitializeThread+68   
ntdll!_LdrpInitialize+16f   
ntdll!KiUserApcDispatcher+25
Coordinator
Jun 17, 2010 at 2:22 PM
It looks like a problem with memory corruption. That would explain the problem with wcslen as well as the problem with the critical section lock. But it's hard to know. It would be good to get the log statements immediately preceding the EXCEPTION in the IIRF log for IIS6. Also - I don't understand why the stacktrace is corrupt. Are you using the 32-bit DLL on a 64-bit server? If the problem is reproducable, it would be good to get a complete logfile (with the stacktrace and the immediately preceding statements) using the debug version of IIRF. You'd need to install both the dll and the .pdb in order to get the proper symbols to display in the stacktrace.
Jun 17, 2010 at 2:27 PM
Edited Jun 17, 2010 at 3:47 PM

It's not memory corruption - it's happening on all 3 of my servers.

Here is the log file with the debug version as promised

 

Thu Jun 17 08:51:59 -  3984 - ReadVdirConfig: Done reading INI for the root vdir, found 4 rules (0 errors, 0 warnings) on 296 lines
Thu Jun 17 08:52:37 -  1892 - EXCEPTION
Thu Jun 17 08:52:37 -  1892 - SymInit: Symbol-SearchPath: 'C:\WINDOWS\system32\inetsrv\ionic\;.;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: '*******'
Thu Jun 17 08:52:37 -  1892 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Thu Jun 17 08:52:38 -  1892 - Stack trace:
7C8417DF module(ntdll): (filename not available): RtlSecondsSince1970ToTime
f:\dd\vctools\crt_bld\self_x86\crt\src\malloc.c (105): _heap_alloc_base
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (427): _heap_alloc_dbg_impl
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (239): _nh_malloc_dbg_impl
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (296): _nh_malloc_dbg
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgmalloc.c (56): malloc
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1895): GenerateReplacementString
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (2583): Iirf_EvaluateRules
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (879): DoRewrites
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1075): OnAuthComplete
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1239): HttpFilterProc
5A3988A4 module(w3core): (filename not available): (function-name not available)
5A3C14A6 module(w3core): (filename not available): UlW3Start
5A3A4DBE module(w3core): (filename not available): W3_FILE_INFO_CACHE::GetFileInfo
5A3A14F1 module(w3core): (filename not available): W3_FILE_INFO_CACHE::GetFileInfo
5A392274 module(w3core): (filename not available): (function-name not available)
5A3965FA module(w3core): (filename not available): (function-name not available)
5A3616CF module(w3dt): (filename not available): UlAtqAllocateMemory
5A3616FA module(w3dt): (filename not available): UlAtqAllocateMemory
5A3024CE module(W3TP): (filename not available): THREAD_POOL::PostCompletion
5A3026AC module(W3TP): (filename not available): THREAD_POOL::~THREAD_POOL
5A301DA9 module(W3TP): (filename not available): (function-name not available)
77E6482F module(kernel32): (filename not available): GetModuleHandleA
77E6482F module(kernel32): (filename not available): GetModuleHandleA

 

Jun 17, 2010 at 2:29 PM
Edited Jun 17, 2010 at 2:30 PM

Sorry I didn't have symbols attached when I did the dump - here is the corrected version.  It appears to have to do with the server variables function as I noticed the more server variable references I had in my rules, the faster it would crash

Thread 6 - System ID 5372

This thread is waiting on critical section IIRF!_newmode+37c

Function   Source
ntdll!KiFastSystemCallRet   
ntdll!ZwWaitForSingleObject+c   
ntdll!RtlpWaitOnCriticalSection+1a3   
ntdll!RtlEnterCriticalSection+a8   
IIRF!_lock+3d   
IIRF!_heap_alloc+67   
IIRF!_nh_malloc_dbg+7f   
IIRF!_nh_malloc_dbg+2c   
IIRF!malloc+1b   
IIRF!GetServerVariable+1f8   
IIRF!Iirf_EvaluateRules+1c1   
IIRF!DoRewrites+239   
IIRF!OnAuthComplete+74   
IIRF!HttpFilterProc+17a   
w3core!W3_FILTER_CONTEXT::NotifyFilters+52d   
w3core!W3_FILTER_CONTEXT::NotifyAuthComplete+39   
w3core!W3_MAIN_CONTEXT::NotifyFilters+d0   
w3core!W3_STATE_AUTHENTICATION::DoWork+967   
w3core!W3_MAIN_CONTEXT::DoWork+a6   
w3core!W3_MAIN_CONTEXT::OnNewRequest+55   
w3dt!UL_NATIVE_REQUEST::DoStateProcess+48   
w3dt!UL_NATIVE_REQUEST::DoWork+7f   
w3dt!OverlappedCompletionRoutine+1a   
w3tp!THREAD_POOL_DATA::ThreadPoolThread+73   
w3tp!THREAD_POOL_DATA::ThreadPoolThread+24   
w3tp!THREAD_MANAGER::ThreadManagerThread+39   
kernel32!BaseThreadStart+34
Jun 17, 2010 at 2:35 PM
Edited Jun 17, 2010 at 2:36 PM

I have to use the debugger because the lock issue is preventing IIRF from writing to the exception log correctly:

MyLoggingStackWalker recurses about 50 times in this one thread, waiting for the malloc lock that was locked in the other thread.

Here is only a portion of that trace:

 

IIRF!MyLoggingStackWalker::MyLoggingStackWalker+74     012751d0     00000000     cccccccc   
IIRF!ExceptionFilter+3b     00f789ec     012751d0     1003b2e4   
IIRF!HttpFilterProc+239     00000000     00000000     00000000   
IIRF!_EH4_CallFilterFunc+12     10010e53     100a85f8     00000000   
IIRF!_except_handler4+b9     00f78ad8     00f7f828     00f78af4   
ntdll!ExecuteHandler2+26     00f78ad8     00f7f828     00f78af4   
ntdll!ExecuteHandler+24     00f78000     00f78af4     00f78ad8   
ntdll!KiUserExceptionDispatcher+e     00f78000     00f78af4     00f78ad8   
ntdll!RtlAllocateHeap+33e     01270000     00000000     00000128   
IIRF!_heap_alloc_base+5e     00000128     21abba91     00f791d8   
IIRF!_heap_alloc+216     00000104     00000001     00000000   
IIRF!_nh_malloc_dbg+7f     00000104     00000000     00000001   
IIRF!_nh_malloc_dbg+2c     00000104     00000000     00000001   
IIRF!malloc+1b     00000104     00000000     00000000   
IIRF!MyLoggingStackWalker::MyLoggingStackWalker+74     012751d0     00000000     cccccccc   
IIRF!ExceptionFilter+3b     00f79244     012751d0     1003b2e4   
IIRF!HttpFilterProc+239     00000000     00000000     00000000   
IIRF!_EH4_CallFilterFunc+12     10010e53     100a85f8     00000000   
IIRF!_except_handler4+b9     00f79330     00f7f828     00f7934c   
ntdll!ExecuteHandler2+26     00f79330     00f7f828     00f7934c   
ntdll!ExecuteHandler+24     00f79000     00f7934c     00f79330   
ntdll!KiUserExceptionDispatcher+e     00f79000     00f7934c     00f79330   
ntdll!RtlAllocateHeap+33e     01270000     00000000     00000128   
IIRF!_heap_alloc_base+5e     00000128     21abb249     00f79a30   
IIRF!_heap_alloc+216     00000104     00000001     00000000   
IIRF!_nh_malloc_dbg+7f     00000104     00000000     00000001   
IIRF!_nh_malloc_dbg+2c     00000104     00000000     00000001   
IIRF!malloc+1b     00000104     00000000     00000000   
IIRF!MyLoggingStackWalker::MyLoggingStackWalker+74     012751d0     00000000     cccccccc   
IIRF!ExceptionFilter+3b     00f79a9c     012751d0     1003b2e4   
IIRF!HttpFilterProc+239     00000000     00000000     00000000   
IIRF!_EH4_CallFilterFunc+12     10010e53     100a85f8     00000000   
IIRF!_except_handler4+b9     00f79b88     00f7f828     00f79ba4   
ntdll!ExecuteHandler2+26     00f79b88     00f7f828     00f79ba4   
ntdll!ExecuteHandler+24     00f79000     00f79ba4     00f79b88   
ntdll!KiUserExceptionDispatcher+e     00f79000     00f79ba4     00f79b88   
ntdll!RtlAllocateHeap+33e     01270000     00000000     00000128   
IIRF!_heap_alloc_base+5e     00000128     21ab8a21     00f7a288   
IIRF!_heap_alloc+216     00000104     00000001     00000000   
IIRF!_nh_malloc_dbg+7f     00000104     00000000     00000001   
IIRF!_nh_malloc_dbg+2c     00000104     00000000     00000001   
IIRF!malloc+1b     00000104     00000000     00000000   
IIRF!MyLoggingStackWalker::MyLoggingStackWalker+74     012751d0     00000000     cccccccc   
IIRF!ExceptionFilter+3b     00f7a2f4     012751d0     1003b2e4   
IIRF!HttpFilterProc+239     00000000     00000000     00000000   
IIRF!_EH4_CallFilterFunc+12     10010e53     100a85f8     00000000   
IIRF!_except_handler4+b9     00f7a3e0     00f7f828     00f7a3fc   
ntdll!ExecuteHandler2+26     00f7a3e0     00f7f828     00f7a3fc   
ntdll!ExecuteHandler+24     00f79000     00f7a3fc     00f7a3e0   
ntdll!KiUserExceptionDispatcher+e     00f79000     00f7a3fc     00f7a3e0   
ntdll!RtlAllocateHeap+a61     01270000     00000000     000000de   
IIRF!_heap_alloc_base+5e     000000de     21ab8399     00f7c22c   
IIRF!_heap_alloc+216     000000ba     00000001     00000000   
IIRF!_nh_malloc_dbg+7f     000000ba     00000000     00000001   
IIRF!_nh_malloc_dbg+2c     000000ba     00000000     00000001   
IIRF!_malloc_dbg+21     000000ba     00000001     00000000   
IIRF!_strdup_dbg+40     0ec009e0     00000001     00000000   
IIRF!_strdup+14     0ec009e0     00f7c664     00f7c238   
IIRF!StackWalkerInternal::Init+40a     0ec009e0     00f7ed68     00f7ed74   
IIRF!StackWalker::LoadModules+438     00000000     00f7ed74     cccccccc   
IIRF!StackWalker::ShowCallstack+55     fffffffe     00f7eee8     00000000   
IIRF!ExceptionFilter+83     00f7ede0     012751d0     1003b2e4   
IIRF!HttpFilterProc+239     00000000     00000000     00000000   
IIRF!_EH4_CallFilterFunc+12     10010e53     100a85f8     00000000   
IIRF!_except_handler4+b9     00f7eecc     00f7f828     00f7eee8   
ntdll!ExecuteHandler2+26     00f7eecc     00f7f828     00f7eee8   
ntdll!ExecuteHandler+24     00f79000     00f7eee8     00f7eecc   
ntdll!KiUserExceptionDispatcher+e     00f79000     00f7eee8     00f7eecc   
ntdll!RtlAllocateHeap+961     01270000     00000000     000000ab   
IIRF!_heap_alloc_base+5e     000000ab     21abdee5     00f7f674   
IIRF!_heap_alloc+216     00000087     00000001     00000000   
IIRF!_nh_malloc_dbg+7f     00000087     00000000     00000001   
IIRF!_nh_malloc_dbg+2c     00000087     00000000     00000001   
IIRF!malloc+1b     00000087     00f7f724     0000004f   
IIRF!GenerateReplacementString+9c4     02932570     012751d0     0ec00360   
IIRF!Iirf_EvaluateRules+5c2     02932570     05c432e8     00000000   
IIRF!DoRewrites+239     02932570     05de73f8     08000002   
IIRF!OnAuthComplete+74     02932570     00f7fa8c     21abd2e9   
IIRF!HttpFilterProc+17a     02932570     04000000     00f7fa8c   
w3core!W3_FILTER_CONTEXT::NotifyFilters+52d     04000000     00f7fa8c     00f7fa40   
w3core!W3_FILTER_CONTEXT::NotifyAuthComplete+39     00f7fa8c     00f7fa40     00000208   
w3core!W3_MAIN_CONTEXT::NotifyFilters+d0     04000000     00f7fa8c     00f7fa40   
w3core!W3_STATE_AUTHENTICATION::DoWork+967     02931d00     00000000     00000000   
w3core!W3_MAIN_CONTEXT::DoWork+a6     00000000     00000000     00000000   
w3core!W3_MAIN_CONTEXT::OnNewRequest+55     02931238     02931238     5a361680   
w3dt!UL_NATIVE_REQUEST::DoStateProcess+48     00268750     0026875c     00f7ff5c   
w3dt!UL_NATIVE_REQUEST::DoWork+7f     0000065e     00000000     0293123c   
w3dt!OverlappedCompletionRoutine+1a     00000000     0000065e     0293123c   
w3tp!THREAD_POOL_DATA::ThreadPoolThread+73     00000000     002687c8     5a300000   
w3tp!THREAD_POOL_DATA::ThreadPoolThread+24     00268750     00000000     00000000   
w3tp!THREAD_MANAGER::ThreadManagerThread+39     002687c8     00000000     00000000   
kernel32!BaseThreadStart+34     5a301d70     002687c8     00000000   

 

Coordinator
Jun 17, 2010 at 2:54 PM
It looks like a memory corruption or pointer size problem due to a logic error within the GenerateReplacementString() function. I'd like to see the 50 logfile statements (LEVEL 4) immediately preceding the exception. If there is a particular rule that you believe is causing the problem (with it's condition, if any), I'd like to see that, too. this should be evident from the IIRF logfile.
Jun 17, 2010 at 3:45 PM
Edited Jun 17, 2010 at 3:46 PM

It took a few tries before I could get a valid log to write out before it crashed altogether

Thu Jun 17 10:41:17 -  7600 - EvaluateRules: returning 0
Thu Jun 17 10:41:17 -  7600 - DoRewrites: No Rewrite
Thu Jun 17 10:41:17 -  5808 - HttpFilterProc: SF_NOTIFY_URL_MAP
Thu Jun 17 10:41:17 -  5808 - HttpFilterProc: cfg= 0x012751D0
Thu Jun 17 10:41:17 -  2220 - HttpFilterProc: SF_NOTIFY_URL_MAP
Thu Jun 17 10:41:17 -  2220 - HttpFilterProc: cfg= 0x012751D0
Thu Jun 17 10:41:17 -  2220 - HttpFilterProc: SF_NOTIFY_URL_MAP
Thu Jun 17 10:41:17 -  2220 - HttpFilterProc: cfg= 0x012751D0
Thu Jun 17 10:41:17 -  5808 - HttpFilterProc: SF_NOTIFY_LOG
Thu Jun 17 10:41:17 -  5808 - ReleaseOrExpireVdirConfig: vdir '/LM/W3SVC/714817590/Root' (era=0) (rc=0) (Expired=0) (ptr=0x012751D0)...
Thu Jun 17 10:41:17 -  5316 - IsIniFileUpdated: \\alpanet\Webshare$\dnn4x\Iirf.ini NO
Thu Jun 17 10:41:17 -  5316 - IsIniFileUpdated: \\alpanet\Webshare$\dnn4x\iirf\dnsredirects.ini NO
Thu Jun 17 10:41:17 -  5316 - IsIniFileUpdated: \\alpanet\Webshare$\dnn4x\iirf\wwwvdirs.ini NO
Thu Jun 17 10:41:17 -  5316 - GetVdirConfig: Obtain  vdir '/LM/W3SVC/714817590/Root' (era=0) (rc=1) (Expired=0) (ptr=0x012751D0)...
Thu Jun 17 10:41:17 -  5316 - HttpFilterProc: SF_NOTIFY_URL_MAP
Thu Jun 17 10:41:17 -  5316 - HttpFilterProc: cfg= 0x012751D0
Thu Jun 17 10:41:17 -  5316 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
Thu Jun 17 10:41:17 -  5316 - DoRewrites
Thu Jun 17 10:41:17 -  5316 - GetHeader_AutoFree: 'url' = '/Home/tabid/410/ctl/Login/Default.aspx?returnurl=%2fDefault.aspx'
Thu Jun 17 10:41:17 -  5316 - GetHeader_AutoFree: 'method' = 'GET'
Thu Jun 17 10:41:17 -  5316 - DoRewrites: New Url, before decoding: '/Home/tabid/410/ctl/Login/Default.aspx?returnurl=%2fDefault.aspx'
Thu Jun 17 10:41:17 -  5316 - DoRewrites: Url (decoded): '/Home/tabid/410/ctl/Login/Default.aspx?returnurl=/Default.aspx'
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: depth=0
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: no RewriteBase
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 1: pattern: ^(.*)$  subject: /Home/tabid/410/ctl/Login/Default.aspx?returnurl=/Default.aspx
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 1: 2 match
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 1: evaluating condition
Thu Jun 17 10:41:17 -  5316 - ReplaceServerVariables: alloc 48 bytes
Thu Jun 17 10:41:17 -  5316 - ReplaceServerVariables: in='${DnsRedirects:%{HTTP_HOST}|NotFound}' out='${DnsRedirects:www.expressjetalpa.org|NotFound}'
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: map?
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: alloc 30 bytes
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: result 'www.expressjetalpa.org'
Thu Jun 17 10:41:17 -  5316 - MapKey: map(DnsRedirects) key(www.expressjetalpa.org)
Thu Jun 17 10:41:17 -  5316 - MapKey: map(DnsRedirects) key(www.expressjetalpa.org) no value found
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: alloc 16 bytes
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: result 'NotFound'
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: alloc 16 bytes
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: map?
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: alloc 30 bytes
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: result 'www.expressjetalpa.org'
Thu Jun 17 10:41:17 -  5316 - MapKey: map(DnsRedirects) key(www.expressjetalpa.org)
Thu Jun 17 10:41:17 -  5316 - MapKey: map(DnsRedirects) key(www.expressjetalpa.org) no value found
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: alloc 16 bytes
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: result 'NotFound'
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: result 'NotFound'
Thu Jun 17 10:41:17 -  5316 - EvalCondition: Cond t(${DnsRedirects:%{HTTP_HOST}|NotFound}) op(|) p(^(?!NotFound)((?:https?://).+)$) => FALSE
Thu Jun 17 10:41:17 -  5316 - EvalConditionList: rule 1, FALSE, Rule does not apply
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 2: pattern: ^(.*)$  subject: /Home/tabid/410/ctl/Login/Default.aspx?returnurl=/Default.aspx
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 2: 2 matches
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 2: evaluating condition
Thu Jun 17 10:41:17 -  5316 - ReplaceServerVariables: alloc 33 bytes
Thu Jun 17 10:41:17 -  5316 - ReplaceServerVariables: in='%{HTTP_HOST}' out='www.expressjetalpa.org'
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: alloc 30 bytes
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: result 'www.expressjetalpa.org'
Thu Jun 17 10:41:17 -  5316 - EvalCondition: Cond t(%{HTTP_HOST}) op(|) p(^(www\.)?alpa\.org$) => FALSE
Thu Jun 17 10:41:17 -  5316 - EvalConditionList: rule 2, FALSE, Rule does not apply
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 3: pattern: ^(.*)$  subject: /Home/tabid/410/ctl/Login/Default.aspx?returnurl=/Default.aspx
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 3: 2 matches
Thu Jun 17 10:41:17 -  5316 - EvaluateRules: Rule 3: evaluating condition
Thu Jun 17 10:41:17 -  5316 - ReplaceServerVariables: alloc 69 bytes
Thu Jun 17 10:41:17 -  5316 - ReplaceServerVariables: in='%{URL}' out='/Home/tabid/410/ctl/Login/Default.aspx?returnurl=%2fDefault.aspx'
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: alloc 72 bytes
Thu Jun 17 10:41:17 -  5316 - GenerateReplacementString: result '/Home/tabid/410/ctl/Login/Default.aspx?returnurl=%2fDefault.aspx'
Thu Jun 17 10:41:17 -  5316 - EvalCondition: Cond t(%{URL}) op(|) p(tabid/([0-9]+)/ctl/Login) => TRUE
Thu Jun 17 10:41:17 -  5316 - EvalConditionList: rule 3, TRUE, Rule will apply
Thu Jun 17 10:41:17 -  5316 - ReplaceServerVariables: alloc 110 bytes
Thu Jun 17 10:41:17 -  5316 - EXCEPTION
Thu Jun 17 10:41:17 -  5316 - SymInit: Symbol-SearchPath: 'C:\WINDOWS\system32\inetsrv\ionic\;.;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: '*******'
Thu Jun 17 10:41:17 -  5316 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Thu Jun 17 10:41:18 -  5316 - Stack trace:
7C82A432 module(ntdll): (filename not available): RtlRestoreLastWin32Error
f:\dd\vctools\crt_bld\self_x86\crt\src\malloc.c (105): _heap_alloc_base
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (427): _heap_alloc_dbg_impl
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (239): _nh_malloc_dbg_impl
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (296): _nh_malloc_dbg
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgmalloc.c (56): malloc
c:\dinoch\dev\isapi\iirf\v2.0\filter\iirflogging.c (232): LogMessage
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1384): ReplaceServerVariables
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (2576): Iirf_EvaluateRules
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (879): DoRewrites
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1075): OnAuthComplete
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1239): HttpFilterProc
5A3988A4 module(w3core): (filename not available): (function-name not available)
5A3C14A6 module(w3core): (filename not available): UlW3Start
5A3A4DBE module(w3core): (filename not available): W3_FILE_INFO_CACHE::GetFileInfo
5A3A14F1 module(w3core): (filename not available): W3_FILE_INFO_CACHE::GetFileInfo
5A392274 module(w3core): (filename not available): (function-name not available)
5A3965FA module(w3core): (filename not available): (function-name not available)
5A3616CF module(w3dt): (filename not available): UlAtqAllocateMemory
5A3616FA module(w3dt): (filename not available): UlAtqAllocateMemory
5A3024CE module(W3TP): (filename not available): THREAD_POOL::PostCompletion
5A3026AC module(W3TP): (filename not available): THREAD_POOL::~THREAD_POOL
5A301DA9 module(W3TP): (filename not available): (function-name not available)
77E6482F module(kernel32): (filename not available): GetModuleHandleA
77E6482F module(kernel32): (filename not available): GetModuleHandleA

 

Jun 17, 2010 at 3:49 PM
Edited Jun 17, 2010 at 4:07 PM

The rule in question is this:

RewriteCond            %{URL}        tabid/([0-9]+)/ctl/Login        [I]
RedirectRule        ^(.*)$        http://www.alpa.org/AlpaLogin/tabid/2415/Default.aspx?returnurl=http%3a%2f%2f%{HTTP_HOST}%2fDefault.aspx%3ftabid%3d*1        [R=302]

Jun 17, 2010 at 4:11 PM
Edited Jun 17, 2010 at 5:41 PM

I'm playing with adding rules and seeing which ones break it, but 9 times out of 10 the log stops here with no exception logging:

Thu Jun 17 10:56:59 -  5240 - EvalCondition: Cond t(%{URL}) op(|) p(tabid/([0-9]+)/ctl/Login) => TRUE
Thu Jun 17 10:56:59 -  5240 - EvalConditionList: rule 4, TRUE, Rule will apply
Thu Jun 17 10:56:59 -  5240 - ReplaceServerVariables: alloc 110 bytes
Thu Jun 17 10:56:59 -  5240 - ReplaceServerVariables: in='http://www.alpa.org/AlpaLogin/tabid/2415/Default.aspx?returnurl=http%3a%2f%2f%{HTTP_HOST}%2fDefault.aspx%3ftabid%3d*1' out='http://www.alpa.org/AlpaLogin/tabid/2415/Default.aspx?returnurl=http%3a%2f%2fwww.expressjetalpa.org%2fDefault.aspx%3ftabid%3d*1'

Sometimes these last 2 lines are included as well:

Thu Jun 17 10:56:59 -  5240 - GenerateReplacementString: alloc 136 bytes
Thu Jun 17 10:56:59 -  5240 - GenerateReplacementString: result 'http://www.alpa.org/AlpaLogin/tabid/2415/Default.aspx?returnurl=http%3a%2f%2fwww.expressjetalpa.org%2fDefault.aspx%3ftabid%3d410'

 

Then the app pool restarts and a new IIRF log file is created

Here is a copy of using SCRIPT_NAME to crash it:

Thu Jun 17 11:09:09 -  6080 - ReplaceServerVariables: in='%{HTTP_HOST}' out='www.expressjetalpa.org'
Thu Jun 17 11:09:09 -  6080 - GenerateReplacementString: alloc 30 bytes
Thu Jun 17 11:09:09 -  6080 - GenerateReplacementString: result 'www.expressjetalpa.org'
Thu Jun 17 11:09:09 -  6080 - EvalCondition: Cond t(%{HTTP_HOST}) op(|) p(^(www\.)?alpa\.org$) => FALSE
Thu Jun 17 11:09:09 -  6080 - EvalConditionList: rule 2, FALSE, Rule does not apply
Thu Jun 17 11:09:09 -  6080 - EvaluateRules: Rule 3: pattern: ^(.*)$  subject: /Home/tabid/410/ctl/Login/Default.aspx?returnurl=/Default.aspx
Thu Jun 17 11:09:09 -  6080 - EvaluateRules: Rule 3: 2 matches
Thu Jun 17 11:09:09 -  6080 - EvaluateRules: Rule 3: evaluating condition
Thu Jun 17 11:09:09 -  6080 - ReplaceServerVariables: alloc 51 bytes
Thu Jun 17 11:09:09 -  6080 - ReplaceServerVariables: in='%{SCRIPT_NAME}' out='/Home/tabid/410/ctl/Login/Default.aspx'
Thu Jun 17 11:09:09 -  6080 - GenerateReplacementString: alloc 46 bytes
Thu Jun 17 11:09:09 -  6080 - GenerateReplacementString: result '/Home/tabid/410/ctl/Login/Default.aspx'
Thu Jun 17 11:09:09 -  6080 - EvalCondition: Cond t(%{SCRIPT_NAME}) op(|) p(tabid/([0-9]+)/ctl/Login) => TRUE
Thu Jun 17 11:09:09 -  6080 - EvalConditionList: rule 3, TRUE, Rule will apply
Thu Jun 17 11:09:09 -  6080 - ReplaceServerVariables: alloc 110 bytes
Thu Jun 17 11:09:09 -  6080 - EXCEPTION
Thu Jun 17 11:09:09 -  6080 - SymInit: Symbol-SearchPath: 'C:\WINDOWS\system32\inetsrv\ionic\;.;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: '*******'
Thu Jun 17 11:09:09 -  6080 - OS-Version: 5.2.3790 (Service Pack 2) 0x110-0x3
Thu Jun 17 11:09:09 -  6080 - Stack trace:
7C82A432 module(ntdll): (filename not available): RtlRestoreLastWin32Error
f:\dd\vctools\crt_bld\self_x86\crt\src\malloc.c (105): _heap_alloc_base
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (427): _heap_alloc_dbg_impl
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (239): _nh_malloc_dbg_impl
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgheap.c (296): _nh_malloc_dbg
f:\dd\vctools\crt_bld\self_x86\crt\src\dbgmalloc.c (56): malloc
c:\dinoch\dev\isapi\iirf\v2.0\filter\iirflogging.c (232): LogMessage
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1384): ReplaceServerVariables
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (2576): Iirf_EvaluateRules
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (879): DoRewrites
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1075): OnAuthComplete
c:\dinoch\dev\isapi\iirf\v2.0\filter\rewriter.c (1239): HttpFilterProc
5A3988A4 module(w3core): (filename not available): (function-name not available)
5A3C14A6 module(w3core): (filename not available): UlW3Start
5A3A4DBE module(w3core): (filename not available): W3_FILE_INFO_CACHE::GetFileInfo
5A3A14F1 module(w3core): (filename not available): W3_FILE_INFO_CACHE::GetFileInfo
5A392274 module(w3core): (filename not available): (function-name not available)
5A3965FA module(w3core): (filename not available): (function-name not available)
5A3616CF module(w3dt): (filename not available): UlAtqAllocateMemory
5A3616FA module(w3dt): (filename not available): UlAtqAllocateMemory
5A3024CE module(W3TP): (filename not available): THREAD_POOL::PostCompletion
5A3026AC module(W3TP): (filename not available): THREAD_POOL::~THREAD_POOL
5A301DA9 module(W3TP): (filename not available): (function-name not available)
77E6482F module(kernel32): (filename not available): GetModuleHandleA
77E6482F module(kernel32): (filename not available): GetModuleHandleA

 

 

Coordinator
Jun 17, 2010 at 5:14 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.
Coordinator
Jun 17, 2010 at 5:16 PM

looks like a bug to me...

Jul 8, 2010 at 3:26 PM

Cheeso-

Do you have any links to previous versions of the 2.1 beta binaries?  I would like to see if there is a version I can use in the mean time that fixes the ProxyPass issue I was having (like v23 does) but without the memory allocation issues I am having on v23.  If so, it would be a great help so I can get one of my sites back up and running.

Thanks

Aug 11, 2010 at 4:46 PM
I very reliably get an app pool crash when I try to submit a post with a large file- it looks like a more severe version of the old 48k file limit, but instead of just truncating the file, the app pool goes down. The specific environment I'm using is a Windows 2K3/IIS6 server running a reverse proxy to a similar internal server that's providing MantisBT Here's the local ini file, which I pared down to the most basic elements to try to eliminate any other possible problems: # IIRF.ini StatusUrl /iirfStatus RewriteLog C:\WINDOWS\system32\LogFiles\iirf\iirfLog.issues RewriteLogLevel 5 RewriteCond %{URL} ^/$ [I] RedirectRule ^/(?!track/)(.*) http://issues.koryak.net/track/$1 [R=301] #Proxy the issues website ProxyPass ^/track/(.*)$ http://devserver.koryak.local/track/$1 And here's the log 5 dump. Everything seems fine, it the pool just crashes at the end: Wed Aug 11 02:31:17 - 3536 - ------------------------------------------------------- Wed Aug 11 02:31:17 - 3536 - Ionic ISAPI Rewriting Filter (IIRF) 2.1.1.23 x86 RELEASE Wed Aug 11 02:31:17 - 3536 - IIRF was built on: May 30 2010 13:26:57 Wed Aug 11 02:31:17 - 3536 - Cached: DLL_PROCESS_ATTACH Wed Aug 11 02:31:17 - 3536 - Cached: Process ID: 1176 Wed Aug 11 02:31:17 - 3536 - Cached: ReadServerConfig: C:\Program Files\Ionic Shade\IIRF 2.1\IirfGlobal.ini(23): Filter Priority is now: HIGH (0x80000) Wed Aug 11 02:31:17 - 3536 - Cached: ReadServerConfig: C:\Program Files\Ionic Shade\IIRF 2.1\IirfGlobal.ini(46): NotifyLog setting is now: OFF Wed Aug 11 02:31:17 - 3536 - Cached: ReadServerConfig: C:\Program Files\Ionic Shade\IIRF 2.1\IirfGlobal.ini(63): RewriteEngine setting is now: ON Wed Aug 11 02:31:17 - 3536 - Cached: DLL_PROCESS_ATTACH - complete Wed Aug 11 02:31:17 - 3536 - Cached: GetFilterVersion Wed Aug 11 02:31:17 - 3536 - GetLogFile: app:'/LM/W3SVC/719142050/Root' new log:'C:\WINDOWS\system32\LogFiles\iirf\iirfLog.issues.1176.log' Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: actual log file 'C:\WINDOWS\system32\LogFiles\iirf\iirfLog.issues.1176.log' Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: ini file: 'E:\Issues\Iirf.ini' Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: ini file timestamp: 2010/08/11 02:30:58 Eastern Daylight Time Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: cfg(0x012343D0) Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: LogLevel = 5 Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: pass 2 Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: E:\Issues\Iirf.ini(3): StatusUrl /iirfStatus (--) Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: E:\Issues\Iirf.ini(3): WARNING: the StatusUrl directive is obsolete. Please use StatusInquiry. Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: E:\Issues\Iirf.ini(3): IIRF Status Inquiry is enabled at path '/iirfStatus' for local requests only. Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: E:\Issues\Iirf.ini(8): RewriteCond %{URL} ^/$ '[I]' Wed Aug 11 02:31:17 - 3536 - ParseCondModifierFlags: '[I]' Wed Aug 11 02:31:17 - 3536 - ParseCondModifierFlags: token 'I' Wed Aug 11 02:31:17 - 3536 - Cond: Case Insensitive match Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: E:\Issues\Iirf.ini(9): RedirectRule (rule 1) '^/(?!track/)(.*)' 'http://issues.koryak.net/track/$1' [R=301] Wed Aug 11 02:31:17 - 3536 - ParseRuleModifierFlags: '[R=301]' Wed Aug 11 02:31:17 - 3536 - ParseRuleModifierFlags: token 'R=301' Wed Aug 11 02:31:17 - 3536 - rule: Redirect(301) Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: E:\Issues\Iirf.ini(12): ProxyPass (rule 2) '^/track/(.*)$' 'http://devserver.koryak.local/track/$1' (null) Wed Aug 11 02:31:17 - 3536 - ReadVdirConfig: Done reading INI for the root vdir, found 2 rules (0 errors, 1 warnings) on 14 lines Wed Aug 11 02:31:17 - 3536 - GetVdirConfig: Obtain vdir '/LM/W3SVC/719142050/Root' (era=0) (rc=1) (Expired=0) (ptr=0x012343D0)... Wed Aug 11 02:31:17 - 3536 - HttpFilterProc: SF_NOTIFY_URL_MAP Wed Aug 11 02:31:17 - 3536 - HttpFilterProc: cfg= 0x012343D0 Wed Aug 11 02:31:17 - 3536 - IsIniFileUpdated: E:\Issues\Iirf.ini NO Wed Aug 11 02:31:17 - 3536 - GetVdirConfig: Obtain vdir '/LM/W3SVC/719142050/Root' (era=0) (rc=2) (Expired=0) (ptr=0x012343D0)... Wed Aug 11 02:31:17 - 3536 - HttpFilterProc: SF_NOTIFY_URL_MAP Wed Aug 11 02:31:17 - 3536 - HttpFilterProc: cfg= 0x012343D0 Wed Aug 11 02:31:17 - 3536 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE Wed Aug 11 02:31:17 - 3536 - DoRewrites Wed Aug 11 02:31:17 - 3536 - GetHeader_AutoFree: getting 'url' Wed Aug 11 02:31:17 - 3536 - GetHeader_AutoFree: 29 bytes ptr:0x000C6520 Wed Aug 11 02:31:17 - 3536 - GetHeader_AutoFree: 'url' = '/track/proj_doc_add_page.php' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'QUERY_STRING' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 1 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result '' Wed Aug 11 02:31:17 - 3536 - GetHeader_AutoFree: getting 'method' Wed Aug 11 02:31:17 - 3536 - GetHeader_AutoFree: 4 bytes ptr:0x000C6790 Wed Aug 11 02:31:17 - 3536 - GetHeader_AutoFree: 'method' = 'GET' Wed Aug 11 02:31:17 - 3536 - DoRewrites: New Url, before decoding: '/track/proj_doc_add_page.php' Wed Aug 11 02:31:17 - 3536 - DoRewrites: Url (no decoding): '/track/proj_doc_add_page.php' Wed Aug 11 02:31:17 - 3536 - EvaluateRules: depth=0 Wed Aug 11 02:31:17 - 3536 - GetServerVariable: getting 'SCRIPT_NAME' Wed Aug 11 02:31:17 - 3536 - GetServerVariable: 29 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable: result '/track/proj_doc_add_page.php' Wed Aug 11 02:31:17 - 3536 - EvaluateRules: no RewriteBase Wed Aug 11 02:31:17 - 3536 - EvaluateRules: Rule 1: pattern: ^/(?!track/)(.*) subject: /track/proj_doc_add_page.php Wed Aug 11 02:31:17 - 3536 - EvaluateRules: Rule 1: -1 (No match) Wed Aug 11 02:31:17 - 3536 - EvaluateRules: Rule 2: pattern: ^/track/(.*)$ subject: /track/proj_doc_add_page.php Wed Aug 11 02:31:17 - 3536 - EvaluateRules: Rule 2: 2 matches Wed Aug 11 02:31:17 - 3536 - ReplaceServerVariables: alloc 39 bytes Wed Aug 11 02:31:17 - 3536 - ReplaceServerVariables: in='http://devserver.koryak.local/track/$1' out='http://devserver.koryak.local/track/$1' Wed Aug 11 02:31:17 - 3536 - GenerateReplacementString: alloc 65 bytes Wed Aug 11 02:31:17 - 3536 - GenerateReplacementString: result 'http://devserver.koryak.local/track/proj_doc_add_page.php' Wed Aug 11 02:31:17 - 3536 - EvaluateRules: Result (length 57): http://devserver.koryak.local/track/proj_doc_add_page.php Wed Aug 11 02:31:17 - 3536 - EvaluateRules: returning 999 Wed Aug 11 02:31:17 - 3536 - DoRewrites: Proxy to: 'http://devserver.koryak.local/track/proj_doc_add_page.php' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'REQUEST_METHOD' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 4 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result 'GET' Wed Aug 11 02:31:17 - 3536 - IirfProxy_SendRequest: http://devserver.koryak.local/track/proj_doc_add_page.php Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'REMOTE_ADDR' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 13 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result '74.98.195.82' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'LOCAL_ADDR' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 15 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result '192.168.101.70' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'HTTP_REFERER' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 49 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result 'http://issues.koryak.net/track/proj_doc_page.php' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'HTTP_USER_AGENT' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 118 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result 'Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'HTTP_ACCEPT' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 91 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result 'application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'SERVER_NAME' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 18 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result 'issues.koryak.net' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: getting 'ALL_RAW' Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: 640 bytes Wed Aug 11 02:31:17 - 3536 - GetServerVariable_AutoFree: result 'Connection: keep-alive Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3 Accept-Encoding: gzip,deflate,sdch Accept-Language: en-US,en;q=0.8 Cookie: PHPSESSID=5b8809uuvhjqoaa77q9pl4fs82; MANTIS_secure_session=0; MANTIS_STRING_COOKIE=6490a44b9041daa991ec3d13d329e2fca90fa8515d49bb4dc6d089a825535ab3; MANTIS_PROJECT_COOKIE=1 Host: issues.koryak.net Referer: http://issues.koryak.net/track/proj_doc_page.php User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4 ' Wed Aug 11 02:31:17 - 3536 - ProxyRequest: host(devserver.koryak.local) path+query(/track/proj_doc_add_page.php) Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: Connection: keep-alive Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3 Accept-Encoding: gzip,deflate,sdch Accept-Language: en-US,en;q=0.8 Cookie: PHPSESSID=5b8809uuvhjqoaa77q9pl4fs82; MANTIS_secure_session=0; MANTIS_STRING_COOKIE=6490a44b9041daa991ec3d13d329e2fca90fa8515d49bb4dc6d089a825535ab3; MANTIS_PROJECT_COOKIE=1 Host: issues.koryak.net Referer: http://issues.koryak.net/track/proj_doc_page.php User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4 Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr Connection: keep-alive Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3 Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr Accept-Encoding: gzip,deflate,sdch Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr Accept-Language: en-US,en;q=0.8 Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr Cookie: PHPSESSID=5b8809uuvhjqoaa77q9pl4fs82; MANTIS_secure_session=0; MANTIS_STRING_COOKIE=6490a44b9041daa991ec3d13d329e2fca90fa8515d49bb4dc6d089a825535ab3; MANTIS_PROJECT_COOKIE=1 Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr Host: issues.koryak.net Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr Referer: http://issues.koryak.net/track/proj_doc_page.php Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: hdr User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4 Wed Aug 11 02:31:17 - 3536 - ParseAllRaw: found 9 headers Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: rh(0x01234078) nh(devserver.koryak.local) sn(issues.koryak.net) la(192.168.101.70) ra(74.98.195.82) ts(0) Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Host: devserver.koryak.local Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Via: 1.1 192.168.101.70 (IIRF v2.1) Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header X-Forwarded-Server: issues.koryak.net Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header X-Forwarded-For: 74.98.195.82 Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Connection: keep-alive Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3 Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Accept-Encoding: gzip,deflate,sdch Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Accept-Language: en-US,en;q=0.8 Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Cookie: PHPSESSID=5b8809uuvhjqoaa77q9pl4fs82; MANTIS_secure_session=0; MANTIS_STRING_COOKIE=6490a44b9041daa991ec3d13d329e2fca90fa8515d49bb4dc6d089a825535ab3; MANTIS_PROJECT_COOKIE=1 Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header X-Forwarded-Host: issues.koryak.net Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header Referer: http://issues.koryak.net/track/proj_doc_page.php Wed Aug 11 02:31:17 - 3536 - GenProxyRequestHeadersString: header User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4 Wed Aug 11 02:31:17 - 3536 - ProxyRequest: WinHttpConnect devserver.koryak.local 80 Wed Aug 11 02:31:17 - 3536 - ProxyRequest: WinHttpOpenRequest: GET /track/proj_doc_add_page.php Wed Aug 11 02:31:17 - 3536 - ProxyRequest: WinHttpAddRequestHeaders Wed Aug 11 02:31:17 - 3536 - ProxyRequest: WinHttpSendRequest Wed Aug 11 02:31:17 - 3536 - Cached: DLL_THREAD_DETACH Wed Aug 11 02:31:17 - 3536 - ProxyRequest: WinHttpReceiveResponse Wed Aug 11 02:31:18 - 3536 - ProxyRequest: WinHttpQueryHeaders Wed Aug 11 02:31:18 - 3536 - ProxyRequest: WinHttpQueryHeaders: status 200 Wed Aug 11 02:31:18 - 3536 - Proxy_SetResponseHeaders: starting status 200 Wed Aug 11 02:31:18 - 3536 - Proxy_SetResponseHeaders: status OK Wed Aug 11 02:31:18 - 3536 - Proxy_SetResponseHeaders: status string '200 OK' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: Allocate 478 Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'Cache-Control: no-store, no-cache, must-revalidate' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'Content-Type: text/html; charset=utf-8' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'Content-Encoding: gzip' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'Expires: Wed, 11 Aug 2010 06:31:27 GMT' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'Last-Modified: Wed, 11 Aug 2010 06:31:27 GMT' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'Vary: Accept-Encoding' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: exclude 'Server: Microsoft-IIS/6.0' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: exclude 'X-Powered-By: PHP/5.3.2' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'X-Content-Type-Options: nosniff' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'X-Frame-Options: DENY' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'X-Content-Security-Policy: allow 'self'; options inline-script eval-script; frame-ancestors 'none'' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: exclude 'X-Powered-By: ASP.NET' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'Date: Wed, 11 Aug 2010 06:31:27 GMT' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: keep 'Connection: close' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: add 'Via: 1.1 192.168.101.70 (IIRF v2.1)' Wed Aug 11 02:31:18 - 3536 - ProcessResponseHeaders: all Cache-Control: no-store, no-cache, must-revalidate Content-Type: text/html; charset=utf-8 Content-Encoding: gzip Expires: Wed, 11 Aug 2010 06:31:27 GMT Last-Modified: Wed, 11 Aug 2010 06:31:27 GMT Vary: Accept-Encoding X-Content-Type-Options: nosniff X-Frame-Options: DENY X-Content-Security-Policy: allow 'self'; options inline-script eval-script; frame-ancestors 'none' Date: Wed, 11 Aug 2010 06:31:27 GMT Connection: close Via: 1.1 192.168.101.70 (IIRF v2.1) Wed Aug 11 02:31:18 - 3536 - ProxyRequest: WinHttpReadData 493 Wed Aug 11 02:31:18 - 3536 - ProxyRequest: WinHttpReadData nRead= 493 Wed Aug 11 02:31:18 - 3536 - ProxyRequest: WinHttpReadData 1587 Wed Aug 11 02:31:18 - 3536 - ProxyRequest: WinHttpReadData nRead= 1587 Wed Aug 11 02:31:18 - 3536 - ProxyRequest: chunks(2) totalBytes(2080) Wed Aug 11 02:31:18 - 3536 - DoRewrites: Proxy complete: 2 chunks, 2080 bytes' Wed Aug 11 02:31:18 - 3536 - ReleaseOrExpireVdirConfig: vdir '/LM/W3SVC/719142050/Root' (era=0) (rc=1) (Expired=0) (ptr=0x012343D0)... Wed Aug 11 02:31:18 - 3536 - ReleaseOrExpireVdirConfig: vdir '/LM/W3SVC/719142050/Root' (era=0) (rc=0) (Expired=0) (ptr=0x012343D0)... Wed Aug 11 02:31:31 - 3536 - IsIniFileUpdated: E:\Issues\Iirf.ini NO Wed Aug 11 02:31:31 - 3536 - GetVdirConfig: Obtain vdir '/LM/W3SVC/719142050/Root' (era=0) (rc=1) (Expired=0) (ptr=0x012343D0)... Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: SF_NOTIFY_URL_MAP Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: cfg= 0x012343D0 Wed Aug 11 02:31:31 - 3536 - IsIniFileUpdated: E:\Issues\Iirf.ini NO Wed Aug 11 02:31:31 - 3536 - GetVdirConfig: Obtain vdir '/LM/W3SVC/719142050/Root' (era=0) (rc=2) (Expired=0) (ptr=0x012343D0)... Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: SF_NOTIFY_URL_MAP Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: cfg= 0x012343D0 Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE Wed Aug 11 02:31:31 - 3536 - DoRewrites Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: getting 'url' Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: 24 bytes ptr:0x000C63E0 Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: 'url' = '/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: getting 'QUERY_STRING' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: 1 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: result '' Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: getting 'method' Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: 5 bytes ptr:0x000C6520 Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: 'method' = 'POST' Wed Aug 11 02:31:31 - 3536 - DoRewrites: New Url, before decoding: '/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - DoRewrites: Url (no decoding): '/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - EvaluateRules: depth=0 Wed Aug 11 02:31:31 - 3536 - GetServerVariable: getting 'SCRIPT_NAME' Wed Aug 11 02:31:31 - 3536 - GetServerVariable: 24 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable: result '/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - EvaluateRules: no RewriteBase Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 1: pattern: ^/(?!track/)(.*) subject: /track/proj_doc_add.php Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 1: -1 (No match) Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 2: pattern: ^/track/(.*)$ subject: /track/proj_doc_add.php Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 2: 2 matches Wed Aug 11 02:31:31 - 3536 - ReplaceServerVariables: alloc 39 bytes Wed Aug 11 02:31:31 - 3536 - ReplaceServerVariables: in='http://devserver.koryak.local/track/$1' out='http://devserver.koryak.local/track/$1' Wed Aug 11 02:31:31 - 3536 - GenerateReplacementString: alloc 60 bytes Wed Aug 11 02:31:31 - 3536 - GenerateReplacementString: result 'http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Result (length 52): http://devserver.koryak.local/track/proj_doc_add.php Wed Aug 11 02:31:31 - 3536 - EvaluateRules: returning 999 Wed Aug 11 02:31:31 - 3536 - DoRewrites: Proxy to: 'http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: getting 'REQUEST_METHOD' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: 5 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: result 'POST' Wed Aug 11 02:31:31 - 3536 - IirfProxy_SendRequest: http://devserver.koryak.local/track/proj_doc_add.php Wed Aug 11 02:31:31 - 3536 - DoRewrites: requires rewrite to: '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE Wed Aug 11 02:31:31 - 3536 - DoRewrites Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: getting 'url' Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: 99 bytes ptr:0x000D4A38 Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: 'url' = '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: getting 'QUERY_STRING' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: 87 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_AutoFree: result 'path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: getting 'method' Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: 5 bytes ptr:0x000D4B48 Wed Aug 11 02:31:31 - 3536 - GetHeader_AutoFree: 'method' = 'POST' Wed Aug 11 02:31:31 - 3536 - DoRewrites: New Url, before decoding: '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - DoRewrites: Url (no decoding): '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - EvaluateRules: depth=0 Wed Aug 11 02:31:31 - 3536 - GetServerVariable: getting 'SCRIPT_NAME' Wed Aug 11 02:31:31 - 3536 - GetServerVariable: 24 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable: result '/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - EvaluateRules: no RewriteBase Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 1: pattern: ^/(?!track/)(.*) subject: /proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 1: 2 match Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 1: evaluating condition Wed Aug 11 02:31:31 - 3536 - EvalCondition: cond 0x01234168 Wed Aug 11 02:31:31 - 3536 - GetServerVariable: getting 'URL' Wed Aug 11 02:31:31 - 3536 - GetStashedHeader(URL): '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - GetServerVariable: 98 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable: result '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - ReplaceServerVariables: alloc 103 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable: getting 'URL' Wed Aug 11 02:31:31 - 3536 - GetStashedHeader(URL): '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - GetServerVariable: 98 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable: result '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - ReplaceServerVariables: vName(URL) value(/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php) Wed Aug 11 02:31:31 - 3536 - ReplaceServerVariables: in='%{URL}' out='/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - EvalCondition: ts1 '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - GenerateReplacementString: alloc 106 bytes Wed Aug 11 02:31:31 - 3536 - GenerateReplacementString: result '/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - EvalCondition: t(/proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php) op(|) p(^/$) Wed Aug 11 02:31:31 - 3536 - EvalCondition: match result: -1 (No match) Wed Aug 11 02:31:31 - 3536 - EvalCondition: Cond t(%{URL}) op(|) p(^/$) => FALSE Wed Aug 11 02:31:31 - 3536 - EvalConditionList: rule 1, FALSE, Rule does not apply Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 2: pattern: ^/track/(.*)$ subject: /proxy.iirf?path=/LM/W3SVC/719142050/Root&url=http://devserver.koryak.local/track/proj_doc_add.php Wed Aug 11 02:31:31 - 3536 - EvaluateRules: Rule 2: -1 (No match) Wed Aug 11 02:31:31 - 3536 - EvaluateRules: returning 0 Wed Aug 11 02:31:31 - 3536 - DoRewrites: No Rewrite Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: SF_NOTIFY_URL_MAP Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: cfg= 0x012343D0 Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: SF_NOTIFY_URL_MAP Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: cfg= 0x012343D0 Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: SF_NOTIFY_URL_MAP Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: cfg= 0x012343D0 Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: SF_NOTIFY_URL_MAP Wed Aug 11 02:31:31 - 3536 - HttpFilterProc: cfg= 0x012343D0 Wed Aug 11 02:31:31 - 3536 - GetVdirConfig_FromPath: Obtain site '/LM/W3SVC/719142050/Root' (era=0) (rc=3) (Expired=0) (ptr=0x012343D0)... Wed Aug 11 02:31:31 - 3536 - HttpExtensionProc: Proxy to 'http://devserver.koryak.local/track/proj_doc_add.php' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: getting 'REMOTE_ADDR' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: 13 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: result '74.98.195.82' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: getting 'LOCAL_ADDR' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: 15 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: result '192.168.101.70' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: getting 'HTTP_REFERER' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: 53 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: result 'http://issues.koryak.net/track/proj_doc_add_page.php' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: getting 'HTTP_USER_AGENT' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: 118 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: result 'Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: getting 'HTTP_ACCEPT' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: 91 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: result 'application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: getting 'SERVER_NAME' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: 18 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: result 'issues.koryak.net' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: getting 'ALL_RAW' Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: Buffer not large enough. Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: 811 bytes Wed Aug 11 02:31:31 - 3536 - GetServerVariable_EX: result 'Cache-Control: max-age=0 Connection: keep-alive Content-Length: 51911 Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryYgGZWZh5CqQV3vzM Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3 Accept-Encoding: gzip,deflate,sdch Accept-Language: en-US,en;q=0.8 Cookie: PHPSESSID=5b8809uuvhjqoaa77q9pl4fs82; MANTIS_secure_session=0; MANTIS_STRING_COOKIE=6490a44b9041daa991ec3d13d329e2fca90fa8515d49bb4dc6d089a825535ab3; MANTIS_PROJECT_COOKIE=1 Host: issues.koryak.net Referer: http://issues.koryak.net/track/proj_doc_add_page.php User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4 Origin: http://issues.koryak.net ' Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: http://devserver.koryak.local/track/proj_doc_add.php Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: url(http://devserver.koryak.local/track/proj_doc_add.php) Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: host(devserver.koryak.local) path+query(/track/proj_doc_add.php) Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: Cache-Control: max-age=0 Connection: keep-alive Content-Length: 51911 Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryYgGZWZh5CqQV3vzM Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3 Accept-Encoding: gzip,deflate,sdch Accept-Language: en-US,en;q=0.8 Cookie: PHPSESSID=5b8809uuvhjqoaa77q9pl4fs82; MANTIS_secure_session=0; MANTIS_STRING_COOKIE=6490a44b9041daa991ec3d13d329e2fca90fa8515d49bb4dc6d089a825535ab3; MANTIS_PROJECT_COOKIE=1 Host: issues.koryak.net Referer: http://issues.koryak.net/track/proj_doc_add_page.php User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4 Origin: http://issues.koryak.net Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Cache-Control: max-age=0 Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Connection: keep-alive Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Content-Length: 51911 Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryYgGZWZh5CqQV3vzM Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3 Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Accept-Encoding: gzip,deflate,sdch Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Accept-Language: en-US,en;q=0.8 Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Cookie: PHPSESSID=5b8809uuvhjqoaa77q9pl4fs82; MANTIS_secure_session=0; MANTIS_STRING_COOKIE=6490a44b9041daa991ec3d13d329e2fca90fa8515d49bb4dc6d089a825535ab3; MANTIS_PROJECT_COOKIE=1 Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Host: issues.koryak.net Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Referer: http://issues.koryak.net/track/proj_doc_add_page.php Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4 Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: hdr Origin: http://issues.koryak.net Wed Aug 11 02:31:31 - 3536 - ParseAllRaw: found 13 headers Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: rh(0x01234DA0) nh(devserver.koryak.local) sn(issues.koryak.net) la(192.168.101.70) ra(74.98.195.82) ts(51911) Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Host: devserver.koryak.local Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Via: 1.1 192.168.101.70 (IIRF v2.1) Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header X-Forwarded-Server: issues.koryak.net Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header X-Forwarded-For: 74.98.195.82 Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Cache-Control: max-age=0 Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Connection: keep-alive Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Content-Length: 51911 Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryYgGZWZh5CqQV3vzM Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3 Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Accept-Encoding: gzip,deflate,sdch Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Accept-Language: en-US,en;q=0.8 Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Cookie: PHPSESSID=5b8809uuvhjqoaa77q9pl4fs82; MANTIS_secure_session=0; MANTIS_STRING_COOKIE=6490a44b9041daa991ec3d13d329e2fca90fa8515d49bb4dc6d089a825535ab3; MANTIS_PROJECT_COOKIE=1 Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header X-Forwarded-Host: issues.koryak.net Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Referer: http://issues.koryak.net/track/proj_doc_add_page.php Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4 Wed Aug 11 02:31:31 - 3536 - GenProxyRequestHeadersString: header Origin: http://issues.koryak.net Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: varAccept 0x01237FD8 (application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5) Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: WinHttpConnect devserver.koryak.local 80 Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: WinHttpOpenRequest POST /track/proj_doc_add.php Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: WinHttpAddRequestHeaders Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: WinHttpSendRequest totalLength(51911/51911) Wed Aug 11 02:31:31 - 3536 - Cached: DLL_THREAD_DETACH Wed Aug 11 02:31:31 - 3536 - ProxyPostRequest: WinHttpWriteData bytes(49152)
Coordinator
Aug 20, 2010 at 11:30 AM
Thanks for the report. If you could open a workitem with that info, I'd appreciate it. Your logfile is unreadable in the format it appears in the foru post, so maybe you can attach it as a file to the workitem. I'll be better able to look into the problem if you can do that. Thanks.
Coordinator
Aug 20, 2010 at 11:34 AM
Also, greenley, in the future please don't resuscitate old threads for new discussions. Just open a new thread. Thanks.
Coordinator
Aug 20, 2010 at 11:40 AM
Xzachtli, thanks for all the research. I do have old binaries but they are on my local HD, Not available for download at the moment. The pc is having some problems, and I also no longer have Internet access (sudden change in living arrangements). So it isn't possible for me to make those old binaries available to you at this time. Sorry. I will get to the workitem as soon as is practical.