all: Rework logging.

Make tests almost completely silent by default, while still printing output
generated during corresponding test on failure.
Produce more somewhat-apache-like error logs, both from httpd and wsgi
errors.

caucase/cli.py

@@ -48,6 +48,7 @@ class RetryingCaucaseClient(CaucaseClient):
   Retries every 10 seconds.
   """
   _until = staticmethod(utils.until)
+  _log_file = sys.stdout
 
   def _request(self, connection, method, url, body=None, headers=None):
     while True:
@@ -73,10 +74,13 @@ class RetryingCaucaseClient(CaucaseClient):
         connection.close() # Resets HTTPConnection state machine.
         # Note: repr(str(exception)) is nicer than repr(exception), without
         # letting non-printable characters through.
-        print('Got a network error, retrying in a bit: %s: %r' % (
-          exception.__class__.__name__,
-          str(exception),
-        ))
+        print(
+          'Got a network error, retrying in a bit: %s: %r' % (
+            exception.__class__.__name__,
+            str(exception),
+          ),
+          file=self._log_file,
+        )
         self._until(datetime.datetime.now() + datetime.timedelta(0, 10))
 
 _cryptography_backend = default_backend()

caucase/http.py

@@ -23,6 +23,7 @@ import argparse
 from collections import defaultdict
 import datetime
 import errno
+from functools import partial
 from getpass import getpass
 import glob
 import itertools
@@ -81,6 +82,7 @@ class ThreadingWSGIServer(ThreadingMixIn, WSGIServer):
   daemon_threads = True
 
   def __init__(self, server_address, *args, **kw):
+    self._error_file = kw.pop('error_file', sys.stderr)
     self.address_family, _, _, _, _ = socket.getaddrinfo(*server_address)[0]
     WSGIServer.__init__(
       self,
@@ -96,6 +98,16 @@ class ThreadingWSGIServer(ThreadingMixIn, WSGIServer):
       self.socket.setsockopt(socket.IPPROTO_IPV6, socket.IPV6_V6ONLY, 1)
     WSGIServer.server_bind(self)
 
+  def handle_error(self, request, client_address):
+    """
+    Handle an error gracefully.
+    """
+    utils.log_exception(
+      error_file=self._error_file,
+      exc_info=sys.exc_info(),
+      client_address=client_address[0],
+    )
+
   # pylint: disable=arguments-differ
   def serve_forever(self, *args, **kw):
     """
@@ -106,7 +118,7 @@ class ThreadingWSGIServer(ThreadingMixIn, WSGIServer):
     """
     try:
       return WSGIServer.serve_forever(self, *args, **kw)
-    except socket.error as exception:
+    except socket.error as exception: # pragma: no cover
       # Workaround for the following unhandled error:
       # Traceback (most recent call last):
       #   File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
@@ -151,9 +163,16 @@ del _buildQuoteCharList
 
 class CaucaseWSGIRequestHandler(WSGIRequestHandler):
   """
-  Make WSGIRequestHandler logging more apache-like.
+  Make WSGIRequestHandler logging more apache-like and allow choosing a file
+  other than stderr for log output.
   """
   server_version = 'caucased ' + version.__version__
+  remote_user_name = '-'
+
+  def __init__(self, *args, **kw):
+    self._log_file = kw.pop('log_file', sys.stdout)
+    self._error_file = kw.pop('error_file', sys.stderr)
+    WSGIRequestHandler.__init__(self, *args, **kw)
 
   def log_date_time_string(self):
     """
@@ -189,13 +208,40 @@ class CaucaseWSGIRequestHandler(WSGIRequestHandler):
       ''.join(_QUOTE_LOG_LIST[ord(x)] for x in headers.get('User-Agent', '-')),
     )
 
+  # pylint: disable=redefined-builtin
+  def log_message(self, format, *args):
+    """
+    Log an arbitrary message.
+
+    Compared to python's default (from BaseHTTPServer):
+    - make remote user name customisable (used in CaucaseSSLWSGIRequestHandler)
+    - make output stream customisable
+    - use print instead of plain .write(), for encoding purposes
+    """
+    print(
+      '%s - %s [%s] %s' % (
+        self.client_address[0],
+        self.remote_user_name,
+        self.log_date_time_string(),
+        format % args,
+      ),
+      file=self._log_file,
+    )
+  # pylint: enable=redefined-builtin
+
+  def get_stderr(self):
+    """
+    Send wsgi.errors to error output.
+    """
+    return self._error_file
+
 class CaucaseSSLWSGIRequestHandler(CaucaseWSGIRequestHandler):
   """
   Add SSL-specific entries to environ:
   - HTTPS=on
   - SSL_CLIENT_CERT when client has sent a certificate.
+  - use certificate serial as user name
   """
