Merge logging support in the web server.

NEWS

@@ -13,6 +13,8 @@
 
   * Move named file initilization to BaseRepo. (Dave Borowitz)
 
+  * Add logging utilities and git/HTTP server logging. (Dave Borowitz)
+
  TESTS
 
   * Add tests for sorted_tree_items and C implementation. (Dave Borowitz)

bin/dul-daemon

@@ -18,6 +18,7 @@
 # MA  02110-1301, USA.
 
 import sys
+from dulwich.log_utils import default_logging_config
 from dulwich.repo import Repo
 from dulwich.server import DictBackend, TCPGitServer
 
@@ -27,6 +28,7 @@ if __name__ == "__main__":
     else:
         gitdir = "."
 
+    default_logging_config()
     backend = DictBackend({"/": Repo(gitdir)})
     server = TCPGitServer(backend, 'localhost')
     server.serve_forever()

bin/dul-web

@@ -19,10 +19,37 @@
 
 import os
 import sys
+from dulwich.log_utils import default_logging_config
 from dulwich.repo import Repo
 from dulwich.server import DictBackend
-from dulwich.web import HTTPGitApplication
-from wsgiref.simple_server import make_server
+from dulwich.web import (
+    logger,
+    HTTPGitApplication,
+    )
+from wsgiref.simple_server import (
+    WSGIRequestHandler,
+    make_server,
+    )
+
+
+class HTTPGitRequestHandler(WSGIRequestHandler):
+    """Handler that uses dulwich's logger for logging exceptions."""
+
+    def log_exception(self, exc_info):
+        logger.exception('Exception happened during processing of request',
+                         exc_info=exc_info)
+
+    def log_message(self, format, *args):
+        logger.info(format, *args)
+
+    def log_error(self, *args):
+        logger.error(*args)
+
+
+# TODO: allow serving on other addresses/ports via command-line flag
+LISTEN_ADDR=''
+PORT = 8000
+
 
 if __name__ == "__main__":
     if len(sys.argv) > 1:
@@ -30,8 +57,10 @@ if __name__ == "__main__":
     else:
         gitdir = os.getcwd()
 
+    default_logging_config()
     backend = DictBackend({"/": Repo(gitdir)})
     app = HTTPGitApplication(backend)
-    # TODO: allow serving on other ports via command-line flag
-    server = make_server('', 8000, app)
+    server = make_server(LISTEN_ADDR, PORT, app,
+                         handler_class=HTTPGitRequestHandler)
+    logger.info('Listening for HTTP connections on %s:%d', LISTEN_ADDR, PORT)
     server.serve_forever()

dulwich/log_utils.py

@@ -0,0 +1,67 @@
+# log_utils.py -- Logging utilities for Dulwich
+# Copyright (C) 2010 Google, Inc.
+#
+# This program is free software; you can redistribute it and/or
+# modify it under the terms of the GNU General Public License
+# as published by the Free Software Foundation; either version 2
+# of the License, or (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor,
+# Boston, MA  02110-1301, USA.
+
+"""Logging utilities for Dulwich.
+
+Any module that uses logging needs to do compile-time initialization to set up
+the logging environment. Since Dulwich is also used as a library, clients may
+not want to see any logging output. In that case, we need to use a special
+handler to suppress spurious warnings like "No handlers could be found for
+logger dulwich.foo".
+
+For details on the _NullHandler approach, see:
+http://docs.python.org/library/logging.html#configuring-logging-for-a-library
+
+For many modules, the only function from the logging module they need is
+getLogger; this module exports that function for convenience. If a calling
+module needs something else, it can import the standard logging module directly.
+"""
+
+import logging
+import sys
+
+getLogger = logging.getLogger
+
+
+class _NullHandler(logging.Handler):
+    """No-op logging handler to avoid unexpected logging warnings."""
+
+    def emit(self, record):
+        pass
+
+
+_NULL_HANDLER = _NullHandler()
+_DULWICH_LOGGER = getLogger('dulwich')
+_DULWICH_LOGGER.addHandler(_NULL_HANDLER)
+
+
+def default_logging_config():
+    """Set up the default Dulwich loggers."""
+    remove_null_handler()
+    logging.basicConfig(level=logging.INFO, stream=sys.stderr,
+                        format='%(asctime)s %(levelname)s: %(message)s')
+
+
+def remove_null_handler():
+    """Remove the null handler from the Dulwich loggers.
+
+    If a caller wants to set up logging using something other than
+    default_logging_config, calling this function first is a minor optimization
+    to avoid the overhead of using the _NullHandler.
+    """
+    _DULWICH_LOGGER.removeHandler(_NULL_HANDLER)

dulwich/server.py

@@ -28,8 +28,9 @@ Documentation/technical directory in the cgit distribution, and in particular:
 
 import collections
 import socket
-import zlib
 import SocketServer
