From 972bb5a92099ce82c9b777a5040f094b13208241 Mon Sep 17 00:00:00 2001 From: meow Date: Mon, 23 Dec 2019 12:58:04 +0500 Subject: [PATCH] - Better error reporting. - Flask now uses application's logger instead of its own. - ucloud file scanner refactored. --- scripts/ucloud | 29 ++------ setup.py | 1 + ucloud/api/helper.py | 3 +- ucloud/api/main.py | 32 ++++++++- ucloud/common/etcd_wrapper.py | 2 +- ucloud/common/logging.py | 24 +++++++ ucloud/common/storage_handlers.py | 30 ++++++--- ucloud/filescanner/main.py | 107 ++++++++++-------------------- ucloud/host/main.py | 5 +- ucloud/host/virtualmachine.py | 25 +------ ucloud/imagescanner/main.py | 27 ++++---- ucloud/metadata/__init__.py | 3 + ucloud/metadata/main.py | 15 +++++ ucloud/settings/__init__.py | 8 +-- 14 files changed, 157 insertions(+), 154 deletions(-) create mode 100644 ucloud/common/logging.py diff --git a/scripts/ucloud b/scripts/ucloud index 0a6c5ec..5e8bce6 100755 --- a/scripts/ucloud +++ b/scripts/ucloud @@ -6,44 +6,23 @@ import importlib import multiprocessing as mp import sys -import colorama - from logging.handlers import SysLogHandler from ucloud.configure.main import configure_parser +from ucloud.common.logging import NoTracebackStreamHandler def exception_hook(exc_type, exc_value, exc_traceback): + logger = logging.getLogger(__name__) logger.error( 'Uncaught exception', exc_info=(exc_type, exc_value, exc_traceback) ) - # print('Error: ', end='') - # print(exc_type, exc_value, exc_traceback) -class NoTracebackStreamHandler(logging.StreamHandler): - def handle(self, record): - info, cache = record.exc_info, record.exc_text - record.exc_info, record.exc_text = None, None - - if record.levelname == 'WARNING': - color = colorama.Fore.YELLOW - elif record.levelname == 'ERROR': - color = colorama.Fore.LIGHTRED_EX - else: - color = colorama.Fore.RED - try: - print(color) - super().handle(record) - finally: - record.exc_info = info - record.exc_text = cache - print(colorama.Style.RESET_ALL) +sys.excepthook = exception_hook if __name__ == '__main__': - sys.excepthook = exception_hook - arg_parser = argparse.ArgumentParser() subparsers = arg_parser.add_subparsers(dest="command") @@ -68,7 +47,7 @@ if __name__ == '__main__': arg_parser.print_help() else: # Setting up root logger - logger = logging.getLogger('ucloud') + logger = logging.getLogger(__name__) syslog_handler = SysLogHandler(address='/dev/log') syslog_handler.setLevel(logging.DEBUG) diff --git a/setup.py b/setup.py index b4341d3..2c1c2cb 100644 --- a/setup.py +++ b/setup.py @@ -40,6 +40,7 @@ setup(name='ucloud', 'colorama', 'sphinx-rtd-theme', 'etcd3 @ https://github.com/kragniz/python-etcd3/tarball/master#egg=etcd3', + 'werkzeug' ], scripts=['scripts/ucloud'], data_files=[(os.path.expanduser('~/ucloud/'), ['conf/ucloud.conf'])], diff --git a/ucloud/api/helper.py b/ucloud/api/helper.py index 9cda36e..e275e46 100755 --- a/ucloud/api/helper.py +++ b/ucloud/api/helper.py @@ -10,7 +10,8 @@ from pyotp import TOTP from ucloud.shared import shared from ucloud.settings import settings -logger = logging.getLogger("ucloud.api.helper") +logger = logging.getLogger(__name__) + def check_otp(name, realm, token): try: diff --git a/ucloud/api/main.py b/ucloud/api/main.py index 05972ff..92c73f5 100644 --- a/ucloud/api/main.py +++ b/ucloud/api/main.py @@ -1,11 +1,14 @@ import json import pynetbox +import logging +import urllib3 from uuid import uuid4 from os.path import join as join_path from flask import Flask, request from flask_restful import Resource, Api +from werkzeug.exceptions import HTTPException from ucloud.common import counters from ucloud.common.vm import VMStatus @@ -15,10 +18,33 @@ from ucloud.shared import shared from . import schemas from .helper import generate_mac, mac2ipv6 -from . import logger + + +def get_parent(obj, attr): + parent = getattr(obj, attr) + child = parent + while parent is not None: + child = parent + parent = getattr(parent, attr) + return child + + +logger = logging.getLogger(__name__) app = Flask(__name__) api = Api(app) +app.logger.handlers.clear() + + +@app.errorhandler(Exception) +def handle_exception(e): + app.logger.error(e) + # pass through HTTP errors + if isinstance(e, HTTPException): + return e + + # now you're handling non-HTTP exceptions only + return {'message': 'Server Error'}, 500 class CreateVM(Resource): @@ -438,8 +464,8 @@ class CreateNetwork(Resource): "is_pool": True, } ) - except Exception: - logger.exception("Exception occur while contacting netbox") + except Exception as err: + app.logger.error(err) return {"message": "Error occured while creating network."} else: network_entry["ipv6"] = prefix["prefix"] diff --git a/ucloud/common/etcd_wrapper.py b/ucloud/common/etcd_wrapper.py index 91149b8..eecf4c7 100644 --- a/ucloud/common/etcd_wrapper.py +++ b/ucloud/common/etcd_wrapper.py @@ -27,7 +27,7 @@ def readable_errors(func): @wraps(func) def wrapper(*args, **kwargs): try: - func(*args, **kwargs) + return func(*args, **kwargs) except etcd3.exceptions.ConnectionFailedError as err: raise etcd3.exceptions.ConnectionFailedError('etcd connection failed') from err except etcd3.exceptions.ConnectionTimeoutError as err: diff --git a/ucloud/common/logging.py b/ucloud/common/logging.py new file mode 100644 index 0000000..945f473 --- /dev/null +++ b/ucloud/common/logging.py @@ -0,0 +1,24 @@ +import logging +import colorama + + +class NoTracebackStreamHandler(logging.StreamHandler): + def handle(self, record): + info, cache = record.exc_info, record.exc_text + record.exc_info, record.exc_text = None, None + + if record.levelname == 'WARNING': + color = colorama.Fore.YELLOW + elif record.levelname in ['ERROR', 'EXCEPTION']: + color = colorama.Fore.LIGHTRED_EX + elif record.levelname == 'INFO': + color = colorama.Fore.LIGHTBLUE_EX + else: + color = colorama.Fore.WHITE + try: + print(color, end='', flush=True) + super().handle(record) + finally: + record.exc_info = info + record.exc_text = cache + print(colorama.Style.RESET_ALL, end='', flush=True) diff --git a/ucloud/common/storage_handlers.py b/ucloud/common/storage_handlers.py index eaad1a5..4b7928e 100644 --- a/ucloud/common/storage_handlers.py +++ b/ucloud/common/storage_handlers.py @@ -11,6 +11,8 @@ from ucloud.settings import settings as config class ImageStorageHandler(ABC): + handler_name = 'base' + def __init__(self, image_base, vm_base): self.image_base = image_base self.vm_base = vm_base @@ -45,13 +47,17 @@ class ImageStorageHandler(ABC): def delete_vm_image(self, path): raise NotImplementedError() - def execute_command(self, command, report=True): + def execute_command(self, command, report=True, error_origin=None): + if not error_origin: + error_origin = self.handler_name + command = list(map(str, command)) try: - output = sp.check_output(command, stderr=sp.PIPE) - except Exception as e: + sp.check_output(command, stderr=sp.PIPE) + except sp.CalledProcessError as e: + _stderr = e.stderr.decode('utf-8').strip() if report: - logger.exception(e) + logger.exception('%s:- %s', error_origin, _stderr) return False return True @@ -66,6 +72,8 @@ class ImageStorageHandler(ABC): class FileSystemBasedImageStorageHandler(ImageStorageHandler): + handler_name = 'Filesystem' + def import_image(self, src, dest, protect=False): dest = join_path(self.image_base, dest) try: @@ -118,17 +126,23 @@ class FileSystemBasedImageStorageHandler(ImageStorageHandler): class CEPHBasedImageStorageHandler(ImageStorageHandler): + handler_name = 'Ceph' + def import_image(self, src, dest, protect=False): dest = join_path(self.image_base, dest) - command = ["rbd", "import", src, dest] + import_command = ["rbd", "import", src, dest] + commands = [import_command] if protect: snap_create_command = ["rbd", "snap", "create", "{}@protected".format(dest)] snap_protect_command = ["rbd", "snap", "protect", "{}@protected".format(dest)] + commands.append(snap_create_command) + commands.append(snap_protect_command) - return self.execute_command(command) and self.execute_command(snap_create_command) and\ - self.execute_command(snap_protect_command) + result = True + for command in commands: + result = result and self.execute_command(command) - return self.execute_command(command) + return result def make_vm_image(self, src, dest): src = join_path(self.image_base, src) diff --git a/ucloud/filescanner/main.py b/ucloud/filescanner/main.py index ff38748..778e942 100755 --- a/ucloud/filescanner/main.py +++ b/ucloud/filescanner/main.py @@ -3,7 +3,6 @@ import os import pathlib import subprocess as sp import time -import sys from uuid import uuid4 @@ -11,30 +10,6 @@ from . import logger from ucloud.settings import settings from ucloud.shared import shared -def getxattr(file, attr): - """Get specified user extended attribute (arg:attr) of a file (arg:file)""" - try: - attr = "user." + attr - value = sp.check_output(['getfattr', file, - '--name', attr, - '--only-values', - '--absolute-names'], stderr=sp.DEVNULL) - value = value.decode("utf-8") - except sp.CalledProcessError as e: - value = None - - return value - - -def setxattr(file, attr, value): - """Set specified user extended attribute (arg:attr) equal to (arg:value) - of a file (arg:file)""" - - attr = "user." + attr - sp.check_output(['setfattr', file, - '--name', attr, - '--value', str(value)]) - def sha512sum(file: str): """Use sha512sum utility to compute sha512 sum of arg:file @@ -60,12 +35,33 @@ def sha512sum(file: str): return None -try: - sp.check_output(['which', 'getfattr']) - sp.check_output(['which', 'setfattr']) -except Exception as e: - logger.error("You don't seems to have both getfattr and setfattr") - sys.exit(1) +def track_file(file, base_dir): + file_id = uuid4() + + # Get Username + owner = pathlib.Path(file).parts[len(pathlib.Path(base_dir).parts)] + + # Get Creation Date of File + # Here, we are assuming that ctime is creation time + # which is mostly not true. + creation_date = time.ctime(os.stat(file).st_ctime) + + file_path = pathlib.Path(file).parts[-1] + + # Create Entry + entry_key = os.path.join(settings['etcd']['file_prefix'], str(file_id)) + entry_value = { + "filename": file_path, + "owner": owner, + "sha512sum": sha512sum(file), + "creation_date": creation_date, + "size": os.path.getsize(file) + } + + logger.info("Tracking %s", file) + + shared.etcd_client.put(entry_key, entry_value, value_in_json=True) + os.setxattr(file, 'user.utracked', b'True') def main(): @@ -75,48 +71,15 @@ def main(): files = glob.glob("{}/**".format(base_dir), recursive=True) # Retain only Files - files = list(filter(os.path.isfile, files)) + files = [file for file in files if os.path.isfile(file)] - untracked_files = list( - filter(lambda f: not bool(getxattr(f, "utracked")), files) - ) - - tracked_files = list( - filter(lambda f: f not in untracked_files, files) - ) - for file in untracked_files: - file_id = uuid4() - - # Get Username - owner = pathlib.Path(file).parts[len(pathlib.Path(base_dir).parts)] - - # Get Creation Date of File - # Here, we are assuming that ctime is creation time - # which is mostly not true. - creation_date = time.ctime(os.stat(file).st_ctime) - - # Get File Size - size = os.path.getsize(file) - - # Compute sha512 sum - sha_sum = sha512sum(file) - - file_path = pathlib.Path(file).parts[-1] - - # Create Entry - entry_key = os.path.join(settings['etcd']['file_prefix'], str(file_id)) - entry_value = { - "filename": file_path, - "owner": owner, - "sha512sum": sha_sum, - "creation_date": creation_date, - "size": size - } - - logger.info("Tracking %s", file) - - shared.etcd_client.put(entry_key, entry_value, value_in_json=True) - setxattr(file, "utracked", True) + untracked_files = [] + for file in files: + try: + os.getxattr(file, 'user.utracked') + except OSError: + track_file(file, base_dir) + untracked_files.append(file) if __name__ == "__main__": diff --git a/ucloud/host/main.py b/ucloud/host/main.py index f78f629..be4f501 100755 --- a/ucloud/host/main.py +++ b/ucloud/host/main.py @@ -16,8 +16,7 @@ vmm = virtualmachine.VMM() def update_heartbeat(hostname): """Update Last HeartBeat Time for :param hostname: in etcd""" - client = shared.etcd_client - host_pool = HostPool(client) + host_pool = shared.host_pool this_host = next(filter(lambda h: h.hostname == hostname, host_pool.hosts), None) while True: @@ -27,7 +26,7 @@ def update_heartbeat(hostname): def main(hostname): - host_pool = HostPool(shared.etcd_client) + host_pool = shared.host_pool host = next(filter(lambda h: h.hostname == hostname, host_pool.hosts), None) assert host is not None, "No such host with name = {}".format(hostname) diff --git a/ucloud/host/virtualmachine.py b/ucloud/host/virtualmachine.py index cc06ce3..b3a1d2a 100755 --- a/ucloud/host/virtualmachine.py +++ b/ucloud/host/virtualmachine.py @@ -44,29 +44,7 @@ def capture_all_exception(func): try: func(*args, **kwargs) except Exception: - logger.info("Exception absorbed by captual_all_exception()") - logger.exception(func.__name__) - - return wrapper - - -def need_running_vm(func): - @wraps(func) - def wrapper(self, e): - vm = self.get_vm(self.running_vms, e.key) - if vm: - try: - status = vm.handle.command("query-status") - logger.debug("VM Status Check - %s", status) - except Exception as exception: - logger.info("%s failed - VM %s %s", func.__name__, e, exception) - else: - return func(e) - - return None - else: - logger.info("%s failed because VM %s is not running", func.__name__, e.key) - return None + logger.exception('Unhandled exception occur in %s. For more details see Syslog.', __name__) return wrapper @@ -168,7 +146,6 @@ class VMM: self.create(vm_entry) self.launch_vm(vm_entry) - @need_running_vm @capture_all_exception def stop(self, vm_entry): vm = self.get_vm(self.running_vms, vm_entry.key) diff --git a/ucloud/imagescanner/main.py b/ucloud/imagescanner/main.py index d164ea3..0d2fbf2 100755 --- a/ucloud/imagescanner/main.py +++ b/ucloud/imagescanner/main.py @@ -1,6 +1,6 @@ import json import os -import subprocess +import subprocess as sp import sys from os.path import isdir @@ -13,7 +13,7 @@ from ucloud.imagescanner import logger def qemu_img_type(path): qemu_img_info_command = ["qemu-img", "info", "--output", "json", path] try: - qemu_img_info = subprocess.check_output(qemu_img_info_command) + qemu_img_info = sp.check_output(qemu_img_info_command) except Exception as e: logger.exception(e) return None @@ -29,7 +29,7 @@ def check(): ) try: - subprocess.check_output(['which', 'qemu-img']) + sp.check_output(['which', 'qemu-img']) except Exception: print("qemu-img missing") sys.exit(1) @@ -67,29 +67,30 @@ def main(): if qemu_img_type(image_full_path) == "qcow2": try: # Convert .qcow2 to .raw - subprocess.check_output(qemu_img_convert_command) - except Exception as e: - logger.exception(e) + sp.check_output(qemu_img_convert_command,) + + except sp.CalledProcessError: + logger.exception('Image convertion from .qcow2 to .raw failed.') else: # Import and Protect r_status = shared.storage_handler.import_image(src="image.raw", - dest=image_uuid, - protect=True) + dest=image_uuid, + protect=True) if r_status: # Everything is successfully done image.value["status"] = "CREATED" shared.etcd_client.put(image.key, json.dumps(image.value)) + finally: + try: + os.remove("image.raw") + except Exception: + pass else: # The user provided image is either not found or of invalid format image.value["status"] = "INVALID_IMAGE" shared.etcd_client.put(image.key, json.dumps(image.value)) - try: - os.remove("image.raw") - except Exception: - pass - if __name__ == "__main__": main() diff --git a/ucloud/metadata/__init__.py b/ucloud/metadata/__init__.py index e69de29..eea436a 100644 --- a/ucloud/metadata/__init__.py +++ b/ucloud/metadata/__init__.py @@ -0,0 +1,3 @@ +import logging + +logger = logging.getLogger(__name__) diff --git a/ucloud/metadata/main.py b/ucloud/metadata/main.py index 5526084..adec9e7 100644 --- a/ucloud/metadata/main.py +++ b/ucloud/metadata/main.py @@ -2,12 +2,27 @@ import os from flask import Flask, request from flask_restful import Resource, Api +from werkzeug.exceptions import HTTPException + from ucloud.settings import settings from ucloud.shared import shared app = Flask(__name__) api = Api(app) +app.logger.handlers.clear() + + +@app.errorhandler(Exception) +def handle_exception(e): + app.logger.error(e) + # pass through HTTP errors + if isinstance(e, HTTPException): + return e + + # now you're handling non-HTTP exceptions only + return {'message': 'Server Error'}, 500 + def get_vm_entry(mac_addr): return next(filter(lambda vm: mac_addr in list(zip(*vm.network))[1], shared.vm_pool.vms), None) diff --git a/ucloud/settings/__init__.py b/ucloud/settings/__init__.py index 2c77300..b651aa2 100644 --- a/ucloud/settings/__init__.py +++ b/ucloud/settings/__init__.py @@ -5,7 +5,6 @@ import os from ucloud.common.etcd_wrapper import Etcd3Wrapper - logger = logging.getLogger(__name__) @@ -14,8 +13,9 @@ class CustomConfigParser(configparser.RawConfigParser): try: result = super().__getitem__(key) except KeyError as err: - raise KeyError("Key '{}' not found in config file"\ - .format(key)) from err + raise KeyError( + 'Key \'{}\' not found in configuration. Make sure you configure ucloud.'.format(key) + ) from err else: return result @@ -78,7 +78,7 @@ class Settings(object): if config_from_etcd: self.config_parser.read_dict(config_from_etcd.value) else: - raise KeyError("Key '{}' not found in etcd".format(self.config_key)) + raise KeyError("Key '{}' not found in etcd. Please configure ucloud.".format(self.config_key)) def __getitem__(self, key): self.read_values_from_etcd()