5.13_all_logging.patch 11 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273
  1. # Licensed to Cloudera, Inc. under one
  2. # or more contributor license agreements. See the NOTICE file
  3. # distributed with this work for additional information
  4. # regarding copyright ownership. Cloudera, Inc. licenses this file
  5. # to you under the Apache License, Version 2.0 (the
  6. # "License"); you may not use this file except in compliance
  7. # with the License. You may obtain a copy of the License at
  8. #
  9. # http://www.apache.org/licenses/LICENSE-2.0
  10. #
  11. # Unless required by applicable law or agreed to in writing, software
  12. # distributed under the License is distributed on an "AS IS" BASIS,
  13. # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  14. # See the License for the specific language governing permissions and
  15. # limitations under the License.
  16. diff --git a/desktop/core/src/desktop/conf.py b/desktop/core/src/desktop/conf.py
  17. index 152291f402..0bcaa70e04 100644
  18. --- a/desktop/core/src/desktop/conf.py
  19. +++ b/desktop/core/src/desktop/conf.py
  20. @@ -373,6 +373,18 @@ COLLECT_USAGE = Config(
  21. type=coerce_bool,
  22. default=True)
  23. +REST_RESPONSE_SIZE = Config(
  24. + key="rest_response_size",
  25. + help=_("Number of characters the rest api reponse calls to dump to the logs when debug is enabled."),
  26. + type=int,
  27. + default=1000)
  28. +
  29. +THRIFT_RESPONSE_SIZE = Config(
  30. + key="thrift_response_size",
  31. + help=_("Number of characters the thrift api reponse calls to dump to the logs when debug is enabled."),
  32. + type=int,
  33. + default=1000)
  34. +
  35. LEAFLET_TILE_LAYER = Config(
  36. key="leaflet_tile_layer",
  37. 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."),
  38. @@ -1279,6 +1291,17 @@ MEMORY_PROFILER = Config(
  39. default=False)
  40. +def get_instrumentation_default():
  41. + """If django_debug_mode is True, this is automatically enabled"""
  42. + return DJANGO_DEBUG_MODE.get()
  43. +
  44. +INSTRUMENTATION = Config(
  45. + key='instrumentation',
  46. + help=_('Enable or disable instrumentation. If django_debug_mode is True, this is automatically enabled.'),
  47. + type=coerce_bool,
  48. + dynamic_default=get_instrumentation_default)
  49. +
  50. +
  51. AUDIT_EVENT_LOG_DIR = Config(
  52. key="audit_event_log_dir",
  53. help=_("The directory where to store the auditing logs. Auditing is disable if the value is empty."),
  54. diff --git a/desktop/core/src/desktop/lib/rest/resource.py b/desktop/core/src/desktop/lib/rest/resource.py
  55. index 15200940d7..bf8fd88d44 100644
  56. --- a/desktop/core/src/desktop/lib/rest/resource.py
  57. +++ b/desktop/core/src/desktop/lib/rest/resource.py
  58. @@ -16,9 +16,15 @@
  59. import logging
  60. import posixpath
  61. +import time
  62. +
  63. +from django.utils.encoding import iri_to_uri, smart_str
  64. +from django.utils.http import urlencode
  65. from desktop.lib.i18n import smart_unicode
  66. +from desktop import conf
  67. +
  68. LOG = logging.getLogger(__name__)
  69. @@ -69,6 +75,7 @@ class Resource(object):
  70. @return: Raw body or JSON dictionary (if response content type is JSON).
  71. """
  72. path = self._join_uri(relpath)
  73. + start_time = time.time()
  74. resp = self._client.execute(method,
  75. path,
  76. params=params,
  77. @@ -80,11 +87,23 @@ class Resource(object):
  78. clear_cookies=clear_cookies)
  79. if self._client.logger.isEnabledFor(logging.DEBUG):
  80. - self._client.logger.debug(
  81. - "%s Got response: %s%s" %
  82. - (method,
  83. - smart_unicode(resp.content[:1000], errors='replace'),
  84. - len(resp.content) > 1000 and "..." or ""))
  85. + log_length = conf.REST_RESPONSE_SIZE.get() != -1 and conf.REST_RESPONSE_SIZE.get() # We want to output duration without content
  86. + duration = time.time() - start_time
  87. + message = '%s %s %s%s%s %s%s returned in %dms %s %s %s%s' % (
  88. + method,
  89. + type(self._client._session.auth) if self._client._session and self._client._session.auth else None,
  90. + self._client._base_url,
  91. + smart_str(path),
  92. + iri_to_uri('?' + urlencode(params)) if params else '',
  93. + smart_unicode(data, errors='replace')[:log_length] if data else "",
  94. + log_length and len(data) > log_length and "..." or "" if data else "",
  95. + (duration * 1000),
  96. + resp.status_code if resp else 0,
  97. + len(resp.content) if resp else 0,
  98. + smart_unicode(resp.content[:log_length], errors='replace') if resp else "",
  99. + log_length and len(resp.content) > log_length and "..." or "" if resp else ""
  100. + )
  101. + self._client.logger.debug("%s" % message)
  102. return self._format_response(resp)
  103. diff --git a/desktop/core/src/desktop/lib/thrift_util.py b/desktop/core/src/desktop/lib/thrift_util.py
  104. index ad8b69288f..7688974fb2 100644
  105. --- a/desktop/core/src/desktop/lib/thrift_util.py
  106. +++ b/desktop/core/src/desktop/lib/thrift_util.py
  107. @@ -36,6 +36,7 @@ from thrift.protocol.TMultiplexedProtocol import TMultiplexedProtocol
  108. from django.conf import settings
  109. from django.utils.translation import ugettext as _
  110. from desktop.conf import SASL_MAX_BUFFER
  111. +from desktop import conf
  112. from desktop.lib.python_util import create_synchronous_io_multiplexer
  113. from desktop.lib.thrift_.http_client import THttpClient
  114. @@ -440,7 +441,7 @@ class SuperClient(object):
  115. log_msg = _unpack_guid_secret_in_handle(repr(ret))
  116. # Truncate log message, increase output in DEBUG mode
  117. - log_limit = 2000 if settings.DEBUG else 1000
  118. + log_limit = conf.THRIFT_RESPONSE_SIZE.get() if settings.DEBUG else 1000
  119. log_msg = log_msg[:log_limit] + (log_msg[log_limit:] and '...')
  120. duration = time.time() - st
  121. diff --git a/desktop/core/src/desktop/log/access.py b/desktop/core/src/desktop/log/access.py
  122. index bc7a4e82da..f668935b5b 100644
  123. --- a/desktop/core/src/desktop/log/access.py
  124. +++ b/desktop/core/src/desktop/log/access.py
  125. @@ -22,6 +22,8 @@ This assumes a single-threaded server.
  126. import logging
  127. import re
  128. +import resource
  129. +import sys
  130. import threading
  131. import time
  132. @@ -79,16 +81,37 @@ class AccessInfo(dict):
  133. self['proto'] = request.META.get('SERVER_PROTOCOL', '-')
  134. self['agent'] = request.META.get('HTTP_USER_AGENT', '-')
  135. self['time'] = time.time()
  136. + self['duration'] = None
  137. + self['memory'] = None
  138. +
  139. + def memory_usage_resource(self):
  140. + """
  141. + This is a lightweight way to get the total peak memory as
  142. + doing the diffing before/after request with guppy was too inconsistent and memory intensive.
  143. + """
  144. + rusage_denom = 1024
  145. + if sys.platform == 'darwin':
  146. + rusage_denom = rusage_denom * 1024
  147. + # get peak memory usage, bytes on OSX, Kilobytes on Linux
  148. + return resource.getrusage(resource.RUSAGE_SELF).ru_maxrss / rusage_denom
  149. +
  150. + def log(self, level, msg=None, start_time=None):
  151. + is_instrumentation = desktop.conf.INSTRUMENTATION.get()
  152. + self['duration'] = ' returned in %dms' % ((time.time() - start_time) * 1000) if start_time is not None and is_instrumentation else ''
  153. + self['memory'] = ' (mem: %dmb)' % self.memory_usage_resource() if is_instrumentation else ''
  154. - def log(self, level, msg=None):
  155. if msg is not None:
  156. self['msg'] = msg
  157. - ACCESS_LOG.log(level,
  158. - '%(remote_ip)s %(username)s - "%(method)s %(path)s %(proto)s" -- %(msg)s' %
  159. - self)
  160. + ACCESS_LOG.log(level, '%(remote_ip)s %(username)s - "%(method)s %(path)s %(proto)s"%(duration)s%(memory)s-- %(msg)s' % self)
  161. else:
  162. - ACCESS_LOG.log(level,
  163. - '%(remote_ip)s %(username)s - "%(method)s %(path)s %(proto)s"' % self)
  164. + ACCESS_LOG.log(level, '%(remote_ip)s %(username)s - "%(method)s %(path)s %(proto)s"%(duration)s%(memory)s' % self)
  165. +
  166. + if is_instrumentation:
  167. + import gc
  168. + gc.collect()
  169. + for o in gc.garbage:
  170. + for r in gc.get_referrers(o):
  171. + ACCESS_LOG.log(level, 'ref for %r: %r' % (o, r))
  172. def add_to_access_history(self, app):
  173. """Record this user access to the recent access map"""
  174. @@ -138,16 +161,18 @@ class AccessInfo(dict):
  175. _MODULE_RE = re.compile('[^.]*')
  176. -def log_page_hit(request, view_func, level=None):
  177. +def log_page_hit(request, view_func, level=None, start_time=None):
  178. """Log the request to the access log"""
  179. if level is None:
  180. level = logging.INFO
  181. ai = AccessInfo(request)
  182. - ai.log(level)
  183. + ai.log(level, start_time=start_time)
  184. +
  185. + # Disabled for now as not used
  186. # Find the app
  187. - app_re_match = _MODULE_RE.match(view_func.__module__)
  188. - app = app_re_match and app_re_match.group(0) or '-'
  189. - ai.add_to_access_history(app)
  190. +# app_re_match = _MODULE_RE.match(view_func.__module__)
  191. +# app = app_re_match and app_re_match.group(0) or '-'
  192. +# ai.add_to_access_history(app)
  193. def access_log(request, msg=None, level=None):
  194. diff --git a/desktop/core/src/desktop/middleware.py b/desktop/core/src/desktop/middleware.py
  195. index 9741790afc..0cc3d36052 100644
  196. --- a/desktop/core/src/desktop/middleware.py
  197. +++ b/desktop/core/src/desktop/middleware.py
  198. @@ -273,6 +273,8 @@ class LoginAndPermissionMiddleware(object):
  199. which tells us the log level. The downside is that we don't have the status code,
  200. which isn't useful for status logging anyways.
  201. """
  202. + request.ts = time.time()
  203. + request.view_func = view_func
  204. access_log_level = getattr(view_func, 'access_log_level', None)
  205. # First, skip views not requiring login
  206. @@ -315,7 +317,8 @@ class LoginAndPermissionMiddleware(object):
  207. return PopupException(
  208. _("You do not have permission to access the %(app_name)s application.") % {'app_name': app_accessed.capitalize()}, error_code=401).response(request)
  209. else:
  210. - log_page_hit(request, view_func, level=access_log_level)
  211. + if not hasattr(request, 'view_func'):
  212. + log_page_hit(request, view_func, level=access_log_level)
  213. return None
  214. logging.info("Redirecting to login page: %s", request.get_full_path())
  215. @@ -330,6 +333,11 @@ class LoginAndPermissionMiddleware(object):
  216. else:
  217. return HttpResponseRedirect("%s?%s=%s" % (settings.LOGIN_URL, REDIRECT_FIELD_NAME, urlquote(request.get_full_path())))
  218. + def process_response(self, request, response):
  219. + if hasattr(request, 'ts') and hasattr(request, 'view_func'):
  220. + log_page_hit(request, request.view_func, level=logging.INFO, start_time=request.ts)
  221. + return response
  222. +
  223. class JsonMessage(object):
  224. def __init__(self, **kwargs):
  225. diff --git a/desktop/core/src/desktop/settings.py b/desktop/core/src/desktop/settings.py
  226. index 2dafdd9e2a..e0aa364681 100644
  227. --- a/desktop/core/src/desktop/settings.py
  228. +++ b/desktop/core/src/desktop/settings.py
  229. @@ -20,6 +20,7 @@
  230. # Local customizations are done by symlinking a file
  231. # as local_settings.py.
  232. +import gc
  233. import logging
  234. import os
  235. import pkg_resources
  236. @@ -497,6 +498,9 @@ if desktop.conf.MEMORY_PROFILER.get():
  237. MEMORY_PROFILER = hpy()
  238. MEMORY_PROFILER.setrelheap()
  239. +# Instrumentation
  240. +if desktop.conf.INSTRUMENTATION.get():
  241. + gc.set_debug(gc.DEBUG_UNCOLLECTABLE | gc.DEBUG_OBJECTS)
  242. if not desktop.conf.DATABASE_LOGGING.get():
  243. def disable_database_logging():