Infrastructure/arc
1
0
Fork 0
Code Issues 1 Pull requests Projects Releases Packages Wiki Activity Actions

Simplify the logging and just log to stderr for now

Browse source 
Signed-off-by: Pierre-Yves Chibon <pingou@pingoured.fr>
This commit is contained in:
Pierre-Yves Chibon 2021-01-22 13:15:05 +01:00
parent cb3e97ad10
commit 936f36ac3b
1 changed files with 18 additions and 104 deletions
Download patch file Download diff file Expand all files Collapse all files

122
scripts/test_datagrepper_perfs.py
View file

@ -19,7 +19,6 @@ import time
from datetime import datetime from datetime import datetime
import collections import collections
import logging import logging
from logging.handlers import RotatingFileHandler
import requests import requests
import json import json
import os import os
@ -37,7 +36,7 @@ import queue
if sys.version_info < (3, 7): if sys.version_info < (3, 7):
raise Exception("Requires Python 3.7 or above.") 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 is parent folder of Scripts folder (one level up)
root_path = os.path.dirname(os.path.dirname(os.path.realpath(__file__))) 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" "%(asctime)s [%(levelname)-7s][ln-%(lineno)-3d]: %(message)s"
) )
# Note: To create multiple log files, must use different logger name. handler = logging.StreamHandler(stream=sys.stderr)
def setup_logger(log_file, level=logging.INFO, name="", formatter=common_formatter): handler.setFormatter(common_formatter)
"""Function setup as many loggers as you want.""" _log.setLevel(logging.DEBUG)
handler = logging.FileHandler(log_file, mode="w") # default mode is append _log.addHandler(handler)
# 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),
)
)
class TestAPI: class TestAPI:
@ -132,7 +57,7 @@ class TestAPI:
""" """
def __init__(self): def __init__(self):
log.debug("To load test data.") _log.debug("To load test data.")
self.queue_results = queue.Queue() self.queue_results = queue.Queue()
# test start and end time # test start and end time
@ -176,36 +101,35 @@ class TestAPI:
# Convert assert for functional tests to validate for performance tests # Convert assert for functional tests to validate for performance tests
# so it won't stop on a test failure. # so it won't stop on a test failure.
# assert resp != None # assert resp != None
# assert resp.json()["code"] == 1
if resp == None: 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 return "exception", None
elif resp.status_code != 200: elif resp.status_code != 200:
log.error( _log.error(
"Test %s failed with response status code %s.", "Test %s failed with response status code %s.",
inpsect.stack()[0][3], inspect.stack()[0][3],
resp.status_code, resp.status_code,
) )
return "fail", resp.elapsed.total_seconds() return "fail", resp.elapsed.total_seconds()
elif len(resp.json()["raw_messages"]) == 0: 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() return "fail", resp.elapsed.total_seconds()
else: 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() return "pass", resp.elapsed.total_seconds()
def test_filter_by_topic(self, base_url): 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" url = f"{base_url}/raw?topic=org.fedoraproject.prod.copr.chroot.start"
return self._process_reponse(self.get(url)) return self._process_reponse(self.get(url))
def test_plain_raw(self, base_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" url = f"{base_url}/raw"
return self._process_reponse(self.get(url)) return self._process_reponse(self.get(url))
def test_filter_by_username(self, base_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" url = f"{base_url}/raw?user=pingou"
return self._process_reponse(self.get(url)) return self._process_reponse(self.get(url))
@ -220,6 +144,7 @@ class TestAPI:
for name, function in [ for name, function in [
("test_filter_by_topic", self.test_filter_by_topic), ("test_filter_by_topic", self.test_filter_by_topic),
("test_plain_raw", self.test_plain_raw), ("test_plain_raw", self.test_plain_raw),
("test_filter_by_username", self.test_filter_by_username),
]: ]:
looped_times = 0 looped_times = 0
@ -280,7 +205,7 @@ class TestAPI:
self.tpr_mean[name] = self.sum_response_time[name] / self.pass_requests[name] self.tpr_mean[name] = self.sum_response_time[name] / self.pass_requests[name]
# requests per second # requests per second
if self.start_time == 0: 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: else:
# calc the tested time so far. # calc the tested time so far.
tested_time = end_time - self.start_time tested_time = end_time - self.start_time
@ -361,22 +286,11 @@ class TestAPI:
else: else:
resp = requests.get(url, auth=auth, verify=verify) resp = requests.get(url, auth=auth, verify=verify)
except Exception as ex: except Exception as ex:
log.error("requests.get() failed with exception:", str(ex)) _log.error("requests.get() failed with exception:", str(ex))
return None return None
# pretty request and response into API log file _log.debug("response time in seconds: %s", resp.elapsed.total_seconds())
pretty_print_request(resp.request)
pretty_print_response_json(resp)
log_api.debug(
"response time in seconds: " + str(resp.elapsed.total_seconds()) + "\n"
)
# 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 return resp