DebugLogger

Pinning down the problem

Activating the DebugLogger causes the various ZServer? protocol servers to log when a request is received, processed and sent back to the client. To activate DebugLogger, include the following code in z2.py, just before Medusa is started:

    from ZServer import DebugLogger
    logfile=os.path.join(INSTANCE_HOME, 'var/debug.log')
    DebugLogger.log=DebugLogger.DebugLogger(logfile).log

(see the How To for further information)

You can add arbitrary logging by calling the DebugLogger.Log method in the servers in the ZServer? directory. In my case, PCGIServer? is used, and I have modified the send_response method so that it logs additional detail:

    def send_response(self):
        # create an output pipe by passing request to ZPublisher,
        # and requesting a callback of self.log with the module
        # name and PATH_INFO as an argument.
        self.done=1        
        # MC 2000-04-13 additional logging to determine cause of hanging
        DebugLogger.log('X', id(self), 'send_response: before PCGIResponse')
        response=PCGIResponse(stdout=PCGIPipe(self), stderr=StringIO())
        # MC 2000-04-13 additional logging to determine cause of hanging
        DebugLogger.log('X', id(self), 'send_response: before HTTPRequest')
        request=HTTPRequest(self.data, self.env, response)
        # MC 2000-04-13 additional logging to determine cause of hanging
        DebugLogger.log('X', id(self), 'send_response: before handle')
        handle(self.server.module, request, response)

Analysing the log

Once you think you've caught a thread hanging, you can run the log through an analyser script to identify at what point things went awry. I've taken the script by Amos Lattier, and modified it so that it will work correctly with any additional logging:

    import string, sys

    def analyze(f):
      requests={}
      completed_requests=[];
      while 1:
        line=f.readline()
        line=string.strip(line)
        if not line:
          break
        code, id = string.split(line)[ :2 ]
        codes=requests.get(id, [])
        codes.append(line)
        if code == 'E':
          completed_requests.append(id)
          print '.',
        else:
          requests[ id ]=codes
      print
      for id, l in requests.items():
        if id not in completed_requests:
          print 'request', id, 'did not end\n', string.join(l, '\n'), '\n'

    if __name__=='__main__':
      analyze(open(sys.argv[1]))

The script parses your debug.log file and looks for requests that failed to complete, i.e., those that do not have an E code. It then prints out everything that was logged about those requests.

MarcusCollins