-  ssl_client_cert_serial = '-'
   def get_environ(self):
     """
     Populate environment.
@@ -208,25 +254,10 @@ class CaucaseSSLWSGIRequestHandler(CaucaseWSGIRequestHandler):
         client_cert_der,
         _cryptography_backend,
       )
-      self.ssl_client_cert_serial = str(cert.serial_number)
+      self.remote_user_name = str(cert.serial_number)
       environ['SSL_CLIENT_CERT'] = utils.dump_certificate(cert)
     return environ
 
-  # pylint: disable=redefined-builtin
-  def log_message(self, format, *args):
-    # Note: compared to BaseHTTPHandler, logs the client certificate serial as
-    # user name.
-    print(
-      '%s - %s [%s] %s' % (
-        self.client_address[0],
-        self.ssl_client_cert_serial,
-        self.log_date_time_string(),
-        format % args,
-      ),
-      file=sys.stderr,
-    )
-  # pylint: enable=redefined-builtin
-
 def startServerThread(server):
   """
   Create and start a "serve_forever" thread.
@@ -374,7 +405,12 @@ def getSSLContext(
     ).not_valid_after - threshold_delta,
   )
 
-def main(argv=None, until=utils.until):
+def main(
+  argv=None,
+  until=utils.until,
+  log_file=sys.stdout,
+  error_file=sys.stderr,
+):
   """
   Caucase stand-alone http server.
   """
@@ -705,15 +741,22 @@ def main(argv=None, until=utils.until):
           http_port,
           https_port,
         ),
-        file=sys.stderr,
+        file=error_file,
       )
       http_list.append(
         make_server(
           host=host,
           port=http_port,
           app=application,
-          server_class=ThreadingWSGIServer,
-          handler_class=CaucaseWSGIRequestHandler,
+          server_class=partial(
+            ThreadingWSGIServer,
+            error_file=error_file,
+          ),
+          handler_class=partial(
+            CaucaseWSGIRequestHandler,
+            log_file=log_file,
+            error_file=error_file,
+          ),
         ),
       )
       https_list.append(
@@ -721,8 +764,15 @@ def main(argv=None, until=utils.until):
           host=host,
           port=https_port,
           app=application,
-          server_class=ThreadingWSGIServer,
-          handler_class=CaucaseSSLWSGIRequestHandler,
+          server_class=partial(
+            ThreadingWSGIServer,
+            error_file=error_file,
+          ),
+          handler_class=partial(
+            CaucaseSSLWSGIRequestHandler,
+            log_file=log_file,
+            error_file=error_file,
+          ),
         ),
       )
   ssl_context, next_ssl_update = getSSLContext(
@@ -818,7 +868,7 @@ def main(argv=None, until=utils.until):
   except utils.SleepInterrupt:
     pass
   finally:
-    print('Exiting', file=sys.stderr)
+    print('Exiting', file=error_file)
     for server in itertools.chain(http_list, https_list):
       server.server_close()
       server.shutdown()

caucase/test.py

@@ -25,6 +25,7 @@ from __future__ import absolute_import
 from Cookie import SimpleCookie
 import datetime
 import errno
+import functools
 import glob
 import HTMLParser
 import httplib
@@ -273,6 +274,24 @@ class UntilEvent(object):
         raise utils.SleepInterrupt
     return now
 
+def print_buffer_on_error(func):
+  """
+  Write output buffer to stdout when wrapped method raises.
+  func is expected to be a method from CaucaseTest class.
+  """
+  @functools.wraps(func)
+  def wrapper(self, *args, **kw):
+    """
+    Write output buffer to stdout when wrapped method raises.
+    """
+    try:
+      return func(self, *args, **kw)
+    except Exception:
+      sys.stdout.write(utils.toBytes(os.linesep))
+      sys.stdout.write(self.caucase_test_output.getvalue())
+      raise
+  return wrapper
+
 class CaucaseTest(unittest.TestCase):
   """
   Test a complete caucase setup: spawn a caucase-http server on CAUCASE_NETLOC
@@ -305,6 +324,7 @@ class CaucaseTest(unittest.TestCase):
     self._server_backup_path = os.path.join(server_dir, 'backup')
     self._server_cors_store  = os.path.join(server_dir, 'cors.key')
     # pylint: enable=bad-whitespace
+    self.caucase_test_output = BytesIO()
     os.mkdir(self._server_backup_path)
 
     self._server_netloc = netloc = os.getenv(
@@ -320,6 +340,7 @@ class CaucaseTest(unittest.TestCase):
     )
     self._startServer()
 
+  @print_buffer_on_error
   def tearDown(self):
     """
     Stop any running caucased and delete all test data files.
@@ -479,7 +500,7 @@ class CaucaseTest(unittest.TestCase):
         crl=None,
       )
       # pylint: enable=protected-access
