Merge pull request #115 from YunoHost/logging

Make use of logging instead of msignals.display

bin/yunohost

@@ -7,27 +7,28 @@ import os
 # Either we are in a development environment or not
 IN_DEVEL = False
 
-# Either cache has to be used inside the moulinette or not
-USE_CACHE = True
-
-# Either the output has to be encoded as a JSON encoded string or not
-PRINT_JSON = False
-
-# Either the output has to printed for scripting usage or not
-PRINT_PLAIN = False
-
 # Level for which loggers will log
 LOGGERS_LEVEL = 'INFO'
+TTY_LOG_LEVEL = 'SUCCESS'
 
 # Handlers that will be used by loggers
 #  - file: log to the file LOG_DIR/LOG_FILE
-#  - console: log to stderr
+#  - tty: log to current tty
-LOGGERS_HANDLERS = ['file']
+LOGGERS_HANDLERS = ['file', 'tty']
 
 # Directory and file to be used by logging
 LOG_DIR = '/var/log/yunohost'
 LOG_FILE = 'yunohost-cli.log'
 
+# Check and load - as needed - development environment
+if not __file__.startswith('/usr/'):
+    IN_DEVEL = True
+if IN_DEVEL:
+    basedir = os.path.abspath('%s/../' % os.path.dirname(__file__))
+    if os.path.isdir(os.path.join(basedir, 'moulinette')):
+        sys.path.insert(0, basedir)
+    LOG_DIR = os.path.join(basedir, 'log')
+
 
 # Initialization & helpers functions -----------------------------------
 
@@ -40,83 +41,114 @@ def _die(message, title='Error:'):
     print('%s %s' % (colorize(title, 'red'), message))
     sys.exit(1)
 
-def _check_in_devel():
+def _parse_cli_args():
-    """Check and load if needed development environment"""
+    """Parse additional arguments for the cli"""
-    global IN_DEVEL, LOG_DIR
+    import argparse
-    basedir = os.path.abspath('%s/../' % os.path.dirname(__file__))
-    if os.path.isdir('%s/moulinette' % basedir) and not IN_DEVEL:
-        # Add base directory to python path
-        sys.path.insert(0, basedir)
 
-        # Update global variables
+    parser = argparse.ArgumentParser(add_help=False)
-        IN_DEVEL = True
+    parser.add_argument('--no-cache',
-        LOG_DIR = '%s/log' % basedir
+        action='store_false', default=True, dest='use_cache',
+        help="Don't use actions map cache",
+    )
+    parser.add_argument('--output-as',
+        choices=['json', 'plain'], default=None,
+        help="Output result in another format",
+    )
+    parser.add_argument('--debug',
+        action='store_true', default=False,
+        help="Log and print debug messages",
+    )
+    parser.add_argument('--verbose',
+        action='store_true', default=False,
+        help="Be more verbose in the output",
+    )
+    parser.add_argument('--quiet',
+        action='store_true', default=False,
+        help="Don't produce any output",
+    )
+    # deprecated arguments
+    parser.add_argument('--plain',
+        action='store_true', default=False, help=argparse.SUPPRESS
+    )
+    parser.add_argument('--json',
+        action='store_true', default=False, help=argparse.SUPPRESS
+    )
 
-def _parse_argv():
+    opts, args = parser.parse_known_args()
-    """Parse additional arguments and return remaining ones"""
-    argv = list(sys.argv)
-    argv.pop(0)
 
-    if '--no-cache' in argv:
+    # output compatibility
-        global USE_CACHE
+    if opts.plain:
-        USE_CACHE = False
+        opts.output_as = 'plain'
-        argv.remove('--no-cache')
+    elif opts.json:
-    if '--json' in argv:
+        opts.output_as = 'json'
-        global PRINT_JSON
-        PRINT_JSON = True
-        argv.remove('--json')
-    if '--plain' in argv:
-        global PRINT_PLAIN
-        PRINT_PLAIN = True
-        argv.remove('--plain')
-    if '--debug' in argv:
-        global LOGGERS_LEVEL
-        LOGGERS_LEVEL = 'DEBUG'
-        argv.remove('--debug')
-    if '--verbose' in argv:
-        global LOGGERS_HANDLERS
-        if 'console' not in LOGGERS_HANDLERS:
-            LOGGERS_HANDLERS.append('console')
-        argv.remove('--verbose')
-    return argv
 
-def _init_moulinette():
+    return (parser, opts, args)
+
+def _init_moulinette(debug=False, verbose=False, quiet=False):
     """Configure logging and initialize the moulinette"""
     from moulinette import init
 
