Improve logging to contain action duration
The log so far did not contain direct information of the duration
an action took to run. It could only be calculated indirectly from the
time stamps.
This change measures the time the execution of an action took and adds
it to the logging message in milliseconds.
Change-Id: I070a54be315927bebdc944ebbe538e05401c9611
diff --git a/container/tools/actions/abstract.py b/container/tools/actions/abstract.py
index 70d1694..14d53bd 100644
--- a/container/tools/actions/abstract.py
+++ b/container/tools/actions/abstract.py
@@ -16,6 +16,8 @@
import logging
import traceback
+from datetime import datetime
+
import numpy as np
# pylint: disable=W0703
@@ -32,13 +34,22 @@
def execute(self):
if self._is_executed():
- self.log.debug("Executing %s", self.__class__.__name__)
+ self.log.debug("%s STARTED", self.__class__.__name__)
try:
- return self._execute_action()
+ start = datetime.utcnow()
+ result = self._execute_action()
+ self._log_result(
+ duration=datetime.utcnow() - start,
+ message=self._create_log_message(),
+ )
+ return result
except Exception:
self.failed = True
- self._log_result(traceback.format_exc().replace("\n", " "))
+ self._log_result(
+ duration=datetime.utcnow() - start,
+ message=traceback.format_exc().replace("\n", " "),
+ )
return None
@@ -46,11 +57,16 @@
def _execute_action(self):
pass
- def _log_result(self, message=""):
+ @abc.abstractmethod
+ def _create_log_message(self):
+ pass
+
+ def _log_result(self, duration=0, message=""):
self.log.info(
- "%s %s %s",
+ "%s %s %.2f %s",
self.__class__.__name__,
"FAILED" if self.failed else "OK",
+ duration.total_seconds() * 1000,
message,
)
diff --git a/container/tools/actions/abstract_push.py b/container/tools/actions/abstract_push.py
index b03520c..083fcba 100644
--- a/container/tools/actions/abstract_push.py
+++ b/container/tools/actions/abstract_push.py
@@ -30,6 +30,7 @@
self.local_repo_path = os.path.join("/tmp", self.project_name)
self.repo = git.Repo(self.local_repo_path)
self.refspec = refspec
+ self.num_commits = random.randint(1, 5)
@abc.abstractmethod
def _prepare(self):
@@ -39,15 +40,17 @@
self.repo.git.checkout("origin/master")
self._prepare()
if os.path.exists(self.local_repo_path):
- num_commits = random.randint(1, 5)
- for _ in range(num_commits):
+ for _ in range(self.num_commits):
self._create_commit()
self.repo.remotes.origin.push(refspec=self.refspec)
self.was_executed = True
- self._log_result(
- "Pushed %d commits to project %s using refspec %s"
- % (num_commits, self.project_name, self.refspec)
- )
+
+ def _create_log_message(self):
+ return "Pushed %d commits to project %s using refspec %s" % (
+ self.num_commits,
+ self.project_name,
+ self.refspec,
+ )
def _create_commit(self):
change_type_choice = random.choice(self.change_types)
diff --git a/container/tools/actions/clone_project.py b/container/tools/actions/clone_project.py
index cdbb714..e421611 100644
--- a/container/tools/actions/clone_project.py
+++ b/container/tools/actions/clone_project.py
@@ -34,7 +34,9 @@
git.Repo.clone_from(self._assemble_url(), local_repo_path)
self._install_commit_hook()
self.was_executed = True
- self._log_result(self.project_name)
+
+ def _create_log_message(self):
+ return self.project_name
def _install_commit_hook(self):
hook_path = os.path.join("/tmp", self.project_name, ".git/hooks/commit-msg")
diff --git a/container/tools/actions/create_project.py b/container/tools/actions/create_project.py
index 5c8eece..5547ed0 100644
--- a/container/tools/actions/create_project.py
+++ b/container/tools/actions/create_project.py
@@ -33,7 +33,9 @@
rest_url, auth=(self.user, self.pwd), json={"create_empty_commit": "true"}
)
self.was_executed = True
- self._log_result(self.project_name)
+ return self.project_name
+
+ def _create_log_message(self):
return self.project_name
def _assemble_url(self):
diff --git a/container/tools/actions/fetch_project.py b/container/tools/actions/fetch_project.py
index 9d6e416..52adb3f 100644
--- a/container/tools/actions/fetch_project.py
+++ b/container/tools/actions/fetch_project.py
@@ -33,4 +33,6 @@
for remote in repo.remotes:
remote.fetch()
self.was_executed = True
- self._log_result(self.project_name)
+
+ def _create_log_message(self):
+ return self.project_name
diff --git a/container/tools/actions/query_change_files.py b/container/tools/actions/query_change_files.py
index 0c4b027..3463d90 100644
--- a/container/tools/actions/query_change_files.py
+++ b/container/tools/actions/query_change_files.py
@@ -24,12 +24,15 @@
super().__init__(url, user, pwd, probability)
self.change_id = change_id
self.revision_id = revision_id
+ self.files = list()
def _execute_action(self):
response = requests.get(self._assemble_url(), auth=(self.user, self.pwd))
- files = list(json.loads(response.text.split("\n", 1)[1]).keys())
- self._log_result(files)
- return files
+ self.files = list(json.loads(response.text.split("\n", 1)[1]).keys())
+ return self.files
+
+ def _create_log_message(self):
+ return self.files
def _assemble_url(self):
return "%s/a/changes/%s/revisions/%s/files" % (
diff --git a/container/tools/actions/query_hundred_open_changes.py b/container/tools/actions/query_hundred_open_changes.py
index 95664e1..665dd8a 100644
--- a/container/tools/actions/query_hundred_open_changes.py
+++ b/container/tools/actions/query_hundred_open_changes.py
@@ -21,13 +21,19 @@
class QueryHundredOpenChanges(abstract.AbstractAction):
+ def __init__(self, url, user, pwd, probability=1.0):
+ super().__init__(url, user, pwd, probability=probability)
+ self.change = dict()
+
def _execute_action(self):
rest_url = self._assemble_url()
response = requests.get(rest_url, auth=(self.user, self.pwd))
self.was_executed = True
- change = random.choice(json.loads(response.text.split("\n", 1)[1]))
- self._log_result(change["change_id"])
- return change
+ self.change = random.choice(json.loads(response.text.split("\n", 1)[1]))
+ return self.change
+
+ def _create_log_message(self):
+ return self.change["change_id"]
def _assemble_url(self):
return "%s/a/changes/?q=status:open&n=100" % (self.url)
diff --git a/container/tools/actions/query_projects.py b/container/tools/actions/query_projects.py
index 5205a87..2fb6f4b 100644
--- a/container/tools/actions/query_projects.py
+++ b/container/tools/actions/query_projects.py
@@ -23,17 +23,22 @@
class QueryProjectsAction(abstract.AbstractAction):
+ def __init__(self, url, user, pwd, probability=1.0):
+ super().__init__(url, user, pwd, probability=probability)
+ self.selected_project = None
+
def _execute_action(self):
- selected_project = None
rest_url = self._assemble_url()
response = requests.get(rest_url, auth=(self.user, self.pwd))
self.was_executed = True
projects = list(json.loads(response.text.split("\n", 1)[1]).keys())
for project in DISALLOWED_PROJECTS:
projects.remove(project)
- selected_project = random.choice(projects)
- self._log_result(selected_project)
- return selected_project
+ self.selected_project = random.choice(projects)
+ return self.selected_project
+
+ def _create_log_message(self):
+ return self.selected_project
def _assemble_url(self):
return "%s/a/projects/?d" % (self.url)
diff --git a/container/tools/actions/review_change.py b/container/tools/actions/review_change.py
index 1e20e78..c1742d3 100644
--- a/container/tools/actions/review_change.py
+++ b/container/tools/actions/review_change.py
@@ -32,7 +32,9 @@
rest_url = self._assemble_review_url()
requests.post(rest_url, auth=(self.user, self.pwd), json=self._assemble_body())
self.was_executed = True
- self._log_result()
+
+ def _create_log_message(self):
+ return self.change_id
def _get_change_id(self):
try:
diff --git a/kubernetes/efk/fluentbit.yaml b/kubernetes/efk/fluentbit.yaml
index c744ed2..1d6164d 100644
--- a/kubernetes/efk/fluentbit.yaml
+++ b/kubernetes/efk/fluentbit.yaml
@@ -14,6 +14,12 @@
enabled: true
regex:
- name: loadtester
- regex: '^(?<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2},\d{3})\s(?<action>[^\s]+)\s(?<result>(?:OK)|(?:FAILED))\s(?<message>.*)$'
+ regex: '^(?<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2},\d{3})\s(?<action>[^\s]+)\s(?<status>[A-Z]+)\s?(?<duration>[0-9\.]*)\s?(?<message>.*)$'
timeKey: time
timeFormat: "%Y-%d-%m %H:%M:%S.%f"
+
+extraEntries:
+ filter: |-
+ [FILTER]
+ Name modify
+ Match mem.*
