Mailing-List: contact dev-help@apr.apache.org; run by ezmlm
Precedence: bulk
Errors-To: <wrowe@rowe-clan.net>
Message-ID: <045001c1b442$8323d790$94c0b0d0@v505>
From: "William A. Rowe, Jr." <wrowe@rowe-clan.net>
To: <dev@apr.apache.org>
Subject: Debugging Win32 apr/Apache HANDLES
Date: Tue, 12 Feb 2002 21:51:56 -0600
MIME-Version: 1.0
Content-Type: multipart/mixed;
	boundary="----=_NextPart_000_044B_01C1B40F.7D717060"

This is a multi-part message in MIME format.

------=_NextPart_000_044B_01C1B40F.7D717060
Content-Type: text/plain;
	charset="iso-8859-1"
Content-Transfer-Encoding: 7bit

Ok... took us quite a bit of blood [mostly inflicted on one another],
sweat and tears but the bugs are gone again from the Win32 service.
The question is how can we tell?

"Tell us!"

Because WinNT's SCM (Service Control Manager) has very narrow constraints 
on system startup timing, real 'Debuggers' such as BoundsChecker were 
not helping any.  Had to write up my own detailed flavor of an strace
/ApiSpy32 style utility, with enough feedback of the 'where's' to tie 
down who was corrupting the handles.  I thought this might interest others, 
certainly wanted it archvied somewhere for posterity.

The attached logging patch traps most handle creation/destruction related
calls, and dumps them into a threadsafe logger in the format;

  Handle Sequence ThreadID HandleApiCall(flavor) sourcefile:line
000000ac 0000000a 00000124 CreatePipe(hRead) C:\clean\httpd-2.0\server\mpm\winnt\service.c:637
000000ac 00000037 000006d0 CloseHandle() C:\clean\httpd-2.0\server\mpm\winnt\service.c:597
000000ac 0000005c 000008f4 DuplicateHandle(Target) C:\clean\httpd-2.0\srclib\apr\file_io\win32\filedup.c:122
000000ac 0000005d 000008f4 SetStdHandle() C:\clean\httpd-2.0\srclib\apr\file_io\win32\filedup.c:125
000000ac 00000076 000008f4 GetStdHandle() C:\clean\httpd-2.0\server\mpm\winnt\mpm_winnt.c:1596

The output is logged to ExeImagePathName.### where ### is the pid.

The Sequence is incremented across all threads, so you have a single
reference point of order-of-execution.  Since I immediately run it through
a sort pipe, to get Handle-Major order [I'm looking for twisted and abused
handles], I needed a seq in logging output to keep some order.

More than one log entry may occur per sequence (e.g. CreatePipe(hRead) and (hWrite) 
creation events are logged.)  The API is somewhat cryptic, but I'm sure if you
stare at it for a minute it will make sense.  I left out the ability to check
the return value _as_well_as_ indirect handles, and don't trace the arguments to
the various calls.  These wouldn't be difficult, they simply weren't necessary
when I hacked this together.

Note when looking at DuplicateHandle(EXTERN ---) results that the handle noted
doesn't even live in this processes' address space.

So it was an interesting exercise, and I was curious if it interested others.
I don't see it having a permanent home in the apr source tree, so I'm just
tossing it to the list as a patch to play with.

Bill


------=_NextPart_000_044B_01C1B40F.7D717060
Content-Type: application/octet-stream;
	name="apr_dbg_win32_handles.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
	filename="apr_dbg_win32_handles.patch"

Index: include/apr.hw
===================================================================
RCS file: /home/cvs/apr/include/apr.hw,v
retrieving revision 1.87
diff -u -r1.87 apr.hw
--- include/apr.hw	13 Feb 2002 02:34:26 -0000	1.87
+++ include/apr.hw	13 Feb 2002 03:34:22 -0000
@@ -432,6 +432,8 @@
 #pragma warning(pop)
 #endif
 
