From 936f36ac3bf94d651987dd6c38ef8cfd78f5696b Mon Sep 17 00:00:00 2001 From: Pierre-Yves Chibon Date: Fri, 22 Jan 2021 13:15:05 +0100 Subject: [PATCH] Simplify the logging and just log to stderr for now Signed-off-by: Pierre-Yves Chibon --- scripts/test_datagrepper_perfs.py | 122 +++++------------------------- 1 file changed, 18 insertions(+), 104 deletions(-) diff --git a/scripts/test_datagrepper_perfs.py b/scripts/test_datagrepper_perfs.py index 0c436d3..93aeb44 100644 --- a/scripts/test_datagrepper_perfs.py +++ b/scripts/test_datagrepper_perfs.py @@ -19,7 +19,6 @@ import time from datetime import datetime import collections import logging -from logging.handlers import RotatingFileHandler import requests import json import os @@ -37,7 +36,7 @@ import queue if sys.version_info < (3, 7): raise Exception("Requires Python 3.7 or above.") -LOG_LEVEL = logging.DEBUG +_log = logging.getLogger(__name__) # root_path is parent folder of Scripts folder (one level up) root_path = os.path.dirname(os.path.dirname(os.path.realpath(__file__))) @@ -46,84 +45,10 @@ common_formatter = logging.Formatter( "%(asctime)s [%(levelname)-7s][ln-%(lineno)-3d]: %(message)s" ) -# Note: To create multiple log files, must use different logger name. -def setup_logger(log_file, level=logging.INFO, name="", formatter=common_formatter): - """Function setup as many loggers as you want.""" - handler = logging.FileHandler(log_file, mode="w") # default mode is append - # Or use a rotating file handler - # handler = RotatingFileHandler(log_file,maxBytes=1024, backupCount=5) - handler.setFormatter(formatter) - logger = logging.getLogger(name) - logger.setLevel(level) - logger.addHandler(handler) - return logger - - -# default debug logger -debug_log_filename = os.path.join(root_path, "debug.log") -log = setup_logger(debug_log_filename, LOG_LEVEL, "log") - -# logger for API outputs -api_formatter = logging.Formatter("%(asctime)s: %(message)s") -api_outputs_filename = os.path.join(root_path, "api_outputs.log") -log_api = setup_logger( - api_outputs_filename, LOG_LEVEL, "log_api", formatter=api_formatter -) - - -# pretty print Restful request to API log -# argument is request object -def pretty_print_request(request): - """ - Pay attention at the formatting used in this function because it is programmed to be pretty printed and may differ from the actual request. - """ - log_api.info( - "{}\n{}\n\n{}\n\n{}\n".format( - "-----------Request----------->", - request.method + " " + request.url, - "\n".join("{}: {}".format(k, v) for k, v in request.headers.items()), - request.body, - ) - ) - - -# pretty print Restful request to API log -# argument is response object -def pretty_print_response(response): - log_api.info( - "{}\n{}\n\n{}\n\n{}\n".format( - "<-----------Response-----------", - "Status code:" + str(response.status_code), - "\n".join("{}: {}".format(k, v) for k, v in response.headers.items()), - response.text, - ) - ) - - -# argument is request object -# display body in json format explicitly with expected indent. Actually most of the time it is not very necessary because body is formatted in pretty print way. -def pretty_print_request_json(request): - log_api.info( - "{}\n{}\n\n{}\n\n{}\n".format( - "-----------Request----------->", - request.method + " " + request.url, - "\n".join("{}: {}".format(k, v) for k, v in request.headers.items()), - json.dumps(ast.literal_eval(request.body), indent=4), - ) - ) - - -# argument is response object -# display body in json format explicitly with expected indent. Actually most of the time it is not very necessary because body is formatted in pretty print way. -def pretty_print_response_json(response): - log_api.info( - "{}\n{}\n\n{}\n\n{}\n".format( - "<-----------Response-----------", - "Status code:" + str(response.status_code), - "\n".join("{}: {}".format(k, v) for k, v in response.headers.items()), - json.dumps(response.json(), indent=4), - ) - ) +handler = logging.StreamHandler(stream=sys.stderr) +handler.setFormatter(common_formatter) +_log.setLevel(logging.DEBUG) +_log.addHandler(handler) class TestAPI: @@ -132,7 +57,7 @@ class TestAPI: """ def __init__(self): - log.debug("To load test data.") + _log.debug("To load test data.") self.queue_results = queue.Queue() # test start and end time @@ -176,36 +101,35 @@ class TestAPI: # Convert assert for functional tests to validate for performance tests # so it won't stop on a test failure. # assert resp != None - # assert resp.json()["code"] == 1 if resp == None: - log.error("Test %s failed with exception." % inspect.stack()[0][3]) + _log.error("Test %s failed with exception." % inspect.stack()[0][3]) return "exception", None elif resp.status_code != 200: - log.error( + _log.error( "Test %s failed with response status code %s.", - inpsect.stack()[0][3], + inspect.stack()[0][3], resp.status_code, ) return "fail", resp.elapsed.total_seconds() elif len(resp.json()["raw_messages"]) == 0: - log.error("Test %s failed No messages returned", (inspect.stack()[0][3])) + _log.error("Test %s failed No messages returned", (inspect.stack()[0][3])) return "fail", resp.elapsed.total_seconds() else: - log.info("Test %s passed." % inspect.stack()[0][3]) + _log.info("Test %s passed (%s).", inspect.stack()[0][3], resp.status_code) return "pass", resp.elapsed.total_seconds() def test_filter_by_topic(self, base_url): - log.info("Calling %s." % inspect.stack()[0][3]) + _log.info("Calling %s: %s.", inspect.stack()[0][3], base_url) url = f"{base_url}/raw?topic=org.fedoraproject.prod.copr.chroot.start" return self._process_reponse(self.get(url)) def test_plain_raw(self, base_url): - log.info("Calling %s." % inspect.stack()[0][3]) + _log.info("Calling %s: %s.", inspect.stack()[0][3], base_url) url = f"{base_url}/raw" return self._process_reponse(self.get(url)) def test_filter_by_username(self, base_url): - log.info("Calling %s." % inspect.stack()[0][3]) + _log.info("Calling %s: %s.", inspect.stack()[0][3], base_url) url = f"{base_url}/raw?user=pingou" return self._process_reponse(self.get(url)) @@ -220,6 +144,7 @@ class TestAPI: for name, function in [ ("test_filter_by_topic", self.test_filter_by_topic), ("test_plain_raw", self.test_plain_raw), + ("test_filter_by_username", self.test_filter_by_username), ]: looped_times = 0 @@ -280,7 +205,7 @@ class TestAPI: self.tpr_mean[name] = self.sum_response_time[name] / self.pass_requests[name] # requests per second if self.start_time == 0: - log.error("stats: self.start_time is not set, skipping rps stats.") + _log.error("stats: self.start_time is not set, skipping rps stats.") else: # calc the tested time so far. tested_time = end_time - self.start_time @@ -361,22 +286,11 @@ class TestAPI: else: resp = requests.get(url, auth=auth, verify=verify) except Exception as ex: - log.error("requests.get() failed with exception:", str(ex)) + _log.error("requests.get() failed with exception:", str(ex)) return None - # pretty request and response into API log file - pretty_print_request(resp.request) - pretty_print_response_json(resp) - log_api.debug( - "response time in seconds: " + str(resp.elapsed.total_seconds()) + "\n" - ) + _log.debug("response time in seconds: %s", resp.elapsed.total_seconds()) - # This return caller function's name, not this function post. - # caller_func_name = inspect.stack()[1][3] - # if resp.status_code != 200: - # log.error('%s failed with response code %s.' %(caller_func_name,resp.status_code)) - # return None - # return resp.json() return resp