# Licensed to Cloudera, Inc. under one # or more contributor license agreements. See the NOTICE file # distributed with this work for additional information # regarding copyright ownership. Cloudera, Inc. licenses this file # to you under the Apache License, Version 2.0 (the # "License"); you may not use this file except in compliance # with the License. You may obtain a copy of the License at # # http://www.apache.org/licenses/LICENSE-2.0 # # Unless required by applicable law or agreed to in writing, software # distributed under the License is distributed on an "AS IS" BASIS, # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. diff --git a/desktop/core/src/desktop/conf.py b/desktop/core/src/desktop/conf.py index 152291f402..0bcaa70e04 100644 --- a/desktop/core/src/desktop/conf.py +++ b/desktop/core/src/desktop/conf.py @@ -373,6 +373,18 @@ COLLECT_USAGE = Config( type=coerce_bool, default=True) +REST_RESPONSE_SIZE = Config( + key="rest_response_size", + help=_("Number of characters the rest api reponse calls to dump to the logs when debug is enabled."), + type=int, + default=1000) + +THRIFT_RESPONSE_SIZE = Config( + key="thrift_response_size", + help=_("Number of characters the thrift api reponse calls to dump to the logs when debug is enabled."), + type=int, + default=1000) + LEAFLET_TILE_LAYER = Config( key="leaflet_tile_layer", help=_("Tile layer server URL for the Leaflet map charts. Read more on http://leafletjs.com/reference.html#tilelayer. Make sure you add the tile domain to the img-src section of the 'secure_content_security_policy' configuration parameter as well."), @@ -1279,6 +1291,17 @@ MEMORY_PROFILER = Config( default=False) +def get_instrumentation_default(): + """If django_debug_mode is True, this is automatically enabled""" + return DJANGO_DEBUG_MODE.get() + +INSTRUMENTATION = Config( + key='instrumentation', + help=_('Enable or disable instrumentation. If django_debug_mode is True, this is automatically enabled.'), + type=coerce_bool, + dynamic_default=get_instrumentation_default) + + AUDIT_EVENT_LOG_DIR = Config( key="audit_event_log_dir", help=_("The directory where to store the auditing logs. Auditing is disable if the value is empty."), diff --git a/desktop/core/src/desktop/lib/rest/resource.py b/desktop/core/src/desktop/lib/rest/resource.py index 15200940d7..bf8fd88d44 100644 --- a/desktop/core/src/desktop/lib/rest/resource.py +++ b/desktop/core/src/desktop/lib/rest/resource.py @@ -16,9 +16,15 @@ import logging import posixpath +import time + +from django.utils.encoding import iri_to_uri, smart_str +from django.utils.http import urlencode from desktop.lib.i18n import smart_unicode +from desktop import conf + LOG = logging.getLogger(__name__) @@ -69,6 +75,7 @@ class Resource(object): @return: Raw body or JSON dictionary (if response content type is JSON). """ path = self._join_uri(relpath) + start_time = time.time() resp = self._client.execute(method, path, params=params, @@ -80,11 +87,23 @@ class Resource(object): clear_cookies=clear_cookies) if self._client.logger.isEnabledFor(logging.DEBUG): - self._client.logger.debug( - "%s Got response: %s%s" % - (method, - smart_unicode(resp.content[:1000], errors='replace'), - len(resp.content) > 1000 and "..." or "")) + log_length = conf.REST_RESPONSE_SIZE.get() != -1 and conf.REST_RESPONSE_SIZE.get() # We want to output duration without content + duration = time.time() - start_time + message = '%s %s %s%s%s %s%s returned in %dms %s %s %s%s' % ( + method, + type(self._client._session.auth) if self._client._session and self._client._session.auth else None, + self._client._base_url, + smart_str(path), + iri_to_uri('?' + urlencode(params)) if params else '', + smart_unicode(data, errors='replace')[:log_length] if data else "", + log_length and len(data) > log_length and "..." or "" if data else "", + (duration * 1000), + resp.status_code if resp else 0, + len(resp.content) if resp else 0, + smart_unicode(resp.content[:log_length], errors='replace') if resp else "", + log_length and len(resp.content) > log_length and "..." or "" if resp else "" + ) + self._client.logger.debug("%s" % message) return self._format_response(resp) diff --git a/desktop/core/src/desktop/lib/thrift_util.py b/desktop/core/src/desktop/lib/thrift_util.py index ad8b69288f..7688974fb2 100644 --- a/desktop/core/src/desktop/lib/thrift_util.py +++ b/desktop/core/src/desktop/lib/thrift_util.py @@ -36,6 +36,7 @@ from thrift.protocol.TMultiplexedProtocol import TMultiplexedProtocol from django.conf import settings from django.utils.translation import ugettext as _ from desktop.conf import SASL_MAX_BUFFER +from desktop import conf from desktop.lib.python_util import create_synchronous_io_multiplexer from desktop.lib.thrift_.http_client import THttpClient @@ -440,7 +441,7 @@ class SuperClient(object): log_msg = _unpack_guid_secret_in_handle(repr(ret)) # Truncate log message, increase output in DEBUG mode - log_limit = 2000 if settings.DEBUG else 1000 + log_limit = conf.THRIFT_RESPONSE_SIZE.get() if settings.DEBUG else 1000 log_msg = log_msg[:log_limit] + (log_msg[log_limit:] and '...') duration = time.time() - st diff --git a/desktop/core/src/desktop/log/access.py b/desktop/core/src/desktop/log/access.py index bc7a4e82da..f668935b5b 100644 --- a/desktop/core/src/desktop/log/access.py +++ b/desktop/core/src/desktop/log/access.py @@ -22,6 +22,8 @@ This assumes a single-threaded server. import logging import re +import resource +import sys import threading import time @@ -79,16 +81,37 @@ class AccessInfo(dict): self['proto'] = request.META.get('SERVER_PROTOCOL', '-') self['agent'] = request.META.get('HTTP_USER_AGENT', '-') self['time'] = time.time() + self['duration'] = None + self['memory'] = None + + def memory_usage_resource(self): + """ + This is a lightweight way to get the total peak memory as + doing the diffing before/after request with guppy was too inconsistent and memory intensive. + """ + rusage_denom = 1024 + if sys.platform == 'darwin': + rusage_denom = rusage_denom * 1024 + # get peak memory usage, bytes on OSX, Kilobytes on Linux + return resource.getrusage(resource.RUSAGE_SELF).ru_maxrss / rusage_denom + + def log(self, level, msg=None, start_time=None): + is_instrumentation = desktop.conf.INSTRUMENTATION.get() + self['duration'] = ' returned in %dms' % ((time.time() - start_time) * 1000) if start_time is not None and is_instrumentation else '' + self['memory'] = ' (mem: %dmb)' % self.memory_usage_resource() if is_instrumentation else '' - def log(self, level, msg=None): if msg is not None: self['msg'] = msg - ACCESS_LOG.log(level, - '%(remote_ip)s %(username)s - "%(method)s %(path)s %(proto)s" -- %(msg)s' % - self) + ACCESS_LOG.log(level, '%(remote_ip)s %(username)s - "%(method)s %(path)s %(proto)s"%(duration)s%(memory)s-- %(msg)s' % self) else: - ACCESS_LOG.log(level, - '%(remote_ip)s %(username)s - "%(method)s %(path)s %(proto)s"' % self) + ACCESS_LOG.log(level, '%(remote_ip)s %(username)s - "%(method)s %(path)s %(proto)s"%(duration)s%(memory)s' % self) + + if is_instrumentation: + import gc + gc.collect() + for o in gc.garbage: + for r in gc.get_referrers(o): + ACCESS_LOG.log(level, 'ref for %r: %r' % (o, r)) def add_to_access_history(self, app): """Record this user access to the recent access map""" @@ -138,16 +161,18 @@ class AccessInfo(dict): _MODULE_RE = re.compile('[^.]*') -def log_page_hit(request, view_func, level=None): +def log_page_hit(request, view_func, level=None, start_time=None): """Log the request to the access log""" if level is None: level = logging.INFO ai = AccessInfo(request) - ai.log(level) + ai.log(level, start_time=start_time) + + # Disabled for now as not used # Find the app - app_re_match = _MODULE_RE.match(view_func.__module__) - app = app_re_match and app_re_match.group(0) or '-' - ai.add_to_access_history(app) +# app_re_match = _MODULE_RE.match(view_func.__module__) +# app = app_re_match and app_re_match.group(0) or '-' +# ai.add_to_access_history(app) def access_log(request, msg=None, level=None): diff --git a/desktop/core/src/desktop/middleware.py b/desktop/core/src/desktop/middleware.py index 9741790afc..0cc3d36052 100644 --- a/desktop/core/src/desktop/middleware.py +++ b/desktop/core/src/desktop/middleware.py @@ -273,6 +273,8 @@ class LoginAndPermissionMiddleware(object): which tells us the log level. The downside is that we don't have the status code, which isn't useful for status logging anyways. """ + request.ts = time.time() + request.view_func = view_func access_log_level = getattr(view_func, 'access_log_level', None) # First, skip views not requiring login @@ -315,7 +317,8 @@ class LoginAndPermissionMiddleware(object): return PopupException( _("You do not have permission to access the %(app_name)s application.") % {'app_name': app_accessed.capitalize()}, error_code=401).response(request) else: - log_page_hit(request, view_func, level=access_log_level) + if not hasattr(request, 'view_func'): + log_page_hit(request, view_func, level=access_log_level) return None logging.info("Redirecting to login page: %s", request.get_full_path()) @@ -330,6 +333,11 @@ class LoginAndPermissionMiddleware(object): else: return HttpResponseRedirect("%s?%s=%s" % (settings.LOGIN_URL, REDIRECT_FIELD_NAME, urlquote(request.get_full_path()))) + def process_response(self, request, response): + if hasattr(request, 'ts') and hasattr(request, 'view_func'): + log_page_hit(request, request.view_func, level=logging.INFO, start_time=request.ts) + return response + class JsonMessage(object): def __init__(self, **kwargs): diff --git a/desktop/core/src/desktop/settings.py b/desktop/core/src/desktop/settings.py index 2dafdd9e2a..e0aa364681 100644 --- a/desktop/core/src/desktop/settings.py +++ b/desktop/core/src/desktop/settings.py @@ -20,6 +20,7 @@ # Local customizations are done by symlinking a file # as local_settings.py. +import gc import logging import os import pkg_resources @@ -497,6 +498,9 @@ if desktop.conf.MEMORY_PROFILER.get(): MEMORY_PROFILER = hpy() MEMORY_PROFILER.setrelheap() +# Instrumentation +if desktop.conf.INSTRUMENTATION.get(): + gc.set_debug(gc.DEBUG_UNCOLLECTABLE | gc.DEBUG_OBJECTS) if not desktop.conf.DATABASE_LOGGING.get(): def disable_database_logging():