+#include "apr_dbg_win32_handles.h"
+
 #endif /* APR_H */
 #endif /* WIN32 */
 /** @} */
Index: include/apr_dbg_win32_handles.h
===================================================================
RCS file: include/apr_dbg_win32_handles.h
diff -N include/apr_dbg_win32_handles.h
--- /dev/null	1 Jan 1970 00:00:00 -0000
+++ include/apr_dbg_win32_handles.h	13 Feb 2002 03:34:22 -0000
@@ -0,0 +1,123 @@
+
+/* apr_dbg_log always returns the ha value.
+ * However, if nh is non-zero, it does not print the ha value,
+ * but prints remaining args as HANDLE, "desc" pairs.
+ */
+APR_DECLARE_NONSTD(HANDLE) apr_dbg_log(char* fn, HANDLE ha, char* fl, int ln, 
+                                       int nh,/* HANDLE *hv, char *dsc */...);
+
+#define apr_dbg_rv(fn, args) (apr_dbg_log(#fn,(fn) args,__FILE__,__LINE__,0))
+
+#define CloseHandle(h) \
+    ((BOOL)apr_dbg_log("CloseHandle", \
+                       (HANDLE)(CloseHandle)(h), \
+                       __FILE__,__LINE__,1, \
+                       &(h),""))
+
+#define CreateEventA(sd,b1,b2,nm) apr_dbg_rv(CreateEventA,(sd,b1,b2,nm))
+#define CreateEventW(sd,b1,b2,nm) apr_dbg_rv(CreateEventW,(sd,b1,b2,nm))
+
+#define CreateFileA(nm,d1,d2,sd,d3,d4,h) apr_dbg_rv(CreateFileA,(nm,d1,d2,sd,d3,d4,h))
+#define CreateFileW(nm,d1,d2,sd,d3,d4,h) apr_dbg_rv(CreateFileW,(nm,d1,d2,sd,d3,d4,h))
+
+#define CreateFileMappingA(fh,sd,d1,d2,d3,nm) apr_dbg_rv(CreateFileMappingA,(fh,sd,d1,d2,d3,nm))
+#define CreateFileMappingW(fh,sd,d1,d2,d3,nm) apr_dbg_rv(CreateFileMappingW,(fh,sd,d1,d2,d3,nm))
+
+#define CreateMutexA(sd,b,nm) apr_dbg_rv(CreateMutexA,(sd,b,nm))
+#define CreateMutexW(sd,b,nm) apr_dbg_rv(CreateMutexW,(sd,b,nm))
+
+#define CreateIoCompletionPort(h1,h2,pd1,d2) apr_dbg_rv(CreateIoCompletionPort,(h1,h2,pd1,d2))
+
+#define CreateNamedPipeA(nm,d1,d2,d3,d4,d5,d6,sd) apr_dbg_rv(CreateNamedPipeA,(nm,d1,d2,d3,d4,d5,d6,sd))
+#define CreateNamedPipeW(nm,d1,d2,d3,d4,d5,d6,sd) apr_dbg_rv(CreateNamedPipeW,(nm,d1,d2,d3,d4,d5,d6,sd))
+
+#define CreatePipe(ph1,ph2,sd,d) \
+    ((BOOL)apr_dbg_log("CreatePipe", \
+                       (HANDLE)(CreatePipe)(ph1,ph2,sd,d), \
+                       __FILE__,__LINE__,2, \
+                       (ph1),"hRead", \
+                       (ph2),"hWrite"))
+
+#define CreateProcessA(s1,s2,sd1,sd2,b,d1,s3,s4,pd2,hr) \
+    ((BOOL)apr_dbg_log("CreateProcessA", \
+                       (HANDLE)(CreateProcessA)(s1,s2,sd1,sd2,b,d1,s3,s4,pd2,hr), \
+                       __FILE__,__LINE__,2, \
+                       &((hr)->hProcess),"hProcess", \
+                       &((hr)->hThread),"hThread"))
+#define CreateProcessW(s1,s2,sd1,sd2,b,d1,s3,s4,pd2,hr) \
+    ((BOOL)apr_dbg_log("CreateProcessW", \
+                       (HANDLE)(CreateProcessW)(s1,s2,sd1,sd2,b,d1,s3,s4,pd2,hr), \
+                       __FILE__,__LINE__,2, \
+                       &((hr)->hProcess),"hProcess", \
+                       &((hr)->hThread),"hThread"))
+
+#define CreateSemaphoreA(sd,d1,d2,nm) apr_dbg_rv(CreateSemaphoreA,(sd,d1,d2,nm))
+#define CreateSemaphoreW(sd,d1,d2,nm) apr_dbg_rv(CreateSemaphoreW,(sd,d1,d2,nm))
+
+#define CreateThread(sd,d1,fn,pv,d2,pd3) apr_dbg_rv(CreateThread,(sd,d1,fn,pv,d2,pd3))
+
+#define DuplicateHandle(h1,h2,h3,ph4,d1,b,d2) \
+    ((BOOL)apr_dbg_log("DuplicateHandle", \
+                       (HANDLE)(DuplicateHandle)(h1,h2,h3,ph4,d1,b,d2), \
+                       __FILE__,__LINE__,2, \
+                       (ph4),((h3)==GetCurrentProcess()) \
+                                   ? "Target" : "EXTERN Target", \
+                       &(h2),((h1)==GetCurrentProcess()) \
+                                 ? "Source" : "EXTERN Source"))
+
+#define GetCurrentProcess() (apr_dbg_log("GetCurrentProcess",(GetCurrentProcess)(),__FILE__,__LINE__,0))
+
+#define GetCurrentThread() (apr_dbg_log("GetCurrentThread",(GetCurrentThread)(),__FILE__,__LINE__,0))
+
+#define GetModuleHandleA(nm) apr_dbg_rv(GetModuleHandleA,(nm))
+#define GetModuleHandleW(nm) apr_dbg_rv(GetModuleHandleW,(nm))
+
+#define GetStdHandle(d) apr_dbg_rv(GetStdHandle,(d))
+
+#define LoadLibraryA(nm) apr_dbg_rv(LoadLibraryA,(nm))
+#define LoadLibraryW(nm) apr_dbg_rv(LoadLibraryW,(nm))
+
+#define LoadLibraryExA(nm,h,d) apr_dbg_rv(LoadLibraryExA,(nm,h,d))
+#define LoadLibraryExW(nm,h,d) apr_dbg_rv(LoadLibraryExW,(nm,h,d))
+
+#define OpenEventA(d,b,nm) apr_dbg_rv(OpenEventA,(d,b,nm))
+#define OpenEventW(d,b,nm) apr_dbg_rv(OpenEventW,(d,b,nm))
+
+#define OpenFileMappingA(d,b,nm) apr_dbg_rv(OpenFileMappingA,(d,b,nm))
+#define OpenFileMappingW(d,b,nm) apr_dbg_rv(OpenFileMappingW,(d,b,nm))
+
+#define SetStdHandle(d,h) \
+    ((BOOL)apr_dbg_log("SetStdHandle", \
+                       (HANDLE)(SetStdHandle)(d,h), \
+                       __FILE__,__LINE__,1,&(h),""))
+
+#define socket(i1,i2,i3) \
+    ((SOCKET)apr_dbg_log("socket", \
+                         (HANDLE)(socket)(i1,i2,i3), \
+                       __FILE__,__LINE__,0))
+
+#define WSASocketA(i1,i2,i3,pi,g,dw) \
+    ((SOCKET)apr_dbg_log("WSASocketA", \
+                         (HANDLE)(WSASocketA)(i1,i2,i3,pi,g,dw), \
+                       __FILE__,__LINE__,0))
+
+#define WSASocketW(i1,i2,i3,pi,g,dw) \
+    ((SOCKET)apr_dbg_log("WSASocketW", \
+                         (HANDLE)(WSASocketW)(i1,i2,i3,pi,g,dw), \
+                       __FILE__,__LINE__,0))
+
+#define closesocket(sh) \
+    ((int)apr_dbg_log("closesocket", \
+                      (HANDLE)(closesocket)(sh), \
+                      __FILE__,__LINE__,1,&(sh),""))
+
+#define _beginthread(fn,d,pv) \
+    ((unsigned long)apr_dbg_log("_beginthread", \
+                                (HANDLE)(_beginthread)(fn,d,pv), \
+                                __FILE__,__LINE__,0))
+
+#define _beginthreadex(sd,d1,fn,pv,d2,pd3) \
+    ((unsigned long)apr_dbg_log("_beginthreadex", \
+                                (HANDLE)(_beginthreadex)(sd,d1,fn,pv,d2,pd3), \
+                                __FILE__,__LINE__,0))
+
Index: misc/win32/misc.c
===================================================================
RCS file: /home/cvs/apr/misc/win32/misc.c,v
retrieving revision 1.9
diff -u -r1.9 misc.c
--- misc/win32/misc.c	30 Jan 2002 03:12:38 -0000	1.9
+++ misc/win32/misc.c	13 Feb 2002 03:34:22 -0000
@@ -196,3 +196,61 @@
     else
         return GetProcAddress(lateDllHandle[fnLib], fnName);
 }