-    except CertificateVerificationError:
+    except CertificateVerificationError: # pragma: no cover
       raise unittest.SkipTest('OpenSSL versoin does not support IP constraints')
 
   def _restoreServer(
@@ -527,6 +548,8 @@ class CaucaseTest(unittest.TestCase):
           '--cors-key-store', self._server_cors_store,
         ) + argv,
         'until': until,
+        'log_file': self.caucase_test_output,
+        'error_file': self.caucase_test_output,
       }
     )
     server.daemon = True
@@ -1603,7 +1626,7 @@ class CaucaseTest(unittest.TestCase):
       """
       Non-standard shorthand for invoking the WSGI application.
       """
-      environ.setdefault('wsgi.errors', sys.stderr)
+      environ.setdefault('wsgi.errors', self.caucase_test_output)
       environ.setdefault('wsgi.url_scheme', 'http')
       environ.setdefault('SERVER_NAME', server_name)
       environ.setdefault('SERVER_PORT', str(server_http_port))
@@ -2410,6 +2433,8 @@ class CaucaseTest(unittest.TestCase):
         ),
         ('0.0.0.0', 0),
         FakeAppServer(app),
+        log_file=self.caucase_test_output,
+        error_file=self.caucase_test_output,
       )
       return wfile.getvalue().splitlines()
 
@@ -2588,8 +2613,9 @@ class CaucaseTest(unittest.TestCase):
     until_network_issue = UntilEvent(network_issue_event)
     # pylint: disable=protected-access
     cli.RetryingCaucaseClient._until = until_network_issue
-    until_network_issue.action = ON_EVENT_EXPIRE
+    cli.RetryingCaucaseClient._log_file = self.caucase_test_output
     # pylint: enable=protected-access
+    until_network_issue.action = ON_EVENT_EXPIRE
     original_HTTPConnection = cli.RetryingCaucaseClient.HTTPConnection
     class ErrorInjector(object):
       """
@@ -2781,8 +2807,12 @@ class CaucaseTest(unittest.TestCase):
     self.assertEqual(os.stat(self._server_db).st_mode & 0o777, 0o600)
     self.assertEqual(os.stat(self._server_key).st_mode & 0o777, 0o600)
 
+for property_id, property_value in CaucaseTest.__dict__.iteritems():
+  if property_id.startswith('test') and callable(property_value):
+    setattr(CaucaseTest, property_id, print_buffer_on_error(property_value))
+
 # pylint: disable=no-member
-if getattr(CaucaseTest, 'assertItemsEqual', None) is None:
+if getattr(CaucaseTest, 'assertItemsEqual', None) is None: # pragma: no cover
   # Because python3 decided it should be named differently, and 2to3 cannot
   # pick it up, and this code must remain python2-compatible... Yay !
   CaucaseTest.assertItemsEqual = CaucaseTest.assertCountEqual

caucase/utils.py

@@ -20,12 +20,14 @@ Caucase - Certificate Authority for Users, Certificate Authority for SErvices
 
 Small-ish functions needed in many places.
 """
-from __future__ import absolute_import
+from __future__ import absolute_import, print_function
 from binascii import a2b_base64, b2a_base64
 from collections import defaultdict
 import datetime
 import json
 import os
+import threading
+import traceback
 import time
 from cryptography import x509
 from cryptography.hazmat.backends import default_backend
@@ -477,3 +479,29 @@ def until(deadline): # pragma: no cover
     interruptibleSleep((deadline - now).total_seconds())
     now = datetime.datetime.utcnow()
   return now
+
+def log_exception(error_file, exc_info, client_address):
+  """
+  Log an unhandled exception to error_file, using a somewhat apache-inspired
+  format.
+  """
+  try:
+    print(
+      '[%s] [pid %s:tid %s] [client %s] %s %s%s' % (
+        datetime.datetime.utcnow().isoformat(),
+        os.getpid(),
+        threading.current_thread().ident,
+        client_address,
+        exc_info[1],
+        os.linesep,
+        ''.join(traceback.format_exception(
+          exc_info[0],
+          exc_info[1],
+          exc_info[2],
+        )),
+      ),
+      end='', # format_exc has its own linesep
+      file=error_file,
+    )
+  finally:
+    exc_info = None

caucase/wsgi.py

@@ -26,7 +26,6 @@ import os
 import sys
 import threading
 import time
-import traceback
 from urllib import quote, urlencode
 from urlparse import parse_qs
 from wsgiref.util import application_uri, request_uri
@@ -580,8 +579,11 @@ class Application(object):
       except exceptions.CertificateAuthorityException as e:
         raise BadRequest(str(e))
       except Exception:
-        environ['wsgi.errors'].write('Unhandled exception\n')
-        traceback.print_exc(file=environ['wsgi.errors'])
+        utils.log_exception(
+          error_file=environ['wsgi.errors'],
+          exc_info=sys.exc_info(),
+          client_address=environ.get('REMOTE_ADDR', ''),
+        )
         raise ApplicationError
     except ApplicationError as e:
       status = e.status