| 123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273 |
- # 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():
|