mirror of
https://github.com/zulip/zulip.git
synced 2025-11-11 09:27:43 +00:00
Make all the work of the logging middleware not depend on Request or Response objects
(imported from commit ce13909d338230a931cb09405d54bb872b2ff0a6)
This commit is contained in:
Zev Benjamin
@@ -15,119 +15,153 @@ import time
|
|||||||
|
|
||||||
logger = logging.getLogger('zulip.requests')
|
logger = logging.getLogger('zulip.requests')
|
||||||
|
|
||||||
|
def record_request_stop_data(log_data):
|
||||||
|
log_data['time_stopped'] = time.time()
|
||||||
|
log_data['memcached_time_stopped'] = get_memcached_time()
|
||||||
|
log_data['memcached_requests_stopped'] = get_memcached_requests()
|
||||||
|
log_data['bugdown_time_stopped'] = get_bugdown_time()
|
||||||
|
log_data['bugdown_requests_stopped'] = get_bugdown_requests()
|
||||||
|
|
||||||
def async_request_stop(request):
|
def async_request_stop(request):
|
||||||
request._log_data['time_stopped'] = time.time()
|
record_request_stop_data(request._log_data)
|
||||||
request._log_data['memcached_time_stopped'] = get_memcached_time()
|
|
||||||
request._log_data['memcached_requests_stopped'] = get_memcached_requests()
|
def record_request_restart_data(log_data):
|
||||||
request._log_data['bugdown_time_stopped'] = get_bugdown_time()
|
log_data['time_restarted'] = time.time()
|
||||||
request._log_data['bugdown_requests_stopped'] = get_bugdown_requests()
|
log_data['memcached_time_restarted'] = get_memcached_time()
|
||||||
|
log_data['memcached_requests_restarted'] = get_memcached_requests()
|
||||||
|
log_data['bugdown_time_restarted'] = get_bugdown_time()
|
||||||
|
log_data['bugdown_requests_restarted'] = get_bugdown_requests()
|
||||||
|
|
||||||
def async_request_restart(request):
|
def async_request_restart(request):
|
||||||
request._log_data['time_restarted'] = time.time()
|
record_request_restart_data(request._log_data)
|
||||||
request._log_data['memcached_time_restarted'] = get_memcached_time()
|
|
||||||
request._log_data['memcached_requests_restarted'] = get_memcached_requests()
|
def record_request_start_data(log_data):
|
||||||
request._log_data['bugdown_time_restarted'] = get_bugdown_time()
|
log_data['time_started'] = time.time()
|
||||||
request._log_data['bugdown_requests_restarted'] = get_bugdown_requests()
|
log_data['memcached_time_start'] = get_memcached_time()
|
||||||
|
log_data['memcached_requests_start'] = get_memcached_requests()
|
||||||
|
log_data['bugdown_time_start'] = get_bugdown_time()
|
||||||
|
log_data['bugdown_requests_start'] = get_bugdown_requests()
|
||||||
|
|
||||||
|
def write_log_line(log_data, path, method, remote_ip, email, client_name,
|
||||||
|
status_code=200, error_content=''):
|
||||||
|
def timedelta_ms(timedelta):
|
||||||
|
return timedelta * 1000
|
||||||
|
|
||||||
|
def format_timedelta(timedelta):
|
||||||
|
if (timedelta >= 1):
|
||||||
|
return "%.1fs" % (timedelta)
|
||||||
|
return "%.0fms" % (timedelta_ms(timedelta),)
|
||||||
|
|
||||||
|
# For statsd timer name
|
||||||
|
if path == '/':
|
||||||
|
statsd_path = 'webreq'
|
||||||
|
else:
|
||||||
|
statsd_path = u"webreq.%s" % (path[1:].replace('/', '.'),)
|
||||||
|
# Remove non-ascii chars from path (there should be none, if there are it's
|
||||||
|
# because someone manually entered a nonexistant path), as UTF-8 chars make
|
||||||
|
# statsd sad when it sends the key name over the socket
|
||||||
|
statsd_path = statsd_path.encode('ascii', errors='ignore')
|
||||||
|
blacklisted_requests = ['do_confirm', 'accounts.login.openid', 'send_confirm',
|
||||||
|
'eventslast_event_id', 'webreq.content']
|
||||||
|
suppress_statsd = any((blacklisted in statsd_path for blacklisted in blacklisted_requests))
|
||||||
|
|
||||||
|
time_delta = -1
|
||||||
|
# A time duration of -1 means the StartLogRequests middleware
|
||||||
|
# didn't run for some reason
|
||||||
|
optional_orig_delta = ""
|
||||||
|
if 'time_started' in log_data:
|
||||||
|
time_delta = time.time() - log_data['time_started']
|
||||||
|
if 'time_stopped' in log_data:
|
||||||
|
orig_time_delta = time_delta
|
||||||
|
time_delta = ((log_data['time_stopped'] - log_data['time_started']) +
|
||||||
|
(time.time() - log_data['time_restarted']))
|
||||||
|
optional_orig_delta = " (lp: %s)" % (format_timedelta(orig_time_delta),)
|
||||||
|
memcached_output = ""
|
||||||
|
if 'memcached_time_start' in log_data:
|
||||||
|
memcached_time_delta = get_memcached_time() - log_data['memcached_time_start']
|
||||||
|
memcached_count_delta = get_memcached_requests() - log_data['memcached_requests_start']
|
||||||
|
if 'memcached_requests_stopped' in log_data:
|
||||||
|
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
|
||||||
|
memcached_time_delta += (log_data['memcached_time_stopped'] -
|
||||||
|
log_data['memcached_time_restarted'])
|
||||||
|
memcached_count_delta += (log_data['memcached_requests_stopped'] -
|
||||||
|
log_data['memcached_requests_restarted'])
|
||||||
|
|
||||||
|
if (memcached_time_delta > 0.005):
|
||||||
|
memcached_output = " (mem: %s/%s)" % (format_timedelta(memcached_time_delta),
|
||||||
|
memcached_count_delta)
|
||||||
|
|
||||||
|
if not suppress_statsd:
|
||||||
|
statsd.timing("%s.memcached.time" % (statsd_path,), timedelta_ms(memcached_time_delta))
|
||||||
|
statsd.incr("%s.memcached.querycount" % (statsd_path,), memcached_count_delta)
|
||||||
|
|
||||||
|
bugdown_output = ""
|
||||||
|
if 'bugdown_time_start' in log_data:
|
||||||
|
bugdown_time_delta = get_bugdown_time() - log_data['bugdown_time_start']
|
||||||
|
bugdown_count_delta = get_bugdown_requests() - log_data['bugdown_requests_start']
|
||||||
|
if 'bugdown_requests_stopped' in log_data:
|
||||||
|
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
|
||||||
|
bugdown_time_delta += (log_data['bugdown_time_stopped'] -
|
||||||
|
log_data['bugdown_time_restarted'])
|
||||||
|
bugdown_count_delta += (log_data['bugdown_requests_stopped'] -
|
||||||
|
log_data['bugdown_requests_restarted'])
|
||||||
|
|
||||||
|
if (bugdown_time_delta > 0.005):
|
||||||
|
bugdown_output = " (md: %s/%s)" % (format_timedelta(bugdown_time_delta),
|
||||||
|
bugdown_count_delta)
|
||||||
|
|
||||||
|
if not suppress_statsd:
|
||||||
|
statsd.timing("%s.markdown.time" % (statsd_path,), timedelta_ms(bugdown_time_delta))
|
||||||
|
statsd.incr("%s.markdown.count" % (statsd_path,), bugdown_count_delta)
|
||||||
|
|
||||||
|
# Get the amount of time spent doing database queries
|
||||||
|
db_time_output = ""
|
||||||
|
if len(connection.queries) > 0:
|
||||||
|
query_time = sum(float(query.get('time', 0)) for query in connection.queries)
|
||||||
|
db_time_output = " (db: %s/%sq)" % (format_timedelta(query_time),
|
||||||
|
len(connection.queries))
|
||||||
|
|
||||||
|
if not suppress_statsd:
|
||||||
|
# Log ms, db ms, and num queries to statsd
|
||||||
|
statsd.timing("%s.dbtime" % (statsd_path,), timedelta_ms(query_time))
|
||||||
|
statsd.incr("%s.dbq" % (statsd_path, ), len(connection.queries))
|
||||||
|
statsd.timing("%s.total" % (statsd_path,), timedelta_ms(time_delta))
|
||||||
|
|
||||||
|
if 'extra' in log_data:
|
||||||
|
extra_request_data = " %s" % (log_data['extra'],)
|
||||||
|
else:
|
||||||
|
extra_request_data = ""
|
||||||
|
logger_client = "(%s via %s)" % (email, client_name)
|
||||||
|
logger_timing = '%5s%s%s%s%s %s' % \
|
||||||
|
(format_timedelta(time_delta), optional_orig_delta,
|
||||||
|
memcached_output, bugdown_output,
|
||||||
|
db_time_output, path)
|
||||||
|
logger_line = '%-15s %-7s %3d %s%s %s' % \
|
||||||
|
(remote_ip, method, status_code,
|
||||||
|
logger_timing, extra_request_data, logger_client)
|
||||||
|
logger.info(logger_line)
|
||||||
|
|
||||||
|
if time_delta >= 1:
|
||||||
|
queue_json_publish("slow_queries", "%s (%s)" % (logger_timing, email), lambda e: None)
|
||||||
|
|
||||||
|
# Log some additional data whenever we return certain 40x errors
|
||||||
|
if 400 <= status_code < 500 and status_code not in [401, 404, 405]:
|
||||||
|
if len(error_content) > 100:
|
||||||
|
error_content = "[content more than 100 characters]"
|
||||||
|
logger.info('status=%3d, data=%s, uid=%s' % (status_code, error_content, email))
|
||||||
|
|
||||||
class LogRequests(object):
|
class LogRequests(object):
|
||||||
def process_request(self, request):
|
def process_request(self, request):
|
||||||
request._log_data = dict()
|
request._log_data = dict()
|
||||||
request._log_data['time_started'] = time.time()
|
record_request_start_data(request._log_data)
|
||||||
request._log_data['memcached_time_start'] = get_memcached_time()
|
|
||||||
request._log_data['memcached_requests_start'] = get_memcached_requests()
|
|
||||||
request._log_data['bugdown_time_start'] = get_bugdown_time()
|
|
||||||
request._log_data['bugdown_requests_start'] = get_bugdown_requests()
|
|
||||||
connection.queries = []
|
connection.queries = []
|
||||||
|
|
||||||
def process_response(self, request, response):
|
def process_response(self, request, response):
|
||||||
def timedelta_ms(timedelta):
|
|
||||||
return timedelta * 1000
|
|
||||||
|
|
||||||
def format_timedelta(timedelta):
|
|
||||||
if (timedelta >= 1):
|
|
||||||
return "%.1fs" % (timedelta)
|
|
||||||
return "%.0fms" % (timedelta_ms(timedelta),)
|
|
||||||
|
|
||||||
# For statsd timer name
|
|
||||||
if request.path == '/':
|
|
||||||
statsd_path = 'webreq'
|
|
||||||
else:
|
|
||||||
statsd_path = u"webreq.%s" % (request.path[1:].replace('/', '.'),)
|
|
||||||
# Remove non-ascii chars from path (there should be none, if there are it's
|
|
||||||
# because someone manually entered a nonexistant path), as UTF-8 chars make
|
|
||||||
# statsd sad when it sends the key name over the socket
|
|
||||||
statsd_path = statsd_path.encode('ascii', errors='ignore')
|
|
||||||
blacklisted_requests = ['do_confirm', 'accounts.login.openid', 'send_confirm',
|
|
||||||
'eventslast_event_id', 'webreq.content']
|
|
||||||
suppress_statsd = any((blacklisted in statsd_path for blacklisted in blacklisted_requests))
|
|
||||||
|
|
||||||
# The reverse proxy might have sent us the real external IP
|
# The reverse proxy might have sent us the real external IP
|
||||||
remote_ip = request.META.get('HTTP_X_REAL_IP')
|
remote_ip = request.META.get('HTTP_X_REAL_IP')
|
||||||
if remote_ip is None:
|
if remote_ip is None:
|
||||||
remote_ip = request.META['REMOTE_ADDR']
|
remote_ip = request.META['REMOTE_ADDR']
|
||||||
|
|
||||||
time_delta = -1
|
|
||||||
# A time duration of -1 means the StartLogRequests middleware
|
|
||||||
# didn't run for some reason
|
|
||||||
optional_orig_delta = ""
|
|
||||||
if 'time_started' in request._log_data:
|
|
||||||
time_delta = time.time() - request._log_data['time_started']
|
|
||||||
if 'time_stopped' in request._log_data:
|
|
||||||
orig_time_delta = time_delta
|
|
||||||
time_delta = ((request._log_data['time_stopped'] - request._log_data['time_started']) +
|
|
||||||
(time.time() - request._log_data['time_restarted']))
|
|
||||||
optional_orig_delta = " (lp: %s)" % (format_timedelta(orig_time_delta),)
|
|
||||||
memcached_output = ""
|
|
||||||
if 'memcached_time_start' in request._log_data:
|
|
||||||
memcached_time_delta = get_memcached_time() - request._log_data['memcached_time_start']
|
|
||||||
memcached_count_delta = get_memcached_requests() - request._log_data['memcached_requests_start']
|
|
||||||
if 'memcached_requests_stopped' in request._log_data:
|
|
||||||
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
|
|
||||||
memcached_time_delta += (request._log_data['memcached_time_stopped'] -
|
|
||||||
request._log_data['memcached_time_restarted'])
|
|
||||||
memcached_count_delta += (request._log_data['memcached_requests_stopped'] -
|
|
||||||
request._log_data['memcached_requests_restarted'])
|
|
||||||
|
|
||||||
if (memcached_time_delta > 0.005):
|
|
||||||
memcached_output = " (mem: %s/%s)" % (format_timedelta(memcached_time_delta),
|
|
||||||
memcached_count_delta)
|
|
||||||
|
|
||||||
if not suppress_statsd:
|
|
||||||
statsd.timing("%s.memcached.time" % (statsd_path,), timedelta_ms(memcached_time_delta))
|
|
||||||
statsd.incr("%s.memcached.querycount" % (statsd_path,), memcached_count_delta)
|
|
||||||
|
|
||||||
bugdown_output = ""
|
|
||||||
if 'bugdown_time_start' in request._log_data:
|
|
||||||
bugdown_time_delta = get_bugdown_time() - request._log_data['bugdown_time_start']
|
|
||||||
bugdown_count_delta = get_bugdown_requests() - request._log_data['bugdown_requests_start']
|
|
||||||
if 'bugdown_requests_stopped' in request._log_data:
|
|
||||||
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
|
|
||||||
bugdown_time_delta += (request._log_data['bugdown_time_stopped'] -
|
|
||||||
request._log_data['bugdown_time_restarted'])
|
|
||||||
bugdown_count_delta += (request._log_data['bugdown_requests_stopped'] -
|
|
||||||
request._log_data['bugdown_requests_restarted'])
|
|
||||||
|
|
||||||
if (bugdown_time_delta > 0.005):
|
|
||||||
bugdown_output = " (md: %s/%s)" % (format_timedelta(bugdown_time_delta),
|
|
||||||
bugdown_count_delta)
|
|
||||||
|
|
||||||
if not suppress_statsd:
|
|
||||||
statsd.timing("%s.markdown.time" % (statsd_path,), timedelta_ms(bugdown_time_delta))
|
|
||||||
statsd.incr("%s.markdown.count" % (statsd_path,), bugdown_count_delta)
|
|
||||||
|
|
||||||
# Get the amount of time spent doing database queries
|
|
||||||
db_time_output = ""
|
|
||||||
if len(connection.queries) > 0:
|
|
||||||
query_time = sum(float(query.get('time', 0)) for query in connection.queries)
|
|
||||||
db_time_output = " (db: %s/%sq)" % (format_timedelta(query_time),
|
|
||||||
len(connection.queries))
|
|
||||||
|
|
||||||
if not suppress_statsd:
|
|
||||||
# Log ms, db ms, and num queries to statsd
|
|
||||||
statsd.timing("%s.dbtime" % (statsd_path,), timedelta_ms(query_time))
|
|
||||||
statsd.incr("%s.dbq" % (statsd_path, ), len(connection.queries))
|
|
||||||
statsd.timing("%s.total" % (statsd_path,), timedelta_ms(time_delta))
|
|
||||||
|
|
||||||
# Get the requestor's email address and client, if available.
|
# Get the requestor's email address and client, if available.
|
||||||
try:
|
try:
|
||||||
email = request._email
|
email = request._email
|
||||||
@@ -138,30 +172,9 @@ class LogRequests(object):
|
|||||||
except Exception:
|
except Exception:
|
||||||
client = "?"
|
client = "?"
|
||||||
|
|
||||||
if 'extra' in request._log_data:
|
write_log_line(request._log_data, request.path, request.method,
|
||||||
extra_request_data = " %s" % (request._log_data['extra'],)
|
remote_ip, email, client, response.status_code,
|
||||||
else:
|
response.content)
|
||||||
extra_request_data = ""
|
|
||||||
logger_client = "(%s via %s)" % (email, client)
|
|
||||||
logger_timing = '%5s%s%s%s%s %s' % \
|
|
||||||
(format_timedelta(time_delta), optional_orig_delta,
|
|
||||||
memcached_output, bugdown_output,
|
|
||||||
db_time_output, request.path)
|
|
||||||
logger_line = '%-15s %-7s %3d %s%s %s' % \
|
|
||||||
(remote_ip, request.method, response.status_code,
|
|
||||||
logger_timing, extra_request_data, logger_client)
|
|
||||||
logger.info(logger_line)
|
|
||||||
|
|
||||||
if time_delta >= 1:
|
|
||||||
queue_json_publish("slow_queries", "%s (%s)" % (logger_timing, email), lambda e: None)
|
|
||||||
|
|
||||||
# Log some additional data whenever we return certain 40x errors
|
|
||||||
if 400 <= response.status_code < 500 and response.status_code not in [401, 404, 405]:
|
|
||||||
content = response.content
|
|
||||||
if len(content) > 100:
|
|
||||||
content = "[content more than 100 characters]"
|
|
||||||
logger.info('status=%3d, data=%s, uid=%s' % (response.status_code, content, email))
|
|
||||||
|
|
||||||
return response
|
return response
|
||||||
|
|
||||||
class JsonErrorHandler(object):
|
class JsonErrorHandler(object):
|
||||||
|
|||||||
Reference in New Issue
Block a user