+
+
+APR_DECLARE_NONSTD(HANDLE) apr_dbg_log(char* fn, HANDLE ha, char* fl, int ln, 
+                                       int nh, /* HANDLE hv, char *dsc */...)
+{
+    static DWORD tlsid = 0xFFFFFFFF;
+    static HANDLE fh = NULL;
+    static long ctr = 0;
+    static CRITICAL_SECTION cs;
+    long seq;
+    DWORD wrote;
+    char *sbuf;
+    
+    seq = (InterlockedIncrement)(&ctr);
+
+    if (tlsid == 0xFFFFFFFF) {
+        tlsid = (TlsAlloc)();
+    }
+
+    sbuf = (TlsGetValue)(tlsid);
+    if (!fh || !sbuf) {
+        sbuf = (malloc)(1024);
+        (TlsSetValue)(tlsid, sbuf);
+        sbuf[1023] = '\0';
+        if (!fh) {
+            (GetModuleFileName)(NULL, sbuf, 250);
+            sprintf(strchr(sbuf, '\0'), ".%d",
+                    (GetCurrentProcessId)());
+            fh = (CreateFile)(sbuf, GENERIC_WRITE, 0, NULL, 
+                            CREATE_ALWAYS, 0, NULL);
+            (InitializeCriticalSection)(&cs);
+        }
+    }
+
+    if (!nh) {
+        (sprintf)(sbuf, "%08x %08x %08x %s() %s:%d\n",
+                  ha, seq, GetCurrentThreadId(), fn, fl, ln);
+        (EnterCriticalSection)(&cs);
+        (WriteFile)(fh, sbuf, strlen(sbuf), &wrote, NULL);
+        (LeaveCriticalSection)(&cs);
+    } 
+    else {
+        va_list a;
+        va_start(a,nh);
+        (EnterCriticalSection)(&cs);
+        do {
+            HANDLE *hv = va_arg(a, HANDLE*);
+            char *dsc = va_arg(a, char*);
+            (sprintf)(sbuf, "%08x %08x %08x %s(%s) %s:%d\n",
+                      *hv, seq, GetCurrentThreadId(), 
+                      fn, dsc, fl, ln);
+            (WriteFile)(fh, sbuf, strlen(sbuf), &wrote, NULL);
+        } while (--nh);
+        (LeaveCriticalSection)(&cs);
+        va_end(a);
+    }
+    return ha;
+}

------=_NextPart_000_044B_01C1B40F.7D717060--