XXX kedifa: Implement logging

XXX: Missing errors from wsgiref in the log

Logging is better than just printing out things, as times are added and also
they are much better rotated, with controlled retention.

kedifa/app.py

@@ -33,6 +33,8 @@ import sqlite3
 import ssl
 import string
 import urlparse
+import logging
+import logging.handlers
 
 
 class UserExists(Exception):
@@ -510,11 +512,46 @@ class Reloader(object):
       # what is actually used when accepting a connection - so the update
       # is actually successful.
       pass
-    print 'KeDiFa reloaded.'
+    logger.warning('KeDiFa reloaded.')
 
 
-def http(host, port, pocket, certificate, ca_certificate, crl, pidfile):
-  pidfile.write(str(os.getpid()))
+logger = logging.getLogger(__name__)
+
+
+def setuplog(logfile):
+  if logfile == '-':
+    ch = logging.StreamHandler()
+  else:
+    ch = logging.handlers.WatchedFileHandler(logfile)
+  formatter = logging.Formatter(
+    '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+  ch.setFormatter(formatter)
+  logger.addHandler(ch)
+  logger.setLevel(logging.INFO)
+
+
+class KedifaSSLWSGIRequestHandler(caucase.http.CaucaseSSLWSGIRequestHandler):
+  def log_message(self, format, *args):
+    """
+    Log an arbitrary message.
+
+    Compared to caucase.http.CaucaseSSLWSGIRequestHandler:
+    - use logger
+    """
+    logger.info(
+      '%s - %s [%s] %s',
+      self.client_address[0],
+      self.remote_user_name,
+      self.log_date_time_string(),
+      format % args,
+    )
+
+
+def http(host, port, pocket, certificate, ca_certificate, crl, pidfile,
+         logfile):
+  setuplog(logfile)
+  pid = str(os.getpid())
+  pidfile.write(pid)
   pidfile.close()
   kedifa = Kedifa(pocket, ca_certificate, crl)
   if ':' in host:
@@ -523,7 +560,8 @@ def http(host, port, pocket, certificate, ca_certificate, crl, pidfile):
     access_format = 'https://%s:%s/'
   httpd = make_server(
     host, port, kedifa, caucase.http.ThreadingWSGIServer,
-    caucase.http.CaucaseSSLWSGIRequestHandler)
+    KedifaSSLWSGIRequestHandler
+  )
   ssl_context = getSSLContext(certificate.name, ca_certificate.name, crl.name)
   httpd.socket = ssl_context.wrap_socket(
      httpd.socket,
@@ -536,7 +574,9 @@ def http(host, port, pocket, certificate, ca_certificate, crl, pidfile):
     httpd.server_close()
     raise
 
-  print 'Kedifa started at', access_format % httpd.server_address[:2]
+  logger.info(
+   'Kedifa started at %s with pid %s stored in %s',
+   access_format % httpd.server_address[:2], pid, pidfile.name)
 
   reloader = Reloader(
     httpd, kedifa, certificate.name, ca_certificate.name, crl.name)

kedifa/cli.py

@@ -71,10 +71,16 @@ def http(*args):
     help='Path to PID file.',
     required=True
   )
+  parser.add_argument(
+    '--logfile',
+    type=str,
+    help='Path to logfile.',
+    default='-'
+  )
   parsed = parser.parse_args(args)
 
   app.http(parsed.ip, parsed.port, parsed.db, parsed.certificate,
-           parsed.ca_certificate, parsed.crl, parsed.pidfile)
+           parsed.ca_certificate, parsed.crl, parsed.pidfile, parsed.logfile)
 
 
 def getter(*args):

kedifa/test.py

@@ -213,6 +213,7 @@ class KedifaMixinCaucase(KedifaMixin):
   def setUpKedifa(self, ip):
     self.db = os.path.join(self.testdir, 'pocket.sqlite')
     self.pidfile = os.path.join(self.testdir, 'kedifa.pid')
+    self.logfile = os.path.join(self.testdir, 'kedifa.log')
     port = '16080'
     self.kedifa_runtime = multiprocessing.Process(
       target=cli.http,
@@ -223,7 +224,8 @@ class KedifaMixinCaucase(KedifaMixin):
         '--certificate', self.kedifa_key_pem,
         '--ca-certificate', self.ca_crt_pem,
         '--crl', self.crl,
-        '--pidfile', self.pidfile)
+        '--pidfile', self.pidfile,
+        '--logfile', self.logfile)
     )
     self.kedifa_url = 'https://[%s]:%s/' % (ip, port)
     self.addCleanup(self.kedifa_runtime.terminate)
@@ -241,6 +243,14 @@ class KedifaMixinCaucase(KedifaMixin):
     else:
       raise
 
+    with open(self.logfile) as fh:
+      log_line_list = fh.readlines()
+    expected = 'Kedifa started at %s with pid %s stored in %s' % (
+      self.kedifa_url, self.kedifa_runtime.pid, self.pidfile)
+    self.assertTrue(expected in log_line_list[0])
+    expected = '"GET /ping HTTP/1.1" 401 0 "-" "python-requests'
+    self.assertTrue(expected in log_line_list[-1])
+
   def reserveReference(self, *args, **kwargs):
     result = requests.post(
       self.kedifa_url + 'reserve-id',
@@ -323,6 +333,15 @@ class KedifaIntegrationTest(KedifaMixinCaucase, unittest.TestCase):
     self._updater_get(url, certificate, destination)
     return destination
 
+  def test_reload_log(self):
+    with open(self.pidfile) as pidfile:
+      os.kill(int(pidfile.read()), signal.SIGHUP)
+
+    # give some time for KeDiFa to react
+    time.sleep(1)
+
+    self.assertLastLogEntry('WARNING - KeDiFa reloaded.')
+
   def test_GET_root(self):
     result = self.requests_get(self.kedifa_url)
     # KeDiFa does not support nothing on / so for now it just raises
@@ -335,6 +354,13 @@ class KedifaIntegrationTest(KedifaMixinCaucase, unittest.TestCase):
       'A server error occurred.  Please contact the administrator.',
       result.text
     )
+    self.assertLastLogEntry('"GET / HTTP/1.1" 500')
+
+  def assertLastLogEntry(self, entry):
+    with open(self.logfile) as fh:
+      last_log_line = fh.readlines()[-1]
+    self.assertTrue(
+      entry in last_log_line, '%r not found in %r' % (entry, last_log_line))
 
   def test_GET_not_existing(self):
     result = self.requests_get(
@@ -347,6 +373,7 @@ class KedifaIntegrationTest(KedifaMixinCaucase, unittest.TestCase):
       '',
       result.text
     )
+    self.assertLastLogEntry('"GET /%s HTTP/1.1" 404' % (self.reference,))
 
   def test_GET_existing(self):
     self.put()
@@ -360,6 +387,7 @@ class KedifaIntegrationTest(KedifaMixinCaucase, unittest.TestCase):
       self.pem,
       result.text
     )
+    self.assertLastLogEntry('"GET /%s HTTP/1.1" 200' % (self.reference,))
 
   def test_GET_unsigned_identity(self):
     self.put()
@@ -837,6 +865,7 @@ class KedifaIntegrationTest(KedifaMixinCaucase, unittest.TestCase):
       result.headers.get('Location', ''),
       r'^/%s/\d+$' % key
     )
+    self.assertLastLogEntry('"PUT /%s?auth=%s HTTP/1.1" 201' % (key, auth))
 
   def test_PUT(self):
     self.put()