edifa: Implement logging

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

@@ -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):
@@ -510,11 +513,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(__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 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:
@@ -523,7 +572,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 +586,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,13 @@ 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])
+    self.assertLastLogEntry('"GET /ping HTTP/1.1" 401 0 "-" "python-requests')
+
   def reserveReference(self, *args, **kwargs):
     result = requests.post(
       self.kedifa_url + 'reserve-id',
@@ -323,6 +332,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 +353,24 @@ class KedifaIntegrationTest(KedifaMixinCaucase, unittest.TestCase):
       'A server error occurred.  Please contact the administrator.',
       result.text
     )
+    self.assertLastLogEntry('"GET / HTTP/1.1" 500')
+    self.assertAnyLogEntry('Exception while handling the request:')
+    self.assertAnyLogEntry('ValueError')
+
+  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 test_GET_not_existing(self):
     result = self.requests_get(
@@ -347,6 +383,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 +397,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 +875,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()