+    # Define loggers handlers
+    handlers = set(LOGGERS_HANDLERS)
+    if quiet and 'tty' in handlers:
+        handlers.remove('tty')
+    elif verbose and 'tty' not in handlers:
+        handlers.append('tty')
+    root_handlers = handlers - set(['tty'])
+
+    # Define loggers level
+    level = LOGGERS_LEVEL
+    tty_level = TTY_LOG_LEVEL
+    if verbose:
+        tty_level = 'INFO'
+    if debug:
+        tty_level = level = 'DEBUG'
+
     # Custom logging configuration
     logging = {
         'version': 1,
         'disable_existing_loggers': True,
         'formatters': {
-            'simple': {
+            'tty-debug': {
-                'format': '%(relativeCreated)-5d %(levelname)-8s %(name)s - %(message)s'
+                'format': '%(relativeCreated)-4d %(fmessage)s'
             },
             'precise': {
-                'format': '%(asctime)-15s %(levelname)-8s %(name)s %(funcName)s - %(message)s'
+                'format': '%(asctime)-15s %(levelname)-8s %(name)s %(funcName)s - %(fmessage)s'
+            },
+        },
+        'filters': {
+            'action': {
+                '()': 'moulinette.utils.log.ActionFilter',
             },
         },
         'handlers': {
-            'console': {
+            'tty': {
-                'class': 'logging.StreamHandler',
+                'level': tty_level,
-                'formatter': 'simple',
+                'class': 'moulinette.interfaces.cli.TTYHandler',
-                'stream': 'ext://sys.stderr',
+                'formatter': 'tty-debug' if debug else '',
             },
             'file': {
                 'class': 'logging.FileHandler',
                 'formatter': 'precise',
                 'filename': '%s/%s' % (LOG_DIR, LOG_FILE),
+                'filters': ['action'],
             },
         },
         'loggers': {
-            'moulinette': {
-                'level': LOGGERS_LEVEL,
-                'handlers': LOGGERS_HANDLERS,
-            },
             'yunohost': {
-                'level': LOGGERS_LEVEL,
+                'level': level,
-                'handlers': LOGGERS_HANDLERS,
+                'handlers': handlers,
+                'propagate': False,
             },
+            'moulinette': {
+                'level': level,
+                'handlers': [],
+                'propagate': True,
+            },
+        },
+        'root': {
+            'level': level,
+            'handlers': root_handlers,
         },
     }
 
@@ -144,9 +176,8 @@ def _retrieve_namespaces():
 # Main action ----------------------------------------------------------
 
 if __name__ == '__main__':
-    _check_in_devel()
+    parser, opts, args = _parse_cli_args()
-    args = _parse_argv()
+    _init_moulinette(opts.debug, opts.verbose, opts.quiet)
-    _init_moulinette()
 
     # Check that YunoHost is installed
     if not os.path.isfile('/etc/yunohost/installed') and \
@@ -163,6 +194,8 @@ if __name__ == '__main__':
 
     # Execute the action
     from moulinette import cli
-    ret = cli(_retrieve_namespaces(), args, use_cache=USE_CACHE,
+    ret = cli(_retrieve_namespaces(), args,
-              print_json=PRINT_JSON, print_plain=PRINT_PLAIN)
+            use_cache=opts.use_cache, output_as=opts.output_as,
+            parser_kwargs={'top_parser': parser}
+    )
     sys.exit(ret)

bin/yunohost-api

@@ -7,24 +7,32 @@ import os.path
 # Either we are in a development environment or not
 IN_DEVEL = False
 
-# Either cache has to be used inside the moulinette or not
+# Default server configuration
-USE_CACHE = True
+DEFAULT_HOST = 'localhost'
-
+DEFAULT_PORT = 6787
-# Either WebSocket has to be installed by the moulinette or not
-USE_WEBSOCKET = True
 
 # Level for which loggers will log
 LOGGERS_LEVEL = 'INFO'
 
 # Handlers that will be used by loggers
 #  - file: log to the file LOG_DIR/LOG_FILE
+#  - api: serve logs through the api
 #  - console: log to stderr
-LOGGERS_HANDLERS = ['file']
+LOGGERS_HANDLERS = ['file', 'api']
 
 # Directory and file to be used by logging
 LOG_DIR = '/var/log/yunohost'
 LOG_FILE = 'yunohost-api.log'
 
+# Check and load - as needed - development environment
+if not __file__.startswith('/usr/'):
+    IN_DEVEL = True
+if IN_DEVEL:
+    basedir = os.path.abspath('%s/../' % os.path.dirname(__file__))
+    if os.path.isdir(os.path.join(basedir, 'moulinette')):
+        sys.path.insert(0, basedir)
+    LOG_DIR = os.path.join(basedir, 'log')
+
 
 # Initialization & helpers functions -----------------------------------
 
@@ -37,79 +45,112 @@ def _die(message, title='Error:'):
     print('%s %s' % (colorize(title, 'red'), message))
     sys.exit(1)
 
-def _check_in_devel():
+def _parse_api_args():
-    """Check and load if needed development environment"""
+    """Parse main arguments for the api"""
-    global IN_DEVEL, LOG_DIR
+    import argparse
-    basedir = os.path.abspath('%s/../' % os.path.dirname(__file__))
-    if os.path.isdir('%s/moulinette' % basedir) and not IN_DEVEL:
-        # Add base directory to python path
-        sys.path.insert(0, basedir)
 
-        # Update global variables
+    parser = argparse.ArgumentParser(add_help=False,
-        IN_DEVEL = True
+        description="Run the YunoHost API to manage your server.",
-        LOG_DIR = '%s/log' % basedir
+    )
+    srv_group = parser.add_argument_group('server configuration')
+    srv_group.add_argument('-h', '--host',
+        action='store', default=DEFAULT_HOST,
+        help="Host to listen on (default: %s)" % DEFAULT_HOST,
+    )
+    srv_group.add_argument('-p', '--port',
+        action='store', default=DEFAULT_PORT, type=int,
+        help="Port to listen on (default: %d)" % DEFAULT_PORT,
+    )
+    srv_group.add_argument('--no-websocket',
+        action='store_true', default=True, dest='use_websocket',
+        help="Serve without WebSocket support, used to handle "
+        "asynchronous responses such as the messages",
+    )
+    glob_group = parser.add_argument_group('global arguments')
+    glob_group.add_argument('--no-cache',
+        action='store_false', default=True, dest='use_cache',
+        help="Don't use actions map cache",
+    )
+    glob_group.add_argument('--debug',
+        action='store_true', default=False,
+        help="Set log level to DEBUG",
+    )
+    glob_group.add_argument('--verbose',
+        action='store_true', default=False,
+        help="Be verbose in the output",
+    )
+    glob_group.add_argument('--help',
+        action='help', help="Show this help message and exit",
+    )
 
-def _parse_argv():
+    return parser.parse_args()
-    """Parse additional arguments and return remaining ones"""
-    argv = list(sys.argv)
-    argv.pop(0)
 
-    if '--no-cache' in argv:
+def _init_moulinette(use_websocket=True, debug=False, verbose=False):
-        global USE_CACHE
-        USE_CACHE = False
-        argv.remove('--no-cache')
-    if '--no-websocket' in argv:
-        global USE_WEBSOCKET
-        USE_WEBSOCKET = False
-        argv.remove('--no-websocket')
-    if '--debug' in argv:
-        global LOGGERS_LEVEL
-        LOGGERS_LEVEL = 'DEBUG'
-        argv.remove('--debug')
-    if '--verbose' in argv:
-        global LOGGERS_HANDLERS
-        if 'console' not in LOGGERS_HANDLERS:
-            LOGGERS_HANDLERS.append('console')
-        argv.remove('--verbose')
-    return argv
-
-def _init_moulinette():
     """Configure logging and initialize the moulinette"""
     from moulinette import init
 
+    # Define loggers handlers
+    handlers = set(LOGGERS_HANDLERS)
+    if not use_websocket and 'api' in handlers:
+        handlers.remove('api')
+    if verbose and 'console' not in handlers:
+        handlers.add('console')
+    root_handlers = handlers - set(['api'])
+
+    # Define loggers level
+    level = LOGGERS_LEVEL
+    if debug:
+        level = 'DEBUG'
+
     # Custom logging configuration
     logging = {
         'version': 1,
         'disable_existing_loggers': True,
         'formatters': {
-            'simple': {
+            'console': {
-                'format': '%(relativeCreated)-5d %(levelname)-8s %(name)s - %(message)s'
+                'format': '%(relativeCreated)-5d %(levelname)-8s %(name)s %(funcName)s - %(fmessage)s'
             },
             'precise': {
-                'format': '%(asctime)-15s %(levelname)-8s %(name)s %(funcName)s - %(message)s'
+                'format': '%(asctime)-15s %(levelname)-8s %(name)s %(funcName)s - %(fmessage)s'
+            },
+        },
+        'filters': {
+            'action': {
+                '()': 'moulinette.utils.log.ActionFilter',
             },
         },
         'handlers': {
-            'console': {
+            'api': {
-                'class': 'logging.StreamHandler',
+                'class': 'moulinette.interfaces.api.APIQueueHandler',
-                'formatter': 'simple',
-                'stream': 'ext://sys.stderr',
             },
             'file': {
                 'class': 'logging.handlers.WatchedFileHandler',
                 'formatter': 'precise',
                 'filename': '%s/%s' % (LOG_DIR, LOG_FILE),
+                'filters': ['action'],
+            },
+            'console': {
+                'class': 'logging.StreamHandler',
+                'formatter': 'console',
+                'stream': 'ext://sys.stdout',
+                'filters': ['action'],
             },
         },
         'loggers': {
-            'moulinette': {
-                'level': LOGGERS_LEVEL,
-                'handlers': LOGGERS_HANDLERS,
-            },
             'yunohost': {
-                'level': LOGGERS_LEVEL,
+                'level': level,
-                'handlers': LOGGERS_HANDLERS,
+                'handlers': handlers,
+                'propagate': False,
             },
+            'moulinette': {
+                'level': level,
+                'handlers': [],
+                'propagate': True,
+            },
+        },
+        'root': {
+            'level': level,
+            'handlers': root_handlers,
         },
     }
 
@@ -150,20 +191,18 @@ def is_installed():
 # Main action ----------------------------------------------------------
 
 if __name__ == '__main__':
-    _check_in_devel()
+    opts = _parse_api_args()
-    _parse_argv()
+    _init_moulinette(opts.use_websocket, opts.debug, opts.verbose)
-    _init_moulinette()
 
-    from moulinette import (api, MoulinetteError)
+    # Run the server
+    from moulinette import api, MoulinetteError
     from yunohost import get_versions
-    try:
+    ret = api(_retrieve_namespaces(),
-        # Run the server
+            host=opts.host, port=opts.port,
-        api(_retrieve_namespaces(), port=6787,
             routes={
                 ('GET', '/installed'): is_installed,
                 ('GET', '/version'): get_versions,
             },
-            use_cache=USE_CACHE, use_websocket=USE_WEBSOCKET)
+            use_cache=opts.use_cache, use_websocket=opts.use_websocket
-    except MoulinetteError as e:
+    )
-        _die(e.strerror, m18n.g('error'))
+    sys.exit(ret)
-    sys.exit(0)

data/actionsmap/yunohost.yml

@@ -1355,11 +1355,15 @@ hook:
             action_help: Execute hook from a file with arguments
             api: GET /hook
             arguments:
-                file:
+                path:
-                    help: Script to execute
+                    help: Path of the script to execute
                 -a:
                     full: --args
                     help: Arguments to pass to the script
                 --raise-on-error:
                     help: Raise if the script returns a non-zero exit code
                     action: store_true
+                -q:
+                    full: --no-trace
+                    help: Do not print each command that will be executed
+                    action: store_true

data/bash-completion.d/yunohost

@@ -0,0 +1,12 @@
+#
+# Bash completion for yunohost
+#
+
+_python_argcomplete() {
+    local IFS=''
+    COMPREPLY=( $(IFS="$IFS"                   COMP_LINE="$COMP_LINE"                   COMP_POINT="$COMP_POINT"                   _ARGCOMPLETE_COMP_WORDBREAKS="$COMP_WORDBREAKS"                   _ARGCOMPLETE=1                   "$1" 8>&1 9>&2 1>/dev/null 2>/dev/null) )
+    if [[ $? != 0 ]]; then
+        unset COMPREPLY
+    fi
+}
+complete -o nospace -o default -F _python_argcomplete "yunohost"

debian/install

@@ -1,4 +1,5 @@
 bin/* /usr/bin/
+data/bash-completion.d/yunohost /etc/bash_completion.d/
 data/actionsmap/* /usr/share/moulinette/actionsmap/
 data/hooks/* /usr/share/yunohost/hooks/
 data/other/* /usr/share/yunohost/yunohost-config/moulinette/

locales/en.json

@@ -37,7 +37,8 @@
     "mysql_db_initialized" : "MySQL database successfully initialized",
     "extracting" : "Extracting...",
     "downloading" : "Downloading...",
-    "executing_script": "Executing script...",
+    "executing_script": "Executing script '{script:s}'...",
+    "executing_command": "Executing command '{command:s}'...",
     "done" : "Done.",
 
     "path_removal_failed" : "Unable to remove path {:s}",
@@ -87,6 +88,7 @@
     "hook_choice_invalid" : "Invalid choice '{:s}'",
     "hook_argument_missing" : "Missing argument '{:s}'",
     "hook_exec_failed" : "Script execution failed",
+    "hook_exec_not_terminated" : "Script execution hasn’t terminated",
 
     "mountpoint_unknown" : "Unknown mountpoint",
     "unit_unknown" : "Unknown unit '{:s}'",
@@ -118,7 +120,7 @@
     "service_no_log" : "No log to display for service '{:s}'",
     "service_cmd_exec_failed" : "Unable to execute command '{:s}'",
     "services_configured": "Configuration successfully generated",
-    "service_configuration_conflict": "The file {file:s} has been changed since its last generation. Please apply the modifications manually or use the option --force (it will erase all the modifications previously done to the file)",
+    "service_configuration_conflict": "The file {file:s} has been changed since its last generation. Please apply the modifications manually or use the option --force (it will erase all the modifications previously done to the file). Here are the differences:\n{diff:s}",
     "no_such_conf_file": "Unable to copy the file {file:s}: the file does not exist",
     "service_add_configuration": "Adding the configuration file {file:s}",
 

src/yunohost/firewall.py

@@ -83,8 +83,7 @@ def firewall_allow(protocol, port, ipv4_only=False, ipv6_only=False,
                 firewall[i][p].append(port)
             else:
                 ipv = "IPv%s" % i[3]
-                msignals.display(m18n.n('port_already_opened', port, ipv),
+                logger.warning(m18n.n('port_already_opened', port, ipv))
-                                 'warning')
         # Add port forwarding with UPnP
         if not no_upnp and port not in firewall['uPnP'][p]:
             firewall['uPnP'][p].append(port)
@@ -141,8 +140,7 @@ def firewall_disallow(protocol, port, ipv4_only=False, ipv6_only=False,
                 firewall[i][p].remove(port)
             else:
                 ipv = "IPv%s" % i[3]
-                msignals.display(m18n.n('port_already_closed', port, ipv),
+                logger.warning(m18n.n('port_already_closed', port, ipv))
-                                 'warning')
         # Remove port forwarding with UPnP
         if upnp and port in firewall['uPnP'][p]:
             firewall['uPnP'][p].remove(port)
@@ -214,9 +212,9 @@ def firewall_reload(skip_upnp=False):
     try:
         process.check_output("iptables -L")
     except process.CalledProcessError as e:
-        logger.info('iptables seems to be not available, it outputs:\n%s',
+        logger.debug('iptables seems to be not available, it outputs:\n%s',
-                    prependlines(e.output.rstrip(), '> '))
+                     prependlines(e.output.rstrip(), '> '))
-        msignals.display(m18n.n('iptables_unavailable'), 'info')
+        logger.warning(m18n.n('iptables_unavailable'))
     else:
         rules = [
             "iptables -F",
@@ -243,9 +241,9 @@ def firewall_reload(skip_upnp=False):
     try:
         process.check_output("ip6tables -L")
     except process.CalledProcessError as e:
-        logger.info('ip6tables seems to be not available, it outputs:\n%s',
+        logger.debug('ip6tables seems to be not available, it outputs:\n%s',
-                    prependlines(e.output.rstrip(), '> '))
+                     prependlines(e.output.rstrip(), '> '))
-        msignals.display(m18n.n('ip6tables_unavailable'), 'info')
+        logger.warning(m18n.n('ip6tables_unavailable'))
     else:
         rules = [
             "ip6tables -F",
@@ -282,9 +280,9 @@ def firewall_reload(skip_upnp=False):
     os.system("service fail2ban restart")
 
     if errors:
-        msignals.display(m18n.n('firewall_rules_cmd_failed'), 'warning')
+        logger.warning(m18n.n('firewall_rules_cmd_failed'))
     else:
-        msignals.display(m18n.n('firewall_reloaded'), 'success')
+        logger.success(m18n.n('firewall_reloaded'))
     return firewall_list()
 
 
@@ -306,7 +304,7 @@ def firewall_upnp(action='status', no_refresh=False):
 
     # Compatibility with previous version
     if action == 'reload':
-        logger.warning("'reload' action is deprecated and will be removed")
+        logger.info("'reload' action is deprecated and will be removed")
         try:
             # Remove old cron job
             os.remove('/etc/cron.d/yunohost-firewall')
@@ -349,14 +347,14 @@ def firewall_upnp(action='status', no_refresh=False):
         nb_dev = upnpc.discover()
         logger.debug('found %d UPnP device(s)', int(nb_dev))
         if nb_dev < 1:
-            msignals.display(m18n.n('upnp_dev_not_found'), 'error')
+            logger.error(m18n.n('upnp_dev_not_found'))
             enabled = False
         else:
             try:
                 # Select UPnP device
                 upnpc.selectigd()
             except:
-                logger.exception('unable to select UPnP device')
+                logger.info('unable to select UPnP device', exc_info=1)
                 enabled = False
             else:
                 # Iterate over ports
@@ -374,8 +372,8 @@ def firewall_upnp(action='status', no_refresh=False):
                             upnpc.addportmapping(port, protocol, upnpc.lanaddr,
                                 port, 'yunohost firewall: port %d' % port, '')
                         except:
-                            logger.exception('unable to add port %d using UPnP',
+                            logger.info('unable to add port %d using UPnP',
-                                             port)
+                                        port, exc_info=1)
                             enabled = False
 
     if enabled != firewall['uPnP']['enabled']:
@@ -390,9 +388,9 @@ def firewall_upnp(action='status', no_refresh=False):
         if not no_refresh:
             # Display success message if needed
             if action == 'enable' and enabled:
-                msignals.display(m18n.n('upnp_enabled'), 'success')
+                logger.success(m18n.n('upnp_enabled'))
             elif action == 'disable' and not enabled:
-                msignals.display(m18n.n('upnp_disabled'), 'success')
+                logger.success(m18n.n('upnp_disabled'))
             # Make sure to disable UPnP
             elif action != 'disable' and not enabled:
                 firewall_upnp('disable', no_refresh=True)
@@ -455,6 +453,6 @@ def _update_firewall_file(rules):
 def _on_rule_command_error(returncode, cmd, output):
     """Callback for rules commands error"""
     # Log error and continue commands execution
-    logger.error('"%s" returned non-zero exit status %d:\n%s',
+    logger.info('"%s" returned non-zero exit status %d:\n%s',
-                 cmd, returncode, prependlines(output.rstrip(), '> '))
+                cmd, returncode, prependlines(output.rstrip(), '> '))
     return True

src/yunohost/hook.py

@@ -32,12 +32,12 @@ import subprocess
 from glob import iglob
 
 from moulinette.core import MoulinetteError
-from moulinette.utils.log import getActionLogger
+from moulinette.utils import log
 
 hook_folder = '/usr/share/yunohost/hooks/'
 custom_hook_folder = '/etc/yunohost/hooks.d/'
 
-logger = getActionLogger('yunohost.hook')
+logger = log.getActionLogger('yunohost.hook')
 
 
 def hook_add(app, file):
@@ -264,14 +264,9 @@ def hook_callback(action, hooks=[], args=None):
             state = 'succeed'
             filename = '%s-%s' % (priority, name)
             try:
-                ret = hook_exec(info['path'], args=args)
+                hook_exec(info['path'], args=args, raise_on_error=True)
-            except:
+            except MoulinetteError as e:
-                logger.exception("error while executing hook '%s'",
+                logger.error(e.strerror)
-                                 info['path'])
-                state = 'failed'
-            if ret != 0:
-                logger.error("error while executing hook '%s', retcode: %d",
-                             info['path'], ret)
                 state = 'failed'
             try:
                 result[state][name].append(info['path'])
@@ -301,23 +296,31 @@ def hook_check(file):
         return {}
 
 
-def hook_exec(file, args=None, raise_on_error=False):
+def hook_exec(path, args=None, raise_on_error=False, no_trace=False):
     """
     Execute hook from a file with arguments
 
     Keyword argument:
-        file -- Script to execute
+        path -- Path of the script to execute
         args -- Arguments to pass to the script
         raise_on_error -- Raise if the script returns a non-zero exit code
+        no_trace -- Do not print each command that will be executed
 
     """
-    from moulinette.utils.stream import NonBlockingStreamReader
+    import time
+    from moulinette.utils.stream import start_async_file_reading
     from yunohost.app import _value_for_locale
 
+    # Validate hook path
+    if path[0] != '/':
+        path = os.path.realpath(path)
+    if not os.path.isfile(path):
+        raise MoulinetteError(errno.EIO, m18n.g('file_not_exist'))
+
     if isinstance(args, list):
         arg_list = args
     else:
-        required_args = hook_check(file)
+        required_args = hook_check(path)
         if args is None:
             args = {}
 
@@ -351,42 +354,60 @@ def hook_exec(file, args=None, raise_on_error=False):
                     raise MoulinetteError(errno.EINVAL,
                         m18n.n('hook_argument_missing', arg['name']))
 
-    file_path = "./"
+    # Construct command variables
-    if "/" in file and file[0:2] != file_path:
+    cmd_fdir, cmd_fname = os.path.split(path)
-        file_path = os.path.dirname(file)
+    cmd_fname = './{0}'.format(cmd_fname)
-        file = file.replace(file_path +"/", "")
 
-    #TODO: Allow python script
+    cmd_args = ''
-
-    arg_str = ''
     if arg_list:
         # Concatenate arguments and escape them with double quotes to prevent
         # bash related issue if an argument is empty and is not the last
-        arg_str = '"{:s}"'.format('" "'.join(str(s) for s in arg_list))
+        cmd_args = '"{:s}"'.format('" "'.join(str(s) for s in arg_list))
 
-    msignals.display(m18n.n('executing_script'))
+    # Construct command to execute
+    command = ['sudo', '-u', 'admin', '-H', 'sh', '-c']
+    if no_trace:
+        cmd = 'cd "{0:s}" && /bin/bash "{1:s}" {2:s}'
+    else:
+        # use xtrace on fd 7 which is redirected to stdout
+        cmd = 'cd "{0:s}" && BASH_XTRACEFD=7 /bin/bash -x "{1:s}" {2:s} 7>&1'
+    command.append(cmd.format(cmd_fdir, cmd_fname, cmd_args))
 
-    p = subprocess.Popen(
+    if logger.isEnabledFor(log.DEBUG):
-            ['sudo', '-u', 'admin', '-H', 'sh', '-c', 'cd "{:s}" && ' \
+        logger.info(m18n.n('executing_command', command=' '.join(command)))
-                '/bin/bash -x "{:s}" {:s}'.format(
+    else:
-                    file_path, file, arg_str)],
+        logger.info(m18n.n('executing_script', script='{0}/{1}'.format(
-            stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
+                cmd_fdir, cmd_fname)))
+
+    process = subprocess.Popen(command,
+            stdout=subprocess.PIPE, stderr=subprocess.PIPE,
             shell=False)
 
-    # Wrap and get process ouput
+    # Wrap and get process outputs
-    stream = NonBlockingStreamReader(p.stdout)
+    stdout_reader, stdout_queue = start_async_file_reading(process.stdout)
-    while True:
+    stderr_reader, stderr_queue = start_async_file_reading(process.stderr)
-        line = stream.readline(True, 0.1)
+    while not stdout_reader.eof() or not stderr_reader.eof():
-        if not line:
+        while not stdout_queue.empty():
-            # Check if process has terminated
+            line = stdout_queue.get()
-            returncode = p.poll()
+            logger.info(line.rstrip())
-            if returncode is not None:
+        while not stderr_queue.empty():
-                break
+            line = stderr_queue.get()
-        else:
+            logger.warning(line.rstrip())
-            msignals.display(line.rstrip(), 'log')
+        time.sleep(.1)
-    stream.close()
 
-    if raise_on_error and returncode != 0:
+    # Terminate outputs readers
+    stdout_reader.join()
+    stderr_reader.join()
+
+    # Get and return process' return code
+    returncode = process.poll()
+    if returncode is None:
+        if raise_on_error:
+            raise MoulinetteError(m18n.n('hook_exec_not_terminated'))
+        else:
+            logger.error(m18n.n('hook_exec_not_terminated'))
+            return 1
+    elif raise_on_error and returncode != 0:
         raise MoulinetteError(m18n.n('hook_exec_failed'))
     return returncode
 

src/yunohost/service.py

@@ -34,6 +34,7 @@ import difflib
 import hashlib
 
 from moulinette.core import MoulinetteError
+from moulinette.utils import log
 
 template_dir = os.getenv(
     'YUNOHOST_TEMPLATE_DIR',
@@ -44,6 +45,9 @@ conf_backup_dir = os.getenv(
     '/home/yunohost.backup/conffiles'
 )
 
+logger = log.getActionLogger('yunohost.service')
+
+
 def service_add(name, status=None, log=None, runlevel=None):
     """
     Add a custom service
@@ -73,7 +77,7 @@ def service_add(name, status=None, log=None, runlevel=None):
     except:
         raise MoulinetteError(errno.EIO, m18n.n('service_add_failed', name))
 
-    msignals.display(m18n.n('service_added'), 'success')
+    logger.success(m18n.n('service_added'))
 
 
 def service_remove(name):
@@ -96,7 +100,7 @@ def service_remove(name):
     except:
         raise MoulinetteError(errno.EIO, m18n.n('service_remove_failed', name))
 
-    msignals.display(m18n.n('service_removed'), 'success')
+    logger.success(m18n.n('service_removed'))
 
 
 def service_start(names):
@@ -111,12 +115,12 @@ def service_start(names):
         names = [names]
     for name in names:
         if _run_service_command('start', name):
-            msignals.display(m18n.n('service_started', name), 'success')
+            logger.success(m18n.n('service_started', name))
         else:
             if service_status(name)['status'] != 'running':
                 raise MoulinetteError(errno.EPERM,
                                       m18n.n('service_start_failed', name))
-            msignals.display(m18n.n('service_already_started', name))
+            logger.info(m18n.n('service_already_started', name))
 
 
 def service_stop(names):
@@ -131,12 +135,12 @@ def service_stop(names):
         names = [names]
     for name in names:
         if _run_service_command('stop', name):
-            msignals.display(m18n.n('service_stopped', name), 'success')
+            logger.success(m18n.n('service_stopped', name))
         else:
             if service_status(name)['status'] != 'inactive':
                 raise MoulinetteError(errno.EPERM,
                                       m18n.n('service_stop_failed', name))
-            msignals.display(m18n.n('service_already_stopped', name))
+            logger.info(m18n.n('service_already_stopped', name))
 
 
 def service_enable(names):
@@ -151,7 +155,7 @@ def service_enable(names):
         names = [names]
     for name in names:
         if _run_service_command('enable', name):
-            msignals.display(m18n.n('service_enabled', name), 'success')
+            logger.success(m18n.n('service_enabled', name))
         else:
             raise MoulinetteError(errno.EPERM,
                                   m18n.n('service_enable_failed', name))
@@ -169,7 +173,7 @@ def service_disable(names):
         names = [names]
     for name in names:
         if _run_service_command('disable', name):
-            msignals.display(m18n.n('service_disabled', name), 'success')
+            logger.success(m18n.n('service_disabled', name))
         else:
             raise MoulinetteError(errno.EPERM,
                                   m18n.n('service_disable_failed', name))
@@ -217,8 +221,7 @@ def service_status(names=[]):
                                           shell=True)
         except subprocess.CalledProcessError as e:
             if 'usage:' in e.output.lower():
-                msignals.display(m18n.n('service_status_failed', name),
+                logger.warning(m18n.n('service_status_failed', name))
-                                 'warning')
             else:
                 result[name]['status'] = 'inactive'
         else:
@@ -288,7 +291,7 @@ def service_regenconf(service=None, force=False):
         hook_callback('conf_regen', [service], args=[force])
     else:
         hook_callback('conf_regen', args=[force])
-    msignals.display(m18n.n('services_configured'), 'success')
+    logger.success(m18n.n('services_configured'))
 
 
 def _run_service_command(action, service):
@@ -317,8 +320,7 @@ def _run_service_command(action, service):
         ret = subprocess.check_output(cmd.split(), stderr=subprocess.STDOUT)
     except subprocess.CalledProcessError as e:
         # TODO: Log output?
-        msignals.display(m18n.n('service_cmd_exec_failed', ' '.join(e.cmd)),
+        logger.warning(m18n.n('service_cmd_exec_failed', ' '.join(e.cmd)))
-                         'warning')
         return False
     return True
 
@@ -467,12 +469,9 @@ def service_saferemove(service, conf_file, force=False):
     else:
         services[service]['conffiles'][conf_file] = previous_hash
         os.remove(conf_backup_file)
-        if os.isatty(1) and \
+        if len(previous_hash) == 32 or previous_hash[-32:] != current_hash:
-           (len(previous_hash) == 32 or previous_hash[-32:] != current_hash):
+            logger.warning(m18n.n('service_configuration_conflict',
-            msignals.display(
+                file=conf_file))
-                m18n.n('service_configuration_conflict', file=conf_file),
-                'warning'
-            )
 
     _save_services(services)
 
@@ -509,8 +508,7 @@ def service_safecopy(service, new_conf_file, conf_file, force=False):
         )
         process.wait()
     else:
-        msignals.display(m18n.n('service_add_configuration', file=conf_file),
+        logger.info(m18n.n('service_add_configuration', file=conf_file))
-                         'info')
 
     # Add the service if it does not exist
     if service not in services.keys():
@@ -539,15 +537,9 @@ def service_safecopy(service, new_conf_file, conf_file, force=False):
     else:
         new_hash = previous_hash
         if (len(previous_hash) == 32 or previous_hash[-32:] != current_hash):
-            msignals.display(
+            logger.warning(m18n.n('service_configuration_conflict',
-                m18n.n('service_configuration_conflict', file=conf_file),
+                file=conf_file, diff=''.join(diff)))
-                'warning'
+
-            )
-            print('\n' + conf_file)
-            for line in diff:
-                print(line.strip())
-            print('')
-      
     # Remove the backup file if the configuration has not changed
     if new_hash == previous_hash:
         try: