- Better error reporting.

- Flask now uses application's logger instead of its own.
- ucloud file scanner refactored.

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)

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'])],

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:

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"]

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:

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)

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)

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,31 +35,7 @@ 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 main():
-    base_dir = settings['storage']['file_dir']
-
-    # Recursively Get All Files and Folder below BASE_DIR
-    files = glob.glob("{}/**".format(base_dir), recursive=True)
-
-    # Retain only Files
-    files = list(filter(os.path.isfile, files))
-
-    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:
+def track_file(file, base_dir):
     file_id = uuid4()
 
     # Get Username
@@ -95,12 +46,6 @@ def main():
     # 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
@@ -108,15 +53,33 @@ def main():
     entry_value = {
         "filename": file_path,
         "owner": owner,
-            "sha512sum": sha_sum,
+        "sha512sum": sha512sum(file),
         "creation_date": creation_date,
-            "size": size
+        "size": os.path.getsize(file)
     }
 
     logger.info("Tracking %s", file)
 
     shared.etcd_client.put(entry_key, entry_value, value_in_json=True)
-        setxattr(file, "utracked", True)
+    os.setxattr(file, 'user.utracked', b'True')
+
+
+def main():
+    base_dir = settings['storage']['file_dir']
+
+    # Recursively Get All Files and Folder below BASE_DIR
+    files = glob.glob("{}/**".format(base_dir), recursive=True)
+
+    # Retain only Files
+    files = [file for file in files if os.path.isfile(file)]
+
+    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__":

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)
 

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)

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,9 +67,10 @@ 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",
@@ -79,17 +80,17 @@ def main():
                         # 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()

ucloud/metadata/__init__.py

@@ -0,0 +1,3 @@
+import logging
+
+logger = logging.getLogger(__name__)

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)

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()