simplethttpserver: Unify logging

slapos/recipe/simplehttpserver/simplehttpserver.py

 # -*- coding: utf-8 -*-
 from six.moves.SimpleHTTPServer import SimpleHTTPRequestHandler
 from six.moves.socketserver import TCPServer
-import ssl
-import os
+
+import cgi
+import contextlib
+import errno
 import logging
+import os
+import ssl
 import socket
-import cgi, errno
 
 from slapos.util import str2bytes
 
@@ -15,6 +18,30 @@ from . import issubpathof
 class ServerHandler(SimpleHTTPRequestHandler):
   base_path = None # set by run
   restrict_write = True # set by run
+  _additional_logs = None
+
+  @contextlib.contextmanager
+  def _log_extra(self, msg):
+    self._additional_logs = msg
+    try:
+      yield
+    finally:
+      self._additional_logs = None
+
+  def _log(self, level, msg, *args):
+    if self._additional_logs:
+      msg += self._additional_logs
+    logging.log(level, '%s - - ' + msg, self.client_address[0], *args)
+
+  def log_message(self, msg, *args):
+    self._log(logging.INFO, msg, *args)
+
+  def log_error(self, msg, *args):
+    self._log(logging.ERROR, msg, *args)
+
+  def log_request(self, *args):
+    with self._log_extra('\n' + str(self.headers)):
+      SimpleHTTPRequestHandler.log_request(self, *args)
 
   def respond(self, code=200, type='text/html'):
     self.send_response(code)
@@ -39,7 +66,6 @@ class ServerHandler(SimpleHTTPRequestHandler):
 
     request can be encoded as application/x-www-form-urlencoded or multipart/form-data
     """
-    logging.info('%s - POST: %s \n%s' % (self.client_address[0], self.path, self.headers))
     if self.restrictedWriteAccess():
       return
 
@@ -74,27 +100,28 @@ class ServerHandler(SimpleHTTPRequestHandler):
       os.makedirs(os.path.dirname(file_path))
     except OSError as exception:
       if exception.errno != errno.EEXIST:
-        logging.error('Failed to create file in %s. The error is \n%s',
-          file_path, str(exception))
+        self.log_error('Failed to create file in %s. The error is \n%s',
+          file_path, exception)
     # Write content to file
-    logging.info('Writing received content to file %s', file_path)
+    self.log_message('Writing received content to file %s', file_path)
     try:
       with open(file_path, method) as myfile:
         myfile.write(content)
-        logging.info('Done.')
+        self.log_message('Done.')
     except IOError as e:
-      logging.error('Something happened while processing \'writeFile\'. The message is %s',
-                    str(e))
+      self.log_error(
+        'Something happened while processing \'writeFile\'. The message is %s',
+        e)
     self.respond(200, type=self.headers['Content-Type'])
     self.wfile.write(b"Content written to %s" % str2bytes(filename))
 
 
 def run(args):
-
-  # minimal web server.  serves files relative to the
-  # current directory.
-  logging.basicConfig(format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
-                            filename=args['log-file'] ,level=logging.INFO)
+  # minimal web server. serves files relative to the current directory.
+  logging.basicConfig(
+      format="%(asctime)s %(levelname)s - %(message)s",
+      filename=args['log-file'],
+      level=logging.INFO)
 
   address = args['address']
   cwd = args['cwd']

slapos/test/recipe/test_simplehttpserver.py

@@ -76,6 +76,7 @@ class SimpleHTTPServerTest(unittest.TestCase):
     self.install_dir = tempfile.mkdtemp()
     self.addCleanup(shutil.rmtree, self.install_dir)
     self.wrapper = os.path.join(self.install_dir, 'server')
+    self.logfile = self.wrapper + '.log'
     self.process = None
 
   def setUpRecipe(self, opt=None):
@@ -90,7 +91,7 @@ class SimpleHTTPServerTest(unittest.TestCase):
       self.server_url = None
     options = {
         'base-path': self.base_path,
-        'log-file': os.path.join(self.install_dir, 'simplehttpserver.log'),
+        'log-file': self.logfile,
         'wrapper': self.wrapper,
     }
     options.update(opt)
@@ -108,6 +109,7 @@ class SimpleHTTPServerTest(unittest.TestCase):
         stderr=subprocess.PIPE,
         universal_newlines=True, # BBB Py2, use text= in Py3
     )
+    address = self.recipe.options['address']
     if self.server_url:
       kwargs = {'verify': False} if self.certfile else {}
       def check_connection():
@@ -116,7 +118,6 @@ class SimpleHTTPServerTest(unittest.TestCase):
       ConnectionError = requests.exceptions.ConnectionError
       cleanup = None
     else:
-      address = self.recipe.options['address']
       s = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
       def check_connection():
         s.connect(address)
@@ -134,14 +135,19 @@ class SimpleHTTPServerTest(unittest.TestCase):
         # otherwise .communicate() may hang forever.
         self.process.terminate()
         self.process.wait()
+        with open(self.logfile) as f:
+          log = f.read()
         self.fail(
           "Server did not start\n"
           "out: %s\n"
-          "err: %s"
-          % self.process.communicate())
+          "err: %s\n"
+          "log: %s"
+          % (self.process.communicate() + (log,)))
     finally:
       if cleanup:
         cleanup()
+    with open(self.logfile) as f:
+      self.assertIn("Starting simple http server at %s" % (address,), f.read())
     return self.server_url
 
   def tearDown(self):
@@ -199,14 +205,21 @@ class SimpleHTTPServerTest(unittest.TestCase):
     )
     self.assertEqual(resp.status_code, requests.codes.ok)
     self.assertEqual(resp.text, 'Content written to hello-form-data.txt')
-    with open(
-        os.path.join(self.base_path, 'hello-form-data.txt')) as f:
+    hello_form_file = os.path.join(self.base_path, 'hello-form-data.txt')
+    with open(hello_form_file) as f:
       self.assertEqual(f.read(), 'hello-form-data')
 
     self.assertIn('hello-form-data.txt', requests.get(server_base_url).text)
     self.assertEqual(
         requests.get(server_base_url + '/hello-form-data.txt').text, 'hello-form-data')
 
+    # check GET and POST are logged
+    with open(self.logfile) as f:
+      log = f.read()
+    self.assertIn('Writing received content to file ' + hello_form_file, log)
+    self.assertIn('"POST / HTTP/1.1" 200 -', log)
+    self.assertIn('"GET /hello-form-data.txt HTTP/1.1" 200 -', log)
+
     # post as application/x-www-form-urlencoded
     resp = requests.post(
         server_base_url,