From 63ff02be5065efe845d101c29275adf2488e29fc Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Fri, 24 Apr 2020 01:11:56 +0200 Subject: [PATCH 1/8] Keep track of 'parent' operation in operation loggers --- src/yunohost/log.py | 52 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 52 insertions(+) diff --git a/src/yunohost/log.py b/src/yunohost/log.py index de84280f0..20305b2c6 100644 --- a/src/yunohost/log.py +++ b/src/yunohost/log.py @@ -28,6 +28,7 @@ import os import re import yaml import collections +import glob from datetime import datetime from logging import FileHandler, getLogger, Formatter @@ -350,6 +351,8 @@ class OperationLogger(object): This class record logs and metadata like context or start time/end time. """ + _instances = [] + def __init__(self, operation, related_to=None, **kwargs): # TODO add a way to not save password on app installation self.operation = operation @@ -360,6 +363,8 @@ class OperationLogger(object): self.logger = None self._name = None self.data_to_redact = [] + self.parent = self.parent_logger() + self._instances.append(self) for filename in ["/etc/yunohost/mysql", "/etc/yunohost/psql"]: if os.path.exists(filename): @@ -370,6 +375,50 @@ class OperationLogger(object): if not os.path.exists(self.path): os.makedirs(self.path) + def parent_logger(self): + + # If there are other operation logger instances + for instance in reversed(self._instances): + # Is one of these operation logger started but not yet done ? + if instance.started_at is not None and instance.ended_at is None: + # We are a child of the first one we found + return instance.name + + locks = read_file("/var/run/moulinette_yunohost.lock").strip().split("\n") + # If we're the process with the lock, we're the root logger + if locks == [] or str(os.getpid()) in locks: + return None + + # If we get here, we are in a yunohost command called by a yunohost + # (maybe indirectly from an app script for example...) + # + # The strategy is : + # 1. list 20 most recent log files + # 2. iterate over the PID of parent processes + # 3. see if parent process has some log file open (being actively + # written in) + # 4. if among those file, there's an operation log file, we use the id + # of the most recent file + + recent_operation_logs = sorted(glob.iglob("/var/log/yunohost/categories/operation/*.log"), key=os.path.getctime, reverse=True)[:20] + + import psutil + proc = psutil.Process().parent() + while proc is not None: + # We use proc.open_files() to list files opened / actively used by this proc + # We only keep files matching a recent yunohost operation log + active_logs = sorted([f.path for f in proc.open_files() if f.path in recent_operation_logs], key=os.path.getctime, reverse=True) + if active_logs != []: + # extra the log if from the full path + return os.path.basename(active_logs[0])[:-4] + else: + proc = proc.parent() + continue + + # If nothing found, assume we're the root operation logger + return None + + def start(self): """ Start to record logs that change the system @@ -456,6 +505,7 @@ class OperationLogger(object): data = { 'started_at': self.started_at, 'operation': self.operation, + 'parent': self.parent, } if self.related_to is not None: data['related_to'] = self.related_to @@ -491,8 +541,10 @@ class OperationLogger(object): self.ended_at = datetime.utcnow() self._error = error self._success = error is None + if self.logger is not None: self.logger.removeHandler(self.file_handler) + self.file_handler.close() is_api = msettings.get('interface') == 'api' desc = _get_description_from_name(self.name) From 6c3a74c5acb0d9b001ff1f1814c7ba7d8fc1f691 Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Tue, 1 Sep 2020 17:19:50 +0200 Subject: [PATCH 2/8] Handle case where the lock doesn't exist : just assume we're the root logger --- src/yunohost/log.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/yunohost/log.py b/src/yunohost/log.py index 20305b2c6..6605d97f6 100644 --- a/src/yunohost/log.py +++ b/src/yunohost/log.py @@ -384,6 +384,12 @@ class OperationLogger(object): # We are a child of the first one we found return instance.name + # If no lock exists, we are probably in tests or yunohost is used as a + # lib ... let's not really care about that case and assume we're the + # root logger then. + if not os.path.exists("/var/run/moulinette_yunohost.lock"): + return None + locks = read_file("/var/run/moulinette_yunohost.lock").strip().split("\n") # If we're the process with the lock, we're the root logger if locks == [] or str(os.getpid()) in locks: From 624c7eaf776013871166b7a505f131dad9ec1b83 Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Tue, 1 Sep 2020 17:21:12 +0200 Subject: [PATCH 3/8] Move import to top of file --- src/yunohost/log.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/yunohost/log.py b/src/yunohost/log.py index 6605d97f6..3b0ad8c08 100644 --- a/src/yunohost/log.py +++ b/src/yunohost/log.py @@ -29,6 +29,7 @@ import re import yaml import collections import glob +import psutil from datetime import datetime from logging import FileHandler, getLogger, Formatter @@ -408,7 +409,6 @@ class OperationLogger(object): recent_operation_logs = sorted(glob.iglob("/var/log/yunohost/categories/operation/*.log"), key=os.path.getctime, reverse=True)[:20] - import psutil proc = psutil.Process().parent() while proc is not None: # We use proc.open_files() to list files opened / actively used by this proc From bd064e317e825a08bd2bd81c80f12720cd955107 Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Tue, 1 Sep 2020 17:22:07 +0200 Subject: [PATCH 4/8] Use global var --- src/yunohost/log.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/yunohost/log.py b/src/yunohost/log.py index 3b0ad8c08..73a5821c8 100644 --- a/src/yunohost/log.py +++ b/src/yunohost/log.py @@ -407,7 +407,7 @@ class OperationLogger(object): # 4. if among those file, there's an operation log file, we use the id # of the most recent file - recent_operation_logs = sorted(glob.iglob("/var/log/yunohost/categories/operation/*.log"), key=os.path.getctime, reverse=True)[:20] + recent_operation_logs = sorted(glob.iglob(OPERATIONS_PATH + "*.log"), key=os.path.getctime, reverse=True)[:20] proc = psutil.Process().parent() while proc is not None: From 9a7bd77269cad1ed788c3050e42a702ab857fb57 Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Tue, 1 Sep 2020 18:09:15 +0200 Subject: [PATCH 5/8] Get rid of unused complexity for other log categories ... it's been since 3.2 and we only have operations --- data/actionsmap/yunohost.yml | 3 -- src/yunohost/log.py | 94 +++++++++++++++--------------------- 2 files changed, 39 insertions(+), 58 deletions(-) diff --git a/data/actionsmap/yunohost.yml b/data/actionsmap/yunohost.yml index d61538c5c..d5f60d73e 100644 --- a/data/actionsmap/yunohost.yml +++ b/data/actionsmap/yunohost.yml @@ -1631,9 +1631,6 @@ log: action_help: List logs api: GET /logs arguments: - category: - help: Log category to display (default operations), could be operation, history, package, system, access, service or app - nargs: "*" -l: full: --limit help: Maximum number of logs diff --git a/src/yunohost/log.py b/src/yunohost/log.py index 353e508fd..c6a3576aa 100644 --- a/src/yunohost/log.py +++ b/src/yunohost/log.py @@ -27,7 +27,6 @@ import os import re import yaml -import collections import glob import psutil @@ -43,8 +42,6 @@ from moulinette.utils.filesystem import read_file, read_yaml CATEGORIES_PATH = '/var/log/yunohost/categories/' OPERATIONS_PATH = '/var/log/yunohost/categories/operation/' -#CATEGORIES = ['operation', 'history', 'package', 'system', 'access', 'service', 'app'] -CATEGORIES = ['operation'] METADATA_FILE_EXT = '.yml' LOG_FILE_EXT = '.log' RELATED_CATEGORIES = ['app', 'domain', 'group', 'service', 'user'] @@ -52,77 +49,67 @@ RELATED_CATEGORIES = ['app', 'domain', 'group', 'service', 'user'] logger = getActionLogger('yunohost.log') -def log_list(category=[], limit=None, with_details=False): +def log_list(limit=None, with_details=False, with_suboperations=False): """ List available logs Keyword argument: limit -- Maximum number of logs - with_details -- Include details (e.g. if the operation was a success). Likely to increase the command time as it needs to open and parse the metadata file for each log... So try to use this in combination with --limit. + with_details -- Include details (e.g. if the operation was a success). + Likely to increase the command time as it needs to open and parse the + metadata file for each log... So try to use this in combination with + --limit. """ - categories = category is_api = msettings.get('interface') == 'api' - # In cli we just display `operation` logs by default - if not categories: - categories = CATEGORIES + operations = [] - result = collections.OrderedDict() - for category in categories: - result[category] = [] + logs = filter(lambda x: x.endswith(METADATA_FILE_EXT), + os.listdir(OPERATIONS_PATH)) + logs = list(reversed(sorted(logs))) - category_path = os.path.join(CATEGORIES_PATH, category) - if not os.path.exists(category_path): - logger.debug(m18n.n('log_category_404', category=category)) - continue + if limit is not None: + logs = logs[:limit] - logs = filter(lambda x: x.endswith(METADATA_FILE_EXT), - os.listdir(category_path)) - logs = list(reversed(sorted(logs))) + for log in logs: - if limit is not None: - logs = logs[:limit] + base_filename = log[:-len(METADATA_FILE_EXT)] + md_filename = log + md_path = os.path.join(OPERATIONS_PATH, md_filename) - for log in logs: + log = base_filename.split("-") - base_filename = log[:-len(METADATA_FILE_EXT)] - md_filename = log - md_path = os.path.join(category_path, md_filename) + entry = { + "name": base_filename, + "path": md_path, + } + entry["description"] = _get_description_from_name(base_filename) + try: + log_datetime = datetime.strptime(" ".join(log[:2]), + "%Y%m%d %H%M%S") + except ValueError: + pass + else: + entry["started_at"] = log_datetime - log = base_filename.split("-") - - entry = { - "name": base_filename, - "path": md_path, - } - entry["description"] = _get_description_from_name(base_filename) + if with_details: try: - log_datetime = datetime.strptime(" ".join(log[:2]), - "%Y%m%d %H%M%S") - except ValueError: - pass - else: - entry["started_at"] = log_datetime + metadata = read_yaml(md_path) + except Exception as e: + # If we can't read the yaml for some reason, report an error and ignore this entry... + logger.error(m18n.n('log_corrupted_md_file', md_file=md_path, error=e)) + continue + entry["success"] = metadata.get("success", "?") if metadata else "?" - if with_details: - try: - metadata = read_yaml(md_path) - except Exception as e: - # If we can't read the yaml for some reason, report an error and ignore this entry... - logger.error(m18n.n('log_corrupted_md_file', md_file=md_path, error=e)) - continue - entry["success"] = metadata.get("success", "?") if metadata else "?" - - result[category].append(entry) + operations.append(entry) # Reverse the order of log when in cli, more comfortable to read (avoid # unecessary scrolling) if not is_api: - for category in result: - result[category] = list(reversed(result[category])) + operations = list(reversed(operations)) - return result + return {"operation": operations} def log_display(path, number=None, share=False, filter_irrelevant=False): @@ -165,10 +152,7 @@ def log_display(path, number=None, share=False, filter_irrelevant=False): abs_path = path log_path = None if not path.startswith('/'): - for category in CATEGORIES: - abs_path = os.path.join(CATEGORIES_PATH, category, path) - if os.path.exists(abs_path) or os.path.exists(abs_path + METADATA_FILE_EXT): - break + abs_path = os.path.join(OPERATIONS_PATH, path) if os.path.exists(abs_path) and not path.endswith(METADATA_FILE_EXT): log_path = abs_path From 8831c638e64949a89f445f37d494f30c50d503c3 Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Wed, 2 Sep 2020 19:33:48 +0200 Subject: [PATCH 6/8] Add options to include metadata about suboperations --- data/actionsmap/yunohost.yml | 11 +++- src/yunohost/log.py | 110 +++++++++++++++++++++++++++-------- 2 files changed, 96 insertions(+), 25 deletions(-) diff --git a/data/actionsmap/yunohost.yml b/data/actionsmap/yunohost.yml index d5f60d73e..129dbe0a9 100644 --- a/data/actionsmap/yunohost.yml +++ b/data/actionsmap/yunohost.yml @@ -1633,12 +1633,17 @@ log: arguments: -l: full: --limit - help: Maximum number of logs + help: Maximum number of operations to list (default to 50) type: int + default: 50 -d: full: --with-details help: Show additional infos (e.g. operation success) but may significantly increase command time. Consider using --limit in combination with this. action: store_true + -s: + full: --with-suboperations + help: Include metadata about operations that are not the main operation but are sub-operations triggered by another ongoing operation... (e.g. initializing groups/permissions when installing an app) + action: store_true ### log_display() display: @@ -1659,6 +1664,10 @@ log: full: --filter-irrelevant help: Do not show some lines deemed not relevant (like set +x or helper argument parsing) action: store_true + -s: + full: --with-suboperations + help: Include metadata about sub-operations of this operation... (e.g. initializing groups/permissions when installing an app) + action: store_true ############################# diff --git a/src/yunohost/log.py b/src/yunohost/log.py index c6a3576aa..df2b0c195 100644 --- a/src/yunohost/log.py +++ b/src/yunohost/log.py @@ -30,7 +30,7 @@ import yaml import glob import psutil -from datetime import datetime +from datetime import datetime, timedelta from logging import FileHandler, getLogger, Formatter from moulinette import m18n, msettings @@ -57,13 +57,13 @@ def log_list(limit=None, with_details=False, with_suboperations=False): limit -- Maximum number of logs with_details -- Include details (e.g. if the operation was a success). Likely to increase the command time as it needs to open and parse the - metadata file for each log... So try to use this in combination with - --limit. + metadata file for each log... + with_suboperations -- Include operations that are not the "main" + operation but are sub-operations triggered by another ongoing operation + ... (e.g. initializing groups/permissions when installing an app) """ - is_api = msettings.get('interface') == 'api' - - operations = [] + operations = {} logs = filter(lambda x: x.endswith(METADATA_FILE_EXT), os.listdir(OPERATIONS_PATH)) @@ -75,44 +75,62 @@ def log_list(limit=None, with_details=False, with_suboperations=False): for log in logs: base_filename = log[:-len(METADATA_FILE_EXT)] - md_filename = log - md_path = os.path.join(OPERATIONS_PATH, md_filename) - - log = base_filename.split("-") + md_path = os.path.join(OPERATIONS_PATH, log) entry = { "name": base_filename, "path": md_path, + "description": _get_description_from_name(base_filename), } - entry["description"] = _get_description_from_name(base_filename) + try: - log_datetime = datetime.strptime(" ".join(log[:2]), - "%Y%m%d %H%M%S") + entry["started_at"] = _get_datetime_from_name(base_filename) except ValueError: pass - else: - entry["started_at"] = log_datetime + + try: + metadata = read_yaml(md_path) + except Exception as e: + # If we can't read the yaml for some reason, report an error and ignore this entry... + logger.error(m18n.n('log_corrupted_md_file', md_file=md_path, error=e)) + continue if with_details: - try: - metadata = read_yaml(md_path) - except Exception as e: - # If we can't read the yaml for some reason, report an error and ignore this entry... - logger.error(m18n.n('log_corrupted_md_file', md_file=md_path, error=e)) - continue entry["success"] = metadata.get("success", "?") if metadata else "?" + entry["parent"] = metadata.get("parent") - operations.append(entry) + if with_suboperations: + entry["parent"] = metadata.get("parent") + entry["suboperations"] = [] + elif metadata.get("parent") is not None: + continue + + operations[base_filename] = entry + + # When displaying suboperations, we build a tree-like structure where + # "suboperations" is a list of suboperations (each of them may also have a list of + # "suboperations" suboperations etc... + if with_suboperations: + suboperations = [o for o in operations.values() if o["parent"] is not None] + for suboperation in suboperations: + parent = operations.get(suboperation["parent"]) + if not parent: + continue + parent["suboperations"].append(suboperation) + operations = list(reversed(sorted([o for o in operations.values() if o["parent"] is None], key=lambda o: o["name"]))) + else: + operations = [o for o in operations.values()] # Reverse the order of log when in cli, more comfortable to read (avoid # unecessary scrolling) + is_api = msettings.get('interface') == 'api' if not is_api: operations = list(reversed(operations)) return {"operation": operations} -def log_display(path, number=None, share=False, filter_irrelevant=False): +def log_display(path, number=None, share=False, filter_irrelevant=False, with_suboperations=False): """ Display a log file enriched with metadata if any. @@ -211,6 +229,42 @@ def log_display(path, number=None, share=False, filter_irrelevant=False): if 'log_path' in metadata: log_path = metadata['log_path'] + if with_suboperations: + + def suboperations(): + try: + log_start = _get_datetime_from_name(base_filename) + except ValueError: + return + + for filename in os.listdir(OPERATIONS_PATH): + + if not filename.endswith(METADATA_FILE_EXT): + continue + + # We first retrict search to a ~48h time window to limit the number + # of .yml we look into + try: + date = _get_datetime_from_name(base_filename) + except ValueError: + continue + if (date < log_start) or (date > log_start + timedelta(hours=48)): + continue + + try: + submetadata = read_yaml(os.path.join(OPERATIONS_PATH, filename)) + except Exception: + continue + + if submetadata.get("parent") == base_filename: + yield { + "name": filename[:-len(METADATA_FILE_EXT)], + "description": _get_description_from_name(filename), + "success": submetadata.get("success", "?") + } + + metadata["suboperations"] = list(suboperations()) + # Display logs if exist if os.path.exists(log_path): from yunohost.service import _tail @@ -418,7 +472,6 @@ class OperationLogger(object): # If nothing found, assume we're the root operation logger return None - def start(self): """ Start to record logs that change the system @@ -578,6 +631,15 @@ class OperationLogger(object): self.error(m18n.n('log_operation_unit_unclosed_properly')) +def _get_datetime_from_name(name): + + # Filenames are expected to follow the format: + # 20200831-170740-short_description-and-stuff + + raw_datetime = " ".join(name.split("-")[:2]) + return datetime.strptime(raw_datetime, "%Y%m%d %H%M%S") + + def _get_description_from_name(name): """ Return the translated description from the filename From 7edd3ff84037220afa61a8c00fe1662ad011aa91 Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Wed, 2 Sep 2020 20:30:50 +0200 Subject: [PATCH 7/8] Minor fixes after tests.. --- src/yunohost/log.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/yunohost/log.py b/src/yunohost/log.py index df2b0c195..58205d49c 100644 --- a/src/yunohost/log.py +++ b/src/yunohost/log.py @@ -117,10 +117,11 @@ def log_list(limit=None, with_details=False, with_suboperations=False): if not parent: continue parent["suboperations"].append(suboperation) - operations = list(reversed(sorted([o for o in operations.values() if o["parent"] is None], key=lambda o: o["name"]))) + operations = [o for o in operations.values() if o["parent"] is None] else: operations = [o for o in operations.values()] + operations = list(reversed(sorted(operations, key=lambda o: o["name"]))) # Reverse the order of log when in cli, more comfortable to read (avoid # unecessary scrolling) is_api = msettings.get('interface') == 'api' @@ -259,7 +260,7 @@ def log_display(path, number=None, share=False, filter_irrelevant=False, with_su if submetadata.get("parent") == base_filename: yield { "name": filename[:-len(METADATA_FILE_EXT)], - "description": _get_description_from_name(filename), + "description": _get_description_from_name(filename[:-len(METADATA_FILE_EXT)]), "success": submetadata.get("success", "?") } From 88997f5728981358cfc1802a65dcd9b2ec654621 Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Wed, 2 Sep 2020 20:57:51 +0200 Subject: [PATCH 8/8] Small old issue where the number of line filtered doesnt match the requested number, and then the admin doesn't display the 'show more line' button.. --- src/yunohost/log.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/src/yunohost/log.py b/src/yunohost/log.py index 58205d49c..892105c6b 100644 --- a/src/yunohost/log.py +++ b/src/yunohost/log.py @@ -269,11 +269,15 @@ def log_display(path, number=None, share=False, filter_irrelevant=False, with_su # Display logs if exist if os.path.exists(log_path): from yunohost.service import _tail - if number: + if number and filters: + logs = _tail(log_path, int(number*4)) + elif number: logs = _tail(log_path, int(number)) else: logs = read_file(log_path) logs = _filter_lines(logs, filters) + if number: + logs = logs[-number:] infos['log_path'] = log_path infos['logs'] = logs