Added a debug logging facility to trace ZServer requests. Updated the HTTP and...

Added a debug logging facility to trace ZServer requests. Updated the HTTP and PCGI servers to work with the debug logger. Eventially this facility will be rolled into zLOG.

ZServer/DebugLogger.py

+##############################################################################
+# 
+# Zope Public License (ZPL) Version 1.0
+# -------------------------------------
+# 
+# Copyright (c) Digital Creations.  All rights reserved.
+# 
+# This license has been certified as Open Source(tm).
+# 
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions are
+# met:
+# 
+# 1. Redistributions in source code must retain the above copyright
+#    notice, this list of conditions, and the following disclaimer.
+# 
+# 2. Redistributions in binary form must reproduce the above copyright
+#    notice, this list of conditions, and the following disclaimer in
+#    the documentation and/or other materials provided with the
+#    distribution.
+# 
+# 3. Digital Creations requests that attribution be given to Zope
+#    in any manner possible. Zope includes a "Powered by Zope"
+#    button that is installed by default. While it is not a license
+#    violation to remove this button, it is requested that the
+#    attribution remain. A significant investment has been put
+#    into Zope, and this effort will continue if the Zope community
+#    continues to grow. This is one way to assure that growth.
+# 
+# 4. All advertising materials and documentation mentioning
+#    features derived from or use of this software must display
+#    the following acknowledgement:
+# 
+#      "This product includes software developed by Digital Creations
+#      for use in the Z Object Publishing Environment
+#      (http://www.zope.org/)."
+# 
+#    In the event that the product being advertised includes an
+#    intact Zope distribution (with copyright and license included)
+#    then this clause is waived.
+# 
+# 5. Names associated with Zope or Digital Creations must not be used to
+#    endorse or promote products derived from this software without
+#    prior written permission from Digital Creations.
+# 
+# 6. Modified redistributions of any form whatsoever must retain
+#    the following acknowledgment:
+# 
+#      "This product includes software developed by Digital Creations
+#      for use in the Z Object Publishing Environment
+#      (http://www.zope.org/)."
+# 
+#    Intact (re-)distributions of any official Zope release do not
+#    require an external acknowledgement.
+# 
+# 7. Modifications are encouraged but must be packaged separately as
+#    patches to official Zope releases.  Distributions that do not
+#    clearly separate the patches from the original work must be clearly
+#    labeled as unofficial distributions.  Modifications which do not
+#    carry the name Zope may be packaged in any form, as long as they
+#    conform to all of the clauses above.
+# 
+# 
+# Disclaimer
+# 
+#   THIS SOFTWARE IS PROVIDED BY DIGITAL CREATIONS ``AS IS'' AND ANY
+#   EXPRESSED OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+#   IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
+#   PURPOSE ARE DISCLAIMED.  IN NO EVENT SHALL DIGITAL CREATIONS OR ITS
+#   CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+#   SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+#   LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF
+#   USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
+#   ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
+#   OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
+#   OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+#   SUCH DAMAGE.
+# 
+# 
+# This software consists of contributions made by Digital Creations and
+# many individuals on behalf of Digital Creations.  Specific
+# attributions are listed in the accompanying credits file.
+# 
+##############################################################################
+
+import time, thread
+
+class DebugLogger:
+	"""
+	Logs debugging information about how ZServer is handling requests
+	and responses. This log can be used to help locate troublesome requests.
+	
+	The format is:
+	
+		<code> <request id> <time> <data>
+	
+	where:
+	
+		'code' is B for begin, I for received input, A for received output,
+			E for sent output.
+		
+		'request id' is a unique request id.
+		
+		'time' is the time in GMT ISO format.
+		
+		'data' is the HTTP method and the PATH INFO for B, the size of the input
+			for I, the HTTP status code and the size of the output for A, or
+			nothing for E.
+			
+	Note: This facility will be probably be adapted to the zLOG framework.
+	"""
+	
+	def __init__(self, filename):
+		self.file=open(filename, 'a+b')
+		l=thread.allocate_lock()
+		self._acquire=l.acquire
+		self._release=l.release
+		
+	def log(self, code, request_id, data=''):
+		self._acquire()
+		try:
+			t=time.strftime('%Y-%m-%dT%H:%M:%S', time.gmtime(time.time()))
+			self.file.write(
+				'%s %s %s %s\n' % (code, request_id, t, data)
+				)
+		finally:
+			self._release()
+
+
+def log(*args): pass
+
+		
+		
\ No newline at end of file

