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_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_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)