Merge pull request #4844 from minrk/tornado-logs

adjustments to notebook app logging

Mainly add a log_request function (from nbviewer) for formatting tornado access logs.

Relevant effects:

demote successful access logs to DEBUG
demote kernel connect messages to DEBUG
which reduces the noise at INFO-level (default)

IPython/html/log.py

@@ -0,0 +1,52 b''
+#-----------------------------------------------------------------------------
+#  Copyright (C) 2013 The IPython Development Team
+#
+#  Distributed under the terms of the BSD License.  The full license is in
+#  the file COPYING, distributed as part of this software.
+#-----------------------------------------------------------------------------
+
+import json
+from tornado.log import access_log
+
+def log_request(handler):
+    """log a bit more information about each request than tornado's default
+    
+    - move static file get success to debug-level (reduces noise)
+    - get proxied IP instead of proxy IP
+    - log referer for redirect and failed requests
+    - log user-agent for failed requests
+    """
+    status = handler.get_status()
+    request = handler.request
+    if status < 300 or status == 304:
+        # Successes (or 304 FOUND) are debug-level
+        log_method = access_log.debug
+    elif status < 400:
+        log_method = access_log.info
+    elif status < 500:
+        log_method = access_log.warning
+    else:
+        log_method = access_log.error
+    
+    request_time = 1000.0 * handler.request.request_time()
+    ns = dict(
+        status=status,
+        method=request.method,
+        ip=request.remote_ip,
+        uri=request.uri,
+        request_time=request_time,
+    )
+    msg = "{status} {method} {uri} ({ip}) {request_time:.2f}ms"
+    if status >= 300:
+        # log referers on redirects
+        ns['referer'] = request.headers.get('Referer', 'None')
+        msg = msg + ' referer={referer}'
+    if status >= 400:
+        # log user agent for failed requests
+        ns['agent'] = request.headers.get('User-Agent', 'Unknown')
+        msg = msg + ' user-agent={agent}'
+    if status >= 500 and status != 502:
+        # log all headers if it caused an error
+        log_method(json.dumps(request.headers, indent=2))
+    log_method(msg.format(**ns))
+

IPython/consoleapp.py

@@ -210,7 +210,7 b' class IPythonConsoleApp(ConnectionFileMixin):'
             except Exception:
                 self.log.critical("Could not find existing kernel connection file %s", self.existing)
                 self.exit(1)
-            self.log.info("Connecting to existing kernel: %s" % cf)
+            self.log.debug("Connecting to existing kernel: %s" % cf)
             self.connection_file = cf
         else:
             # not existing, check if we are going to write the file
@@ -303,8 +303,8 b' class IPythonConsoleApp(ConnectionFileMixin):'
         base,ext = os.path.splitext(cf)
         base = os.path.basename(base)
         self.connection_file = os.path.basename(base)+'-ssh'+ext
-        self.log.critical("To connect another client via this tunnel, use:")
-        self.log.critical("--existing %s" % self.connection_file)
+        self.log.info("To connect another client via this tunnel, use:")
+        self.log.info("--existing %s" % self.connection_file)
     
     def _new_connection_file(self):
         cf = ''

IPython/html/notebookapp.py

@@ -64,7 +64,7 b' from tornado import web'
 # Our own libraries
 from IPython.html import DEFAULT_STATIC_FILES_PATH
 from .base.handlers import Template404
-
+from .log import log_request
 from .services.kernels.kernelmanager import MappingKernelManager
 from .services.notebooks.nbmanager import NotebookManager
 from .services.notebooks.filenbmanager import FileNotebookManager
@@ -158,6 +158,7 b' class NotebookWebApplication(web.Application):'
         template_path = settings_overrides.get("template_path", os.path.join(os.path.dirname(__file__), "templates"))
         settings = dict(
             # basics
+            log_function=log_request,
             base_project_url=base_project_url,
             base_kernel_url=ipython_app.base_kernel_url,
             template_path=template_path,

IPython/kernel/connect.py

@@ -519,7 +519,7 b' class ConnectionFileMixin(Configurable):'
         """Create a zmq Socket and connect it to the kernel."""
         url = self._make_url(channel)
         socket_type = channel_socket_types[channel]
-        self.log.info("Connecting to: %s" % url)
+        self.log.debug("Connecting to: %s" % url)
         sock = self.context.socket(socket_type)
         if identity:
             sock.identity = identity