ZServer/HTTPServer.py

@@ -123,7 +123,7 @@ from medusa.default_handler import split_path, unquote, get_header
 from ZServer import CONNECTION_LIMIT, ZOPE_VERSION, ZSERVER_VERSION
 
 from zLOG import LOG, register_subsystem, BLATHER, INFO, WARNING, ERROR
-
+import DebugLogger
 
 register_subsystem('ZServer HTTPServer')
 
@@ -140,10 +140,7 @@ header2env={'content-length'    : 'CONTENT_LENGTH',
 
 class zhttp_handler:
     "A medusa style handler for zhttp_server"
-    
-    # XXX add code to allow env overriding 
-    
-    
+        
     def __init__ (self, module, uri_base=None, env=None):
         """Creates a zope_handler
         
@@ -182,6 +179,9 @@ class zhttp_handler:
 
     def handle_request(self,request):
         self.hits.increment()
+
+        DebugLogger.log('B', id(request), '%s %s' % (string.upper(request.command), request.uri))
+
         size=get_header(CONTENT_LENGTH, request.header)
         if size and size != '0':
             size=string.atoi(size)
@@ -269,6 +269,14 @@ class zhttp_handler:
 
     def continue_request(self, sin, request):
         "continue handling request now that we have the stdin"
+       
+        s=get_header(CONTENT_LENGTH, request.header)
+        if s:
+            s=string.atoi(s)
+        else:
+            s=0    
+        DebugLogger.log('I', id(request), s)
+
         env=self.get_environment(request)
         zresponse=make_response(request,env)
         zrequest=HTTPRequest(sin, env, zresponse)

ZServer/PCGIServer.py

@@ -110,7 +110,8 @@ from PubCore import handle
 from PubCore.ZEvent import Wakeup
 from ZPublisher.HTTPResponse import HTTPResponse
 from ZPublisher.HTTPRequest import HTTPRequest
-from Producers import ShutdownProducer, LoggingProducer
+from Producers import ShutdownProducer, LoggingProducer, CallbackProducer
+import DebugLogger
 
 from cStringIO import StringIO
 from tempfile import TemporaryFile
@@ -141,6 +142,9 @@ class PCGIChannel(asynchat.async_chat):
             self.size=string.atoi(self.data.read())
             self.set_terminator(self.size)
             if self.size==0:
+            
+                DebugLogger.log('I', id(self), 0)
+            
                 self.set_terminator('\r\n') 
                 self.data=StringIO()
                 self.send_response()
@@ -170,9 +174,16 @@ class PCGIChannel(asynchat.async_chat):
                         string.strip(self.env['PATH_INFO']),'/'))
                 self.env['PATH_INFO'] = '/' + string.join(path[len(script):],'/')
             self.data=StringIO()
+            
+            DebugLogger.log('B', id(self), 
+                '%s %s' % (self.env['REQUEST_METHOD'], self.env['PATH_INFO']))
+                
             # now read the next size header
             self.set_terminator(10)
         else:
+
+            DebugLogger.log('I', id(self), self.terminator)     
+        
             # we're done, we've got both env and stdin
             self.set_terminator('\r\n')
             self.data.seek(0)
@@ -195,9 +206,8 @@ class PCGIChannel(asynchat.async_chat):
             return 1
      
     def log_request(self, bytes):
-        # XXX need to add reply code logging
         if self.env.has_key('PATH_INFO'):
-            path='%s%s' % (self.server.module, self.env['PATH_INFO'])
+            path=self.env['PATH_INFO']
         else:
             path='%s/' % self.server.module
         if self.env.has_key('REQUEST_METHOD'):
@@ -207,24 +217,24 @@ class PCGIChannel(asynchat.async_chat):
         if self.addr:
             self.server.logger.log (
                 self.addr[0],
-                '%d - - [%s] "%s %s" %d' % (
+                '%d - - [%s] "%s %s" %d %d' % (
                     self.addr[1],
                     time.strftime (
                     '%d/%b/%Y:%H:%M:%S ',
                     time.gmtime(time.time())
                     ) + tz_for_log,
-                    method, path, bytes
+                    method, path, self.reply_code, bytes
                     )
                 )
         else:
             self.server.logger.log (
                 '127.0.0.1',
-                '- - [%s] "%s %s" %d' % (
+                '- - [%s] "%s %s" %d %d' % (
                     time.strftime (
                     '%d/%b/%Y:%H:%M:%S ',
                     time.gmtime(time.time())
                     ) + tz_for_log,
-                    method, path, bytes
+                    method, path, self.reply_code, bytes
                     )
                 )       
 
@@ -399,8 +409,16 @@ class PCGIPipe:
     def close(self):
         data=self._data.getvalue()
         l=len(data)
+        
+        DebugLogger.log('A', id(self._channel), 
+            '%s %s' % (self._channel.reply_code, l))
+        
         self._channel.push('%010d%s%010d' % (l, data, 0), 0)
         self._channel.push(LoggingProducer(self._channel, l, 'log_request'), 0)
+        
+        self._channel.push(CallbackProducer(
+            lambda t=('E', id(self._channel)): apply(DebugLogger.log,t)))
+        
         if self._shutdown:
             try: r=self._shutdown[0]
             except: r=0
@@ -413,10 +431,11 @@ class PCGIPipe:
         self._data=None
         self._channel=None
         
-    def finish(self,request):
-        if request.headers.get('bobo-exception-type','') == \
+    def finish(self, response):
+        if response.headers.get('bobo-exception-type','') == \
                 'exceptions.SystemExit':
-            r=request.headers.get('bobo-exception-value','0')
+            r=response.headers.get('bobo-exception-value','0')
             try: r=string.atoi(r)
             except: r = r and 1 or 0
             self._shutdown=r,
+        self._channel.reply_code=response.status

lib/python/ZServer/DebugLogger.py

+##############################################################################
+# 
+# Zope Public License (ZPL) Version 1.0
+# -------------------------------------
+# 
+# Copyright (c) Digital Creations.  All rights reserved.
+# 
+# This license has been certified as Open Source(tm).
+# 
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions are
+# met:
+# 
+# 1. Redistributions in source code must retain the above copyright
+#    notice, this list of conditions, and the following disclaimer.
+# 
+# 2. Redistributions in binary form must reproduce the above copyright
+#    notice, this list of conditions, and the following disclaimer in
+#    the documentation and/or other materials provided with the
+#    distribution.
+# 
+# 3. Digital Creations requests that attribution be given to Zope
+#    in any manner possible. Zope includes a "Powered by Zope"
+#    button that is installed by default. While it is not a license
+#    violation to remove this button, it is requested that the
+#    attribution remain. A significant investment has been put
+#    into Zope, and this effort will continue if the Zope community
+#    continues to grow. This is one way to assure that growth.
+# 
+# 4. All advertising materials and documentation mentioning
+#    features derived from or use of this software must display
+#    the following acknowledgement:
+# 
+#      "This product includes software developed by Digital Creations
+#      for use in the Z Object Publishing Environment
+#      (http://www.zope.org/)."
+# 
+#    In the event that the product being advertised includes an
+#    intact Zope distribution (with copyright and license included)
+#    then this clause is waived.
+# 
+# 5. Names associated with Zope or Digital Creations must not be used to
+#    endorse or promote products derived from this software without
+#    prior written permission from Digital Creations.
+# 
+# 6. Modified redistributions of any form whatsoever must retain
+#    the following acknowledgment:
+# 
+#      "This product includes software developed by Digital Creations
+#      for use in the Z Object Publishing Environment
+#      (http://www.zope.org/)."
+# 
+#    Intact (re-)distributions of any official Zope release do not
+#    require an external acknowledgement.
+# 
+# 7. Modifications are encouraged but must be packaged separately as
+#    patches to official Zope releases.  Distributions that do not
+#    clearly separate the patches from the original work must be clearly
+#    labeled as unofficial distributions.  Modifications which do not
+#    carry the name Zope may be packaged in any form, as long as they
+#    conform to all of the clauses above.
+# 
+# 
+# Disclaimer
+# 
+#   THIS SOFTWARE IS PROVIDED BY DIGITAL CREATIONS ``AS IS'' AND ANY
+#   EXPRESSED OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+#   IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
+#   PURPOSE ARE DISCLAIMED.  IN NO EVENT SHALL DIGITAL CREATIONS OR ITS
+#   CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+#   SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+#   LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF
+#   USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
+#   ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
+#   OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
+#   OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+#   SUCH DAMAGE.
+# 
+# 
+# This software consists of contributions made by Digital Creations and
+# many individuals on behalf of Digital Creations.  Specific
+# attributions are listed in the accompanying credits file.
+# 
+##############################################################################
+
+import time, thread
+
+class DebugLogger:
+	"""
+	Logs debugging information about how ZServer is handling requests
+	and responses. This log can be used to help locate troublesome requests.
+	
+	The format is:
+	
+		<code> <request id> <time> <data>
+	
+	where:
+	
+		'code' is B for begin, I for received input, A for received output,
+			E for sent output.
+		
+		'request id' is a unique request id.
+		
+		'time' is the time in GMT ISO format.
+		
+		'data' is the HTTP method and the PATH INFO for B, the size of the input
+			for I, the HTTP status code and the size of the output for A, or
+			nothing for E.
+			
+	Note: This facility will be probably be adapted to the zLOG framework.
+	"""
+	
+	def __init__(self, filename):
+		self.file=open(filename, 'a+b')
+		l=thread.allocate_lock()
+		self._acquire=l.acquire
+		self._release=l.release
+		
+	def log(self, code, request_id, data=''):
+		self._acquire()
+		try:
+			t=time.strftime('%Y-%m-%dT%H:%M:%S', time.gmtime(time.time()))
+			self.file.write(
+				'%s %s %s %s\n' % (code, request_id, t, data)
+				)
+		finally:
+			self._release()
+
+
+def log(*args): pass
+
+		
+		
\ No newline at end of file

lib/python/ZServer/HTTPServer.py

@@ -123,7 +123,7 @@ from medusa.default_handler import split_path, unquote, get_header
 from ZServer import CONNECTION_LIMIT, ZOPE_VERSION, ZSERVER_VERSION
 
 from zLOG import LOG, register_subsystem, BLATHER, INFO, WARNING, ERROR
-
+import DebugLogger
 
 register_subsystem('ZServer HTTPServer')
 
@@ -140,10 +140,7 @@ header2env={'content-length'    : 'CONTENT_LENGTH',
 
 class zhttp_handler:
     "A medusa style handler for zhttp_server"
-    
-    # XXX add code to allow env overriding 
-    
-    
+        
     def __init__ (self, module, uri_base=None, env=None):
         """Creates a zope_handler
         
@@ -182,6 +179,9 @@ class zhttp_handler:
 
     def handle_request(self,request):
         self.hits.increment()
+
+        DebugLogger.log('B', id(request), '%s %s' % (string.upper(request.command), request.uri))
+
         size=get_header(CONTENT_LENGTH, request.header)
         if size and size != '0':
             size=string.atoi(size)
@@ -269,6 +269,14 @@ class zhttp_handler:
 
     def continue_request(self, sin, request):
         "continue handling request now that we have the stdin"
+       
+        s=get_header(CONTENT_LENGTH, request.header)
+        if s:
+            s=string.atoi(s)
+        else:
+            s=0    
+        DebugLogger.log('I', id(request), s)
+
         env=self.get_environment(request)
         zresponse=make_response(request,env)
         zrequest=HTTPRequest(sin, env, zresponse)

lib/python/ZServer/PCGIServer.py

@@ -110,7 +110,8 @@ from PubCore import handle
 from PubCore.ZEvent import Wakeup
 from ZPublisher.HTTPResponse import HTTPResponse
 from ZPublisher.HTTPRequest import HTTPRequest
-from Producers import ShutdownProducer, LoggingProducer
+from Producers import ShutdownProducer, LoggingProducer, CallbackProducer
+import DebugLogger
 
 from cStringIO import StringIO
 from tempfile import TemporaryFile
@@ -141,6 +142,9 @@ class PCGIChannel(asynchat.async_chat):
             self.size=string.atoi(self.data.read())
             self.set_terminator(self.size)
             if self.size==0:
+            
+                DebugLogger.log('I', id(self), 0)
+            
                 self.set_terminator('\r\n') 
                 self.data=StringIO()
                 self.send_response()
@@ -170,9 +174,16 @@ class PCGIChannel(asynchat.async_chat):
                         string.strip(self.env['PATH_INFO']),'/'))
                 self.env['PATH_INFO'] = '/' + string.join(path[len(script):],'/')
             self.data=StringIO()
