From 2f4aaaa4f0e721312164252931954dc6db28abe1 Mon Sep 17 00:00:00 2001 From: gallardo Date: Mon, 31 Jan 2022 16:50:48 +0000 Subject: [PATCH] Add log to trace task workflow Change-Id: I7f65766ca22dad2f9cc3d2968bc10bc8f7a2779d Signed-off-by: gallardo --- NG-RO/osm_ng_ro/ns_thread.py | 169 +++++++++++++++++++++++++++++++++++ 1 file changed, 169 insertions(+) diff --git a/NG-RO/osm_ng_ro/ns_thread.py b/NG-RO/osm_ng_ro/ns_thread.py index dbd9fe69..b8b242ca 100644 --- a/NG-RO/osm_ng_ro/ns_thread.py +++ b/NG-RO/osm_ng_ro/ns_thread.py @@ -1501,6 +1501,24 @@ class NsWorker(threading.Thread): try: while True: + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + self._log_ro_task( + None, + None, + None, + "TASK_WF", + "task_locked_time=" + + str(self.task_locked_time) + + " " + + "time_last_task_processed=" + + str(self.time_last_task_processed) + + " " + + "now=" + + str(now), + ) + """ locked = self.db.set_one( "ro_tasks", q_filter={ @@ -1541,6 +1559,128 @@ class NsWorker(threading.Thread): return None + def _get_db_all_tasks(self): + """ + Read all content of table ro_tasks to log it + :return: None + """ + try: + # Checking the content of the BD: + + # read and return + ro_task = self.db.get_list("ro_tasks") + for rt in ro_task: + self._log_ro_task(rt, None, None, "TASK_WF", "GET_ALL_TASKS") + return ro_task + + except DbException as e: + self.logger.error("Database exception at _get_db_all_tasks: {}".format(e)) + except Exception as e: + self.logger.critical( + "Unexpected exception at _get_db_all_tasks: {}".format(e), exc_info=True + ) + + return None + + def _log_ro_task(self, ro_task, db_ro_task_update, db_ro_task_delete, mark, event): + """ + Generate a log with the following format: + + Mark;Event;ro_task_id;locked_at;modified_at;created_at;to_check_at;locked_by; + target_id;vim_info.refresh_at;vim_info;no_of_tasks;task_status;action_id; + task_array_index;task_id;task_action;task_item;task_args + + Example: + + TASK_WF;GET_TASK;888f1864-749a-4fc2-bc1a-97c0fffd6a6f:2;1642158724.8210013; + 1642158640.7986135;1642158640.7986135;1642158640.7986135;b134c9494e75:0a + ;vim:b7ff9e24-8868-4d68-8a57-a59dc11d0327;None;{'created': False, + 'created_items': None, 'vim_id': None, 'vim_name': None, 'vim_status': None, + 'vim_details': None, 'refresh_at': None};1;SCHEDULED; + 888f1864-749a-4fc2-bc1a-97c0fffd6a6f;0;888f1864-749a-4fc2-bc1a-97c0fffd6a6f:2; + CREATE;image;{'filter_dict': {'name': 'ubuntu-os-cloud:image-family:ubuntu-1804-lts'}} + """ + try: + line = [] + i = 0 + if ro_task is not None and isinstance(ro_task, dict): + for t in ro_task["tasks"]: + line.clear() + line.append(mark) + line.append(event) + line.append(ro_task.get("_id", "")) + line.append(str(ro_task.get("locked_at", ""))) + line.append(str(ro_task.get("modified_at", ""))) + line.append(str(ro_task.get("created_at", ""))) + line.append(str(ro_task.get("to_check_at", ""))) + line.append(str(ro_task.get("locked_by", ""))) + line.append(str(ro_task.get("target_id", ""))) + line.append(str(ro_task.get("vim_info", {}).get("refresh_at", ""))) + line.append(str(ro_task.get("vim_info", ""))) + line.append(str(ro_task.get("tasks", ""))) + if isinstance(t, dict): + line.append(str(t.get("status", ""))) + line.append(str(t.get("action_id", ""))) + line.append(str(i)) + line.append(str(t.get("task_id", ""))) + line.append(str(t.get("action", ""))) + line.append(str(t.get("item", ""))) + line.append(str(t.get("find_params", ""))) + line.append(str(t.get("params", ""))) + else: + line.extend([""] * 2) + line.append(str(i)) + line.extend([""] * 5) + + i += 1 + self.logger.debug(";".join(line)) + elif db_ro_task_update is not None and isinstance(db_ro_task_update, dict): + i = 0 + while True: + st = "tasks.{}.status".format(i) + if st not in db_ro_task_update: + break + line.clear() + line.append(mark) + line.append(event) + line.append(db_ro_task_update.get("_id", "")) + line.append(str(db_ro_task_update.get("locked_at", ""))) + line.append(str(db_ro_task_update.get("modified_at", ""))) + line.append("") + line.append(str(db_ro_task_update.get("to_check_at", ""))) + line.append(str(db_ro_task_update.get("locked_by", ""))) + line.append("") + line.append(str(db_ro_task_update.get("vim_info.refresh_at", ""))) + line.append("") + line.append(str(db_ro_task_update.get("vim_info", ""))) + line.append(str(str(db_ro_task_update).count(".status"))) + line.append(db_ro_task_update.get(st, "")) + line.append("") + line.append(str(i)) + line.extend([""] * 3) + i += 1 + self.logger.debug(";".join(line)) + + elif db_ro_task_delete is not None and isinstance(db_ro_task_delete, dict): + line.clear() + line.append(mark) + line.append(event) + line.append(db_ro_task_delete.get("_id", "")) + line.append("") + line.append(db_ro_task_delete.get("modified_at", "")) + line.extend([""] * 13) + self.logger.debug(";".join(line)) + + else: + line.clear() + line.append(mark) + line.append(event) + line.extend([""] * 16) + self.logger.debug(";".join(line)) + + except Exception as e: + self.logger.error("Error logging ro_task: {}".format(e)) + def _delete_task(self, ro_task, task_index, task_depends, db_update): """ Determine if this task need to be done or superseded @@ -1713,6 +1853,11 @@ class NsWorker(threading.Thread): ro_task["vim_info"]["refresh_at"] = next_refresh try: + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + self._log_ro_task(ro_task, None, None, "TASK_WF", "GET_TASK") + """ # 0: get task_status_create lock_object = None task_status_create = None @@ -1963,6 +2108,14 @@ class NsWorker(threading.Thread): db_ro_task_update["modified_at"] = now db_ro_task_update["to_check_at"] = next_check_at + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + db_ro_task_update_log = db_ro_task_update.copy() + db_ro_task_update_log["_id"] = q_filter["_id"] + self._log_ro_task(None, db_ro_task_update_log, None, "TASK_WF", "SET_TASK") + """ + if not self.db.set_one( "ro_tasks", update_dict=db_ro_task_update, @@ -1971,6 +2124,17 @@ class NsWorker(threading.Thread): ): del db_ro_task_update["to_check_at"] del q_filter["to_check_at"] + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + self._log_ro_task( + None, + db_ro_task_update_log, + None, + "TASK_WF", + "SET_TASK " + str(q_filter), + ) + """ self.db.set_one( "ro_tasks", q_filter=q_filter, @@ -2185,6 +2349,11 @@ class NsWorker(threading.Thread): if self.tasks_to_delete: self._process_delete_db_tasks() busy = False + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + _ = self._get_db_all_tasks() + """ ro_task = self._get_db_task() if ro_task: self._process_pending_tasks(ro_task) -- 2.17.1