kedifa: Implement logging

As Kedifa is long running process, it has to be diagnosed post-mortem.
Printing out information is not reliable in this case, so switch to log.

Logging gives:

 * controllable retention of information
 * more details
 * possibility to run quietly on system which do not catch process output

Reopening the logs after its rotation has been solved with WatchedFileHandler,

kedifa/app.py

@@ -24,6 +24,7 @@ from wsgiref.simple_server import make_server
 import caucase.exceptions
 import caucase.http
 import caucase.utils
+from caucase.http_wsgibase import CleanServerHandler
 import datetime
 import json
 import os
@@ -33,6 +34,8 @@ import sqlite3
 import ssl
 import string
 import urlparse
+import logging
+import logging.handlers
 
 
 class UserExists(Exception):
@@ -514,11 +517,57 @@ 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('kedifa')
+
+
+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 log_exception(self, exc_info):
+  try:
+    logger.exception(
+      'Exception while handling the request:', exc_info=exc_info)
+  finally:
+      exc_info = None
+
+
+CleanServerHandler.log_exception = log_exception
+
+
+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:
@@ -527,7 +576,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,
@@ -540,7 +590,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

@@ -226,6 +226,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 = findFreeTCPPort(ip)
     self.kedifa_runtime = multiprocessing.Process(
       target=cli.http,
@@ -236,7 +237,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)
@@ -256,6 +258,11 @@ class KedifaMixinCaucase(KedifaMixin):
       self.fail(
         'Kedifa not available after %.2fs seconds' % (time.time() - b))
 
+    expected = 'Kedifa started at %s with pid %s stored in %s' % (
+      self.kedifa_url, self.kedifa_runtime.pid, self.pidfile)
+    self.assertAnyLogEntry(expected)
+    self.assertLastLogEntry('"GET /ping HTTP/1.1" 401 0 "-" "python-requests')
+
   def reserveReference(self, *args, **kwargs):
     result = requests.post(
       self.kedifa_url + 'reserve-id',
@@ -301,6 +308,21 @@ class KedifaMixinCaucase(KedifaMixin):
 
 
 class KedifaIntegrationTest(KedifaMixinCaucase, unittest.TestCase):
+  def assertAnyLogEntry(self, entry):
+    with open(self.logfile) as fh:
+      log_line_list = fh.readlines()
+    for log_line in log_line_list:
+      if entry in log_line:
+        return
+    self.fail(
+      'Entry %r not found in log:\n %s' % (entry, ''.join(log_line_list)))
+
+  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 _getter_get(self, url, certificate, destination):
     cli.getter(
       url,
@@ -338,6 +360,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
@@ -350,6 +381,15 @@ class KedifaIntegrationTest(KedifaMixinCaucase, unittest.TestCase):
       'Wrong path',
       result.text
     )
+    self.assertLastLogEntry('"GET / HTTP/1.1" 400')
+    # check rotation support
+    os.rename(self.logfile, self.logfile + '.rotated')
+    result = self.requests_get(self.kedifa_url)
+    self.assertEqual(
+      httplib.BAD_REQUEST,
+      result.status_code
+    )
+    self.assertLastLogEntry('"GET / HTTP/1.1" 400')
 
   def test_GET_not_existing(self):
     result = self.requests_get(
@@ -362,6 +402,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()
@@ -375,6 +416,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()
@@ -852,6 +894,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()