+            
+            DebugLogger.log('B', id(self), 
+                '%s %s' % (self.env['REQUEST_METHOD'], self.env['PATH_INFO']))
+                
             # now read the next size header
             self.set_terminator(10)
         else:
+
+            DebugLogger.log('I', id(self), self.terminator)     
+        
             # we're done, we've got both env and stdin
             self.set_terminator('\r\n')
             self.data.seek(0)
@@ -195,9 +206,8 @@ class PCGIChannel(asynchat.async_chat):
             return 1
      
     def log_request(self, bytes):
-        # XXX need to add reply code logging
         if self.env.has_key('PATH_INFO'):
-            path='%s%s' % (self.server.module, self.env['PATH_INFO'])
+            path=self.env['PATH_INFO']
         else:
             path='%s/' % self.server.module
         if self.env.has_key('REQUEST_METHOD'):
@@ -207,24 +217,24 @@ class PCGIChannel(asynchat.async_chat):
         if self.addr:
             self.server.logger.log (
                 self.addr[0],
-                '%d - - [%s] "%s %s" %d' % (
+                '%d - - [%s] "%s %s" %d %d' % (
                     self.addr[1],
                     time.strftime (
                     '%d/%b/%Y:%H:%M:%S ',
                     time.gmtime(time.time())
                     ) + tz_for_log,
-                    method, path, bytes
+                    method, path, self.reply_code, bytes
                     )
                 )
         else:
             self.server.logger.log (
                 '127.0.0.1',
-                '- - [%s] "%s %s" %d' % (
+                '- - [%s] "%s %s" %d %d' % (
                     time.strftime (
                     '%d/%b/%Y:%H:%M:%S ',
                     time.gmtime(time.time())
                     ) + tz_for_log,
-                    method, path, bytes
+                    method, path, self.reply_code, bytes
                     )
                 )       
 
@@ -399,8 +409,16 @@ class PCGIPipe:
     def close(self):
         data=self._data.getvalue()
         l=len(data)
+        
+        DebugLogger.log('A', id(self._channel), 
+            '%s %s' % (self._channel.reply_code, l))
+        
         self._channel.push('%010d%s%010d' % (l, data, 0), 0)
         self._channel.push(LoggingProducer(self._channel, l, 'log_request'), 0)
+        
+        self._channel.push(CallbackProducer(
+            lambda t=('E', id(self._channel)): apply(DebugLogger.log,t)))
+        
         if self._shutdown:
             try: r=self._shutdown[0]
             except: r=0
@@ -413,10 +431,11 @@ class PCGIPipe:
         self._data=None
         self._channel=None
         
-    def finish(self,request):
-        if request.headers.get('bobo-exception-type','') == \
+    def finish(self, response):
+        if response.headers.get('bobo-exception-type','') == \
                 'exceptions.SystemExit':
-            r=request.headers.get('bobo-exception-value','0')
+            r=response.headers.get('bobo-exception-value','0')
             try: r=string.atoi(r)
             except: r = r and 1 or 0
             self._shutdown=r,
+        self._channel.reply_code=response.status