+import sys
+import zlib
 
 from dulwich.errors import (
     ApplyDeltaError,
@@ -37,6 +38,7 @@ from dulwich.errors import (
     GitProtocolError,
     ObjectFormatException,
     )
+from dulwich import log_utils
 from dulwich.objects import (
     hex_to_sha,
     )
@@ -58,6 +60,8 @@ from dulwich.protocol import (
     )
 
 
+logger = log_utils.getLogger(__name__)
+
 
 class Backend(object):
     """A backend for the Git smart server implementation."""
@@ -141,6 +145,7 @@ class DictBackend(Backend):
         self.repos = repos
 
     def open_repository(self, path):
+        logger.debug('Opening repository at %s', path)
         # FIXME: What to do in case there is no repo ?
         return self.repos[path]
 
@@ -178,6 +183,7 @@ class Handler(object):
                 raise GitProtocolError('Client does not support required '
                                        'capability %s.' % cap)
         self._client_capabilities = set(caps)
+        logger.info('Client capabilities: %s', caps)
 
     def has_capability(self, cap):
         if self._client_capabilities is None:
@@ -671,6 +677,7 @@ class TCPGitRequestHandler(SocketServer.StreamRequestHandler):
     def handle(self):
         proto = ReceivableProtocol(self.connection.recv, self.wfile.write)
         command, args = proto.read_cmd()
+        logger.info('Handling %s request, args=%s', command, args)
 
         cls = self.handlers.get(command, None)
         if not callable(cls):
@@ -690,5 +697,14 @@ class TCPGitServer(SocketServer.TCPServer):
     def __init__(self, backend, listen_addr, port=TCP_GIT_PORT, handlers=None):
         self.backend = backend
         self.handlers = handlers
+        logger.info('Listening for TCP connections on %s:%d', listen_addr, port)
         SocketServer.TCPServer.__init__(self, (listen_addr, port),
                                         self._make_handler)
+
+    def verify_request(self, request, client_address):
+        logger.info('Handling request from %s', client_address)
+        return True
+
+    def handle_error(self, request, client_address):
+        logger.exception('Exception happened during processing of request '
+                         'from %s', client_address)

dulwich/web.py

@@ -27,6 +27,7 @@ try:
     from urlparse import parse_qs
 except ImportError:
     from dulwich.misc import parse_qs
+from dulwich import log_utils
 from dulwich.protocol import (
     ReceivableProtocol,
     )
@@ -37,6 +38,9 @@ from dulwich.server import (
     )
 
 
+logger = log_utils.getLogger(__name__)
+
+
 # HTTP error strings
 HTTP_OK = '200 OK'
 HTTP_NOT_FOUND = '404 Not Found'
@@ -106,12 +110,14 @@ def _url_to_path(url):
 def get_text_file(req, backend, mat):
     req.nocache()
     path = _url_to_path(mat.group())
+    logger.info('Sending plain text file %s', path)
     return send_file(req, get_repo(backend, mat).get_named_file(path),
                      'text/plain')
 
 
 def get_loose_object(req, backend, mat):
     sha = mat.group(1) + mat.group(2)
+    logger.info('Sending loose object %s', sha)
     object_store = get_repo(backend, mat).object_store
     if not object_store.contains_loose(sha):
         yield req.not_found('Object not found')
@@ -128,6 +134,7 @@ def get_loose_object(req, backend, mat):
 def get_pack_file(req, backend, mat):
     req.cache_forever()
     path = _url_to_path(mat.group())
+    logger.info('Sending pack file %s', path)
     return send_file(req, get_repo(backend, mat).get_named_file(path),
                      'application/x-git-packed-objects')
 
@@ -135,6 +142,7 @@ def get_pack_file(req, backend, mat):
 def get_idx_file(req, backend, mat):
     req.cache_forever()
     path = _url_to_path(mat.group())
+    logger.info('Sending pack file %s', path)
     return send_file(req, get_repo(backend, mat).get_named_file(path),
                      'application/x-git-packed-objects-toc')
 
@@ -162,6 +170,7 @@ def get_info_refs(req, backend, mat):
         # TODO: select_getanyfile() (see http-backend.c)
         req.nocache()
         req.respond(HTTP_OK, 'text/plain')
+        logger.info('Emulating dumb info/refs')
         repo = get_repo(backend, mat)
         refs = repo.get_refs()
         for name in sorted(refs.iterkeys()):
@@ -182,6 +191,7 @@ def get_info_refs(req, backend, mat):
 def get_info_packs(req, backend, mat):
     req.nocache()
     req.respond(HTTP_OK, 'text/plain')
+    logger.info('Emulating dumb info/packs')
     for pack in get_repo(backend, mat).object_store.packs:
         yield 'P pack-%s.pack\n' % pack.name()
 
@@ -211,6 +221,7 @@ class _LengthLimitedFile(object):
 
 def handle_service_request(req, backend, mat):
     service = mat.group().lstrip('/')
+    logger.info('Handling service request for %s', service)
     handler_cls = req.handlers.get(service, None)
     if handler_cls is None:
         yield req.forbidden('Unsupported service %s' % service)
@@ -263,12 +274,14 @@ class HTTPGitRequest(object):
     def not_found(self, message):
         """Begin a HTTP 404 response and return the text of a message."""
         self._cache_headers = []
+        logger.info('Not found: %s', message)
         self.respond(HTTP_NOT_FOUND, 'text/plain')
         return message
 
     def forbidden(self, message):
         """Begin a HTTP 403 response and return the text of a message."""
         self._cache_headers = []
+        logger.info('Forbidden: %s', message)
         self.respond(HTTP_FORBIDDEN, 'text/plain')
         return message