Add Logging for all http actions.

* Use stabdard python's logging lib.
* Log http-request/response/errors.
* Cmd-line options for logging-format and filename.
* Cmd-line options for request /response/error requests/responses/errors
props to log.
* Add `-v` option controlling verbosity.
* Add docs about new options.
* TCs only `-v` & `--log_file ` (logging statements used throughout all
tests).

README.rst

@@ -112,6 +112,28 @@ pypi-server -h will print a detailed usage message::
     -o, --overwrite
       allow overwriting existing package files
 
+    -v
+      enable INFO logging;  repeate for more verbosity.
+
+    --log-file <FILE>
+      write logging info into this FILE.
+
+    --log-frmt <FILE>
+      the logging format-string.  (see `logging.LogRecord` class from standard python library)
+      [Default: %(asctime)s|%(levelname)s|%(thread)d|%(message)s] 
+
+    --log-req-frmt FORMAT
+      a format-string selecting Http-Request properties to log; set to  '%s' to see them all.
+      [Default: %(bottle.request)s] 
+
+    --log-res-frmt FORMAT
+      a format-string selecting Http-Response properties to log; set to  '%s' to see them all.
+      [Default: %(status)s]
+
+    --log-err-frmt FORMAT
+      a format-string selecting Http-Error properties to log; set to  '%s' to see them all.
+      [Default: %(body)s: %(exception)s \n%(traceback)s]
+
   pypi-server -h
   pypi-server --help
     show this help message

pypiserver/__init__.py

@@ -6,7 +6,10 @@ def app(root=None,
         redirect_to_fallback=True,
         fallback_url=None,
         password_file=None,
-        overwrite=False):
+        overwrite=False,
+        log_req_frmt="%(bottle.request)s", 
+        log_res_frmt="%(status)s", 
+        log_err_frmt="%(body)s: %(exception)s \n%(traceback)s"):
     import sys, os
     from pypiserver import core
     sys.modules.pop("pypiserver._app", None)
@@ -22,7 +25,8 @@ def app(root=None,
         fallback_url = "http://pypi.python.org/simple"
 
     _app.configure(root=root, redirect_to_fallback=redirect_to_fallback, fallback_url=fallback_url,
-                   password_file=password_file, overwrite=overwrite)
+                   password_file=password_file, overwrite=overwrite, 
+                   log_req_frmt=log_req_frmt, log_res_frmt=log_res_frmt, log_err_frmt=log_err_frmt)
     _app.app.module = _app
 
     bottle.debug(True)

pypiserver/_app.py

@@ -1,4 +1,4 @@
-import sys, os, itertools, zipfile, mimetypes
+import sys, os, itertools, zipfile, mimetypes, logging
 
 try:
     from io import BytesIO
@@ -10,10 +10,11 @@ if sys.version_info >= (3, 0):
 else:
     from urlparse import urljoin
 
-from bottle import static_file, redirect, request, HTTPError, Bottle
+from bottle import static_file, redirect, request, response, HTTPError, Bottle
 from pypiserver import __version__
 from pypiserver.core import listdir, find_packages, store, get_prefixes, exists
 
+log = logging.getLogger('pypiserver.http')
 packages = None
 
 
@@ -36,9 +37,21 @@ def configure(root=None,
               redirect_to_fallback=True,
               fallback_url=None,
               password_file=None,
-              overwrite=False):
+              overwrite=False,
+              log_req_frmt=None, 
+              log_res_frmt=None,
+              log_err_frmt=None):
     global packages
 
+    log.info("Starting(%s)", dict(root=root,
+              redirect_to_fallback=redirect_to_fallback,
+              fallback_url=fallback_url,
+              password_file=password_file,
+              overwrite=overwrite,
+              log_req_frmt=log_req_frmt, 
+              log_res_frmt=log_res_frmt,
+              log_err_frmt=log_err_frmt))
+
     if root is None:
         root = os.path.expanduser("~/packages")
 
@@ -68,9 +81,33 @@ def configure(root=None,
         config.htpasswdfile = HtpasswdFile(password_file)
     config.overwrite = overwrite
 
+    config.log_req_frmt = log_req_frmt
+    config.log_res_frmt = log_res_frmt
+    config.log_err_frmt = log_err_frmt
+
 app = Bottle()
 
 
+@app.hook('before_request')
+def log_request():
+    log.info(config.log_req_frmt, request.environ)
+
+
+@app.hook('after_request')
+def log_response():
+    log.info(config.log_res_frmt, #vars(response))  ## DOES NOT WORK!
+            dict(
+                response=response, 
+                status=response.status, headers=response.headers, 
+                body=response.body, cookies=response.COOKIES,
+    ))
+
+
+@app.error
+def log_error(http_error):
+    log.info(config.log_err_frmt, vars(http_error))
+
+
 @app.route("/favicon.ico")
 def favicon():
     return HTTPError(404)

pypiserver/core.py

@@ -1,7 +1,7 @@
 #! /usr/bin/env python
 """minimal PyPI like server for use with pip/easy_install"""
 
-import os, sys, getopt, re, mimetypes, warnings, itertools
+import os, sys, getopt, re, mimetypes, warnings, itertools, logging
 
 warnings.filterwarnings("ignore", "Python 2.5 support may be dropped in future versions of Bottle")
 from pypiserver import bottle, __version__, app
@@ -12,12 +12,20 @@ mimetypes.add_type("application/octet-stream", ".egg")
 mimetypes.add_type("application/octet-stream", ".whl")
 
 DEFAULT_SERVER = None
+log = logging.getLogger('pypiserver.core')
 
 # --- the following two functions were copied from distribute's pkg_resources module
 component_re = re.compile(r'(\d+ | [a-z]+ | \.| -)', re.VERBOSE)
 replace = {'pre': 'c', 'preview': 'c', '-': 'final-', 'rc': 'c', 'dev': '@'}.get
 
 
+def init_logging(level=None, format=None, filename=None):
+    logging.basicConfig(level=level, format=format)
+    rlog = logging.getLogger()
+    rlog.setLevel(level)
+    if filename:
+        rlog.addHandler(logging.FileHandler(filename))
+
 def _parse_version_parts(s):
     for part in component_re.split(s):
         part = replace(part, part)
@@ -159,6 +167,8 @@ def store(root, filename, data):
     dest_fh = open(dest_fn, "wb")
     dest_fh.write(data)
     dest_fh.close()
+    
+    log.info("Stored package: %s", filename)
     return True
 
 
@@ -203,6 +213,28 @@ pypi-server understands the following options:
   -o, --overwrite
     allow overwriting existing package files
 
+  -v
+    enable verbose logging;  repeate for more verbosity.
+
+  --log-file <FILE>
+    write logging info into this FILE.
+
+  --log-frmt <FILE>
+    the logging format-string.  (see `logging.LogRecord` class from standard python library)
+    [Default: %(asctime)s|%(levelname)s|%(thread)d|%(message)s] 
+
+  --log-req-frmt FORMAT
+    a format-string selecting Http-Request properties to log; set to  '%s' to see them all.
+    [Default: %(bottle.request)s] 
+    
+  --log-res-frmt FORMAT
+    a format-string selecting Http-Response properties to log; set to  '%s' to see them all.
+    [Default: %(status)s]
+
+  --log-err-frmt FORMAT
+    a format-string selecting Http-Error properties to log; set to  '%s' to see them all.
+    [Default: %(body)s: %(exception)s \n%(traceback)s]
+
 pypi-server -h
 pypi-server --help
   show this help message
@@ -231,7 +263,6 @@ The following additional options can be specified with -U:
 Visit http://pypi.python.org/pypi/pypiserver for more information.
 """)
 
-
 def main(argv=None):
     if argv is None:
         argv = sys.argv
@@ -246,13 +277,19 @@ def main(argv=None):
     fallback_url = "http://pypi.python.org/simple"
     password_file = None
     overwrite = False
+    verbosity = 1
+    log_file = None
+    log_frmt = None
+    log_req_frmt = None
+    log_res_frmt = None
+    log_err_frmt = None
 
     update_dry_run = True
     update_directory = None
     update_stable_only = True
 
     try:
-        opts, roots = getopt.getopt(argv[1:], "i:p:r:d:P:Uuxoh", [
+        opts, roots = getopt.getopt(argv[1:], "i:p:r:d:P:Uuvxoh", [
             "interface=",
             "passwords=",
             "port=",
@@ -261,6 +298,11 @@ def main(argv=None):
             "fallback-url=",
             "disable-fallback",
             "overwrite",
+            "log-file=",
+            "log-frmt=",
+            "log-req-frmt=",
+            "log-res-frmt=",
+            "log-err-frmt=",
             "version",
             "help"
         ])
@@ -299,6 +341,18 @@ def main(argv=None):
             password_file = v
         elif k in ("-o", "--overwrite"):
             overwrite = True
+        elif k == "--log-file":
+            log_file = v
+        elif k == "--log-frmt":
+            log_frmt = v
+        elif k == "--log-req-frmt":
+            log_req_frmt = v
+        elif k == "--log-res-frmt":
+            log_res_frmt = v
+        elif k == "--log-err-frmt":
+            log_err_frmt = v
+        elif k == "-v":
+            verbosity += 1
         elif k in ("-h", "--help"):
             usage()
             sys.exit(0)
@@ -308,6 +362,9 @@ def main(argv=None):
 
     roots = [os.path.abspath(x) for x in roots]
 
+    verbose_levels = [logging.WARNING, logging.INFO, logging.DEBUG, logging.NOTSET]
+    log_level = list(zip(verbose_levels, range(verbosity)))[-1][0]
+    init_logging(level=log_level, filename=log_file, format=log_frmt)
     
     if command == "update":
         packages = frozenset(itertools.chain(*[listdir(r) for r in roots]))
@@ -321,6 +378,7 @@ def main(argv=None):
         password_file=password_file,
         fallback_url=fallback_url,
         overwrite=overwrite,
+        log_req_frmt=log_req_frmt, log_res_frmt=log_res_frmt, log_err_frmt=log_err_frmt,
     )
     server = server or "auto"
     sys.stdout.write("This is pypiserver %s serving %r on http://%s:%s\n\n" % (__version__, ", ".join(roots), host, port))

tests/test_app.py

@@ -3,6 +3,10 @@
 from pypiserver import core  # do no remove. needed for bottle
 import pytest, bottle, webtest
 
+## Enable logging to detect any problems with it
+##
+import logging
+core.init_logging(level=logging.NOTSET)
 
 @pytest.fixture()
 def _app(app):

tests/test_core.py

@@ -3,6 +3,11 @@
 import pytest
 from pypiserver import core
 
+## Enable logging to detect any problems with it
+##
+import logging
+core.init_logging(level=logging.NOTSET)
+
 
 files = [
     ("pytz-2012b.tar.bz2", "pytz", "2012b"),

tests/test_main.py

@@ -1,6 +1,6 @@
 #! /usr/bin/env py.test
 
-import sys, os, pytest
+import sys, os, pytest, logging
 from pypiserver import core
 
 
@@ -84,3 +84,21 @@ def test_fallback_url_default(main):
     main([])
     assert main.app.module.config.fallback_url == \
         "http://pypi.python.org/simple"
+
+@pytest.fixture
+def logfile(tmpdir):
+    return tmpdir.mkdir("logs").join('test.log')
+
+def test_logging(main, logfile):
+    main(["-v", "--log-file", logfile.strpath])
+    assert logfile.check(), logfile
+    
+def test_logging_verbosity(main):
+    main([])
+    assert logging.getLogger().level == logging.WARN 
+    main(["-v"])
+    assert logging.getLogger().level == logging.INFO 
+    main(["-v", "-v"])
+    assert logging.getLogger().level == logging.DEBUG 
+    main(["-v", "-v", "-v"])
+    assert logging.getLogger().level == logging.NOTSET