Merge pull request #1153 from minrk/log-debug

demote logs of health/liveness checks to debug-level

Author: betatim

binderhub/app.py

@@ -30,6 +30,7 @@
 from .builder import BuildHandler
 from .health import HealthHandler
 from .launcher import Launcher
+from .log import log_request
 from .registry import DockerRegistry
 from .main import MainHandler, ParameterizedMainHandler, LegacyRedirectHandler
 from .repoproviders import (GitHubRepoProvider, GitRepoProvider,
@@ -586,44 +587,47 @@ def initialize(self, *args, **kwargs):
             with open(schema_file) as f:
                 self.event_log.register_schema(json.load(f))
 
-        self.tornado_settings.update({
-            "push_secret": self.push_secret,
-            "image_prefix": self.image_prefix,
-            "debug": self.debug,
-            'launcher': self.launcher,
-            'appendix': self.appendix,
-            "build_namespace": self.build_namespace,
-            "build_image": self.build_image,
-            'build_node_selector': self.build_node_selector,
-            'build_pool': self.build_pool,
-            "sticky_builds": self.sticky_builds,
-            'log_tail_lines': self.log_tail_lines,
-            'pod_quota': self.pod_quota,
-            'per_repo_quota': self.per_repo_quota,
-            'per_repo_quota_higher': self.per_repo_quota_higher,
-            'repo_providers': self.repo_providers,
-            'use_registry': self.use_registry,
-            'registry': registry,
-            'traitlets_config': self.config,
-            'google_analytics_code': self.google_analytics_code,
-            'google_analytics_domain': self.google_analytics_domain,
-            'about_message': self.about_message,
-            'banner_message': self.banner_message,
-            'extra_footer_scripts': self.extra_footer_scripts,
-            'jinja2_env': jinja_env,
-            'build_memory_limit': self.build_memory_limit,
-            'build_memory_request': self.build_memory_request,
-            'build_docker_host': self.build_docker_host,
-            'base_url': self.base_url,
-            'badge_base_url': self.badge_base_url,
-            "static_path": os.path.join(HERE, "static"),
-            'static_url_prefix': url_path_join(self.base_url, 'static/'),
-            'template_variables': self.template_variables,
-            'executor': self.executor,
-            'auth_enabled': self.auth_enabled,
-            'event_log': self.event_log,
-            'normalized_origin': self.normalized_origin
-        })
+        self.tornado_settings.update(
+            {
+                "log_function": log_request,
+                "push_secret": self.push_secret,
+                "image_prefix": self.image_prefix,
+                "debug": self.debug,
+                "launcher": self.launcher,
+                "appendix": self.appendix,
+                "build_namespace": self.build_namespace,
+                "build_image": self.build_image,
+                "build_node_selector": self.build_node_selector,
+                "build_pool": self.build_pool,
+                "sticky_builds": self.sticky_builds,
+                "log_tail_lines": self.log_tail_lines,
+                "pod_quota": self.pod_quota,
+                "per_repo_quota": self.per_repo_quota,
+                "per_repo_quota_higher": self.per_repo_quota_higher,
+                "repo_providers": self.repo_providers,
+                "use_registry": self.use_registry,
+                "registry": registry,
+                "traitlets_config": self.config,
+                "google_analytics_code": self.google_analytics_code,
+                "google_analytics_domain": self.google_analytics_domain,
+                "about_message": self.about_message,
+                "banner_message": self.banner_message,
+                "extra_footer_scripts": self.extra_footer_scripts,
+                "jinja2_env": jinja_env,
+                "build_memory_limit": self.build_memory_limit,
+                "build_memory_request": self.build_memory_request,
+                "build_docker_host": self.build_docker_host,
+                "base_url": self.base_url,
+                "badge_base_url": self.badge_base_url,
+                "static_path": os.path.join(HERE, "static"),
+                "static_url_prefix": url_path_join(self.base_url, "static/"),
+                "template_variables": self.template_variables,
+                "executor": self.executor,
+                "auth_enabled": self.auth_enabled,
+                "event_log": self.event_log,
+                "normalized_origin": self.normalized_origin,
+            }
+        )
         if self.auth_enabled:
             self.tornado_settings['cookie_secret'] = os.urandom(32)
 

binderhub/base.py

@@ -118,6 +118,10 @@ async def get(self):
 
 class VersionHandler(BaseHandler):
     """Serve information about versions running"""
+
+    # demote logging of 200 responses to debug-level
+    log_success_debug = True
+
     async def get(self):
         self.set_header("Content-type", "application/json")
         self.write(json.dumps(

binderhub/health.py

@@ -82,6 +82,10 @@ async def wrapper(*args, **kwargs):
 class HealthHandler(BaseHandler):
     """Serve health status"""
 
+    # demote logging of 200 responses to debug-level
+    # to avoid flooding logs with health checks
+    log_success_debug = True
+
     def initialize(self, hub_url=None):
         self.hub_url = hub_url
 

binderhub/log.py

@@ -0,0 +1,135 @@
+"""logging utilities"""
+
+# copied from jupyterhub 1.1.0
+# Copyright (c) Jupyter Development Team.
+# Distributed under the terms of the Modified BSD License.
+
+import json
+import traceback
+from http.cookies import SimpleCookie
+from urllib.parse import urlparse
+from urllib.parse import urlunparse
+
+from tornado.log import access_log
+from tornado.log import LogFormatter
+from tornado.web import HTTPError
+from tornado.web import StaticFileHandler
+
+
+# url params to be scrubbed if seen
+# any url param that *contains* one of these
+# will be scrubbed from logs
+SCRUB_PARAM_KEYS = ("token", "auth", "key", "code", "state")
+
+
+def _scrub_uri(uri):
+    """scrub auth info from uri"""
+    parsed = urlparse(uri)
+    if parsed.query:
+        # check for potentially sensitive url params
+        # use manual list + split rather than parsing
+        # to minimally perturb original
+        parts = parsed.query.split("&")
+        changed = False
+        for i, s in enumerate(parts):
+            if "=" in s:
+                key, value = s.split("=", 1)
+                for substring in SCRUB_PARAM_KEYS:
+                    if substring in key:
+                        parts[i] = key + "=[secret]"
+                        changed = True
+        if changed:
+            parsed = parsed._replace(query="&".join(parts))
+            return urlunparse(parsed)
+    return uri
+
+
+def _scrub_headers(headers):
+    """scrub auth info from headers"""
+    headers = dict(headers)
+    if "Authorization" in headers:
+        auth = headers["Authorization"]
+        if " " in auth:
+            auth_type = auth.split(" ", 1)[0]
+        else:
+            # no space, hide the whole thing in case there was a mistake
+            auth_type = ""
+        headers["Authorization"] = "{} [secret]".format(auth_type)
+    if "Cookie" in headers:
+        c = SimpleCookie(headers["Cookie"])
+        redacted = []
+        for name in c.keys():
+            redacted.append("{}=[secret]".format(name))
+        headers["Cookie"] = "; ".join(redacted)
+    return headers
+
+
+# log_request adapted from IPython (BSD)
+
+
+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
+    - record per-request metrics in prometheus
+    """
+    status = handler.get_status()
+    request = handler.request
+    if status == 304 or (
+        status < 300
+        and (
+            isinstance(handler, StaticFileHandler)
+            or getattr(handler, "log_success_debug", False)
+        )
+    ):
+        # static-file success and 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
+
+    uri = _scrub_uri(request.uri)
+    headers = _scrub_headers(request.headers)
+
+    request_time = 1000.0 * handler.request.request_time()
+
+    try:
+        user = handler.current_user
+    except (HTTPError, RuntimeError):
+        username = ""
+    else:
+        if user is None:
+            username = ""
+        elif isinstance(user, str):
+            username = user
+        elif isinstance(user, dict):
+            username = user.get("name", "unknown")
+        else:
+            username = "unknown"
+
+    ns = dict(
+        status=status,
+        method=request.method,
+        ip=request.remote_ip,
+        uri=uri,
+        request_time=request_time,
+        user=username,
+        location="",
+    )
+    msg = "{status} {method} {uri}{location} ({user}@{ip}) {request_time:.2f}ms"
+    if status >= 500 and status not in {502, 503}:
+        log_method(json.dumps(headers, indent=2))
+    elif status in {301, 302}:
+        # log redirect targets
+        # FIXME: _headers is private, but there doesn't appear to be a public way
+        # to get headers from tornado
+        location = handler._headers.get("Location")
+        if location:
+            ns["location"] = " -> {}".format(_scrub_uri(location))
+    log_method(msg.format(**ns))

binderhub/metrics.py

@@ -3,6 +3,9 @@
 
 
 class MetricsHandler(BaseHandler):
+    # demote logging of 200 responses to debug-level
+    log_success_debug = True
+
     async def get(self):
         self.set_header("Content-Type", CONTENT_TYPE_LATEST)
         self.write(generate_latest(REGISTRY))

helm-chart/binderhub/templates/deployment.yaml

@@ -117,7 +117,7 @@ spec:
             name: binder
         livenessProbe:
           httpGet:
-            path: {{ default "/" .Values.config.BinderHub.base_url }}about
+            path: {{ default "/" .Values.config.BinderHub.base_url }}versions
             port: binder
           initialDelaySeconds: 10
           periodSeconds: 5