def record_request_stop_data(log_data: MutableMapping[str, Any]) -> None:
log_data["time_stopped"] = time.time()
log_data["remote_cache_time_stopped"] = get_remote_cache_time()
log_data["remote_cache_requests_stopped"] = get_remote_cache_requests()
log_data["markdown_time_stopped"] = get_markdown_time()
log_data["markdown_requests_stopped"] = get_markdown_requests()
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].disable()
def record_request_restart_data(log_data: MutableMapping[str, Any]) -> None:
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].enable()
log_data['time_restarted'] = time.time()
log_data['remote_cache_time_restarted'] = get_remote_cache_time()
log_data['remote_cache_requests_restarted'] = get_remote_cache_requests()
log_data['markdown_time_restarted'] = get_markdown_time()
log_data['markdown_requests_restarted'] = get_markdown_requests()
def record_request_start_data(log_data: MutableMapping[str, Any]) -> None:
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"] = cProfile.Profile()
log_data["prof"].enable()
reset_queries()
log_data["time_started"] = time.time()
log_data["remote_cache_time_start"] = get_remote_cache_time()
log_data["remote_cache_requests_start"] = get_remote_cache_requests()
log_data["markdown_time_start"] = get_markdown_time()
log_data["markdown_requests_start"] = get_markdown_requests()
def write_log_line(
log_data: MutableMapping[str, Any],
path: str,
method: str,
remote_ip: str,
requestor_for_logs: str,
client_name: str,
status_code: int = 200,
error_content: Optional[AnyStr] = None,
error_content_iter: Optional[Iterable[AnyStr]] = None) -> None:
assert error_content is None or error_content_iter is None
if error_content is not None:
error_content_iter = (error_content, )
if settings.STATSD_HOST != '':
# For statsd timer name
if path == '/':
statsd_path = 'webreq'
else:
statsd_path = "webreq.{}".format(path[1:].replace('/', '.'))
# Remove non-ascii chars from path (there should be none, if there are it's
# because someone manually entered a nonexistent 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').decode("ascii")
# TODO: This could probably be optimized to use a regular expression rather than a loop.
suppress_statsd = any(blacklisted in statsd_path
for blacklisted in statsd_blacklisted_requests)
else:
suppress_statsd = True
statsd_path = ''
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 = f" (lp: {format_timedelta(orig_time_delta)})"
remote_cache_output = ""
if 'remote_cache_time_start' in log_data:
remote_cache_time_delta = get_remote_cache_time(
) - log_data['remote_cache_time_start']
remote_cache_count_delta = get_remote_cache_requests(
) - log_data['remote_cache_requests_start']
if 'remote_cache_requests_stopped' in log_data:
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
remote_cache_time_delta += (
log_data['remote_cache_time_stopped'] -
log_data['remote_cache_time_restarted'])
remote_cache_count_delta += (
log_data['remote_cache_requests_stopped'] -
log_data['remote_cache_requests_restarted'])
if (remote_cache_time_delta > 0.005):
remote_cache_output = f" (mem: {format_timedelta(remote_cache_time_delta)}/{remote_cache_count_delta})"
if not suppress_statsd:
statsd.timing(f"{statsd_path}.remote_cache.time",
timedelta_ms(remote_cache_time_delta))
statsd.incr(f"{statsd_path}.remote_cache.querycount",
remote_cache_count_delta)
startup_output = ""
if 'startup_time_delta' in log_data and log_data[
"startup_time_delta"] > 0.005:
startup_output = " (+start: {})".format(
format_timedelta(log_data["startup_time_delta"]))
markdown_output = ""
if 'markdown_time_start' in log_data:
markdown_time_delta = get_markdown_time(
) - log_data['markdown_time_start']
markdown_count_delta = get_markdown_requests(
) - log_data['markdown_requests_start']
if 'markdown_requests_stopped' in log_data:
# (now - restarted) + (stopped - start) = (now - start) + (stopped - restarted)
markdown_time_delta += (log_data['markdown_time_stopped'] -
log_data['markdown_time_restarted'])
markdown_count_delta += (log_data['markdown_requests_stopped'] -
log_data['markdown_requests_restarted'])
if (markdown_time_delta > 0.005):
markdown_output = f" (md: {format_timedelta(markdown_time_delta)}/{markdown_count_delta})"
if not suppress_statsd:
statsd.timing(f"{statsd_path}.markdown.time",
timedelta_ms(markdown_time_delta))
statsd.incr(f"{statsd_path}.markdown.count",
markdown_count_delta)
# Get the amount of time spent doing database queries
db_time_output = ""
queries = connection.connection.queries if connection.connection is not None else []
if len(queries) > 0:
query_time = sum(float(query.get('time', 0)) for query in queries)
db_time_output = f" (db: {format_timedelta(query_time)}/{len(queries)}q)"
if not suppress_statsd:
# Log ms, db ms, and num queries to statsd
statsd.timing(f"{statsd_path}.dbtime", timedelta_ms(query_time))
statsd.incr(f"{statsd_path}.dbq", len(queries))
statsd.timing(f"{statsd_path}.total", timedelta_ms(time_delta))
if 'extra' in log_data:
extra_request_data = " {}".format(log_data['extra'])
else:
extra_request_data = ""
logger_client = f"({requestor_for_logs} via {client_name})"
logger_timing = f'{format_timedelta(time_delta):>5}{optional_orig_delta}{remote_cache_output}{markdown_output}{db_time_output}{startup_output} {path}'
logger_line = f'{remote_ip:<15} {method:<7} {status_code:3} {logger_timing}{extra_request_data} {logger_client}'
if (status_code in [200, 304] and method == "GET"
and path.startswith("/static")):
logger.debug(logger_line)
else:
logger.info(logger_line)
if (is_slow_query(time_delta, path)):
slow_query_logger.info(logger_line)
if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].disable()
profile_path = "/tmp/profile.data.{}.{}".format(
path.split("/")[-1], int(time_delta * 1000))
log_data["prof"].dump_stats(profile_path)
# Log some additional data whenever we return certain 40x errors
if 400 <= status_code < 500 and status_code not in [401, 404, 405]:
assert error_content_iter is not None
error_content_list = list(error_content_iter)
if not error_content_list:
error_data = ''
elif isinstance(error_content_list[0], str):
error_data = ''.join(error_content_list)
elif isinstance(error_content_list[0], bytes):
error_data = repr(b''.join(error_content_list))
if len(error_data) > 200:
error_data = "[content more than 200 characters]"
logger.info('status=%3d, data=%s, uid=%s', status_code, error_data,
requestor_for_logs)