Unittest - Enhanced support for testing hooks (wip)

* It is now possible to test:
  * Hook Input/Output on STDIN/STDOUT channels
  * Exit code of hook script
  * Execution count (how many times the hook was executed)
  * Timestamp execution (when was the hook executed - milisec resolution)

test/basetest/hooks.py

@@ -0,0 +1,491 @@
+# -*- coding: utf-8 -*-
+
+from __future__ import division
+import os
+from sys import stderr
+import shutil
+import stat
+try:
+    import simplejson as json
+except ImportError:
+    import json
+
+from copy import deepcopy
+from datetime import datetime
+from .utils import DEFAULT_HOOK_PATH
+from .exceptions import HookError
+
+
+class Hooks(object):
+    """Abstraction to help interact with hooks (add, remove) during tests and
+    keep track of which are active.
+    """
+    def __init__(self, datadir):
+        """Initialize hooks container which keeps track of active hooks and
+
+        :arg datadir: Temporary location where task is running (/tmp/...)
+        """
+        self.hookdir = os.path.join(datadir, "hooks")
+        self._hooks = {}
+
+        # Check if the hooks dir already exists
+        if not os.path.isdir(self.hookdir):
+            os.mkdir(self.hookdir)
+
+    def __repr__(self):
+        enabled = []
+        disabled = []
+
+        for hook in self:
+            if hook.is_active():
+                enabled.append(hook)
+            else:
+                disabled.append(hook)
+
+        enabled = ", ".join(enabled) or None
+        disabled = ", ".join(disabled) or None
+
+        return "<Hooks: enabled: {0} | disabled: {1}>".format(enabled,
+                                                              disabled)
+
+    def __getitem__(self, name):
+        return self._hooks[name]
+
+    def __setitem(self, key, value):
+        self._hooks[key] = value
+
+    def __delitem(self, key):
+        del self._hooks[key]
+
+    def __iter__(self):
+        for item in self._hooks:
+            yield item
+
+    def __len__(self):
+        return len(self._hooks)
+
+    def add(self, hookname, content, log=False):
+        """Register hook with name 'hookname' and given file content.
+
+        :arg hookname: Should be a string starting with one of:
+            - on-launch
+            - on-add
+            - on-exit
+            - on-modify
+
+        :arg content: Content of the file as a (multi-line) string
+        :arg log: If we require checking input/output of the hook
+        """
+        if log:
+            self[hookname] = LoggedHook(hookname, self.hookdir, content)
+        else:
+            self[hookname] = Hook(hookname, self.hookdir, content)
+
+    def add_default(self, hookname, log=False):
+        """Register a pre-built hook that exists in the folder containing hooks
+        used for testing.
+        If not explicitly passed hooks folder defaults to DEFAULT_HOOK_PATH
+
+        :arg hookname: Name of the default hook
+        :arg log: If we require checking input/output of the hook
+        """
+        if log:
+            self[hookname] = LoggedHook(hookname, self.hookdir, default=True)
+        else:
+            self[hookname] = Hook(hookname, self.hookdir, default=True)
+
+    def remove(self, hook):
+        """Remove the hook matching given hookname"""
+        try:
+            hookname = hook.hookname
+        except AttributeError:
+            hookname = hook
+
+        hook = self[hookname]
+
+        try:
+            del self[hookname]
+        except KeyError:
+            raise HookError("Hook {0} is not on record".format(hookname))
+
+        hook._delete()
+
+    def clear(self):
+        """Remove all existing hooks and empty the hook registry
+        """
+        self._hooks = {}
+
+        # Remove any existing hooks
+        try:
+            shutil.rmtree(self.hookdir)
+        except OSError as e:
+            # If the hookdir folder doesn't exist, no harm done and keep going
+            if e.errno != 2:
+                raise
+
+        os.mkdir(self.hookdir)
+
+
+class Hook(object):
+    """Represents a hook script and provides methods to enable/disable hooks
+    """
+    def __init__(self, hookname, hookdir, content=None, default=False,
+                 default_hookpath=None):
+        """Initialize and create the hook
+
+        This class supports creating hooks in two ways:
+          * by specifying default=True in which case hookname will be
+            searched on the hookpath and linked to the destination
+          * by specifying content="some text" in which case the hook will be
+            created with given content
+
+        :arg hookname: Name of the hook e.g.: on-add.foobar
+        :arg hookdir: Hooks directory under temporary task/ folder
+        :arg content: What should be written to the hookfile
+        :arg default: If True hookname is looked up on default_hookpath
+        :arg default_hookpath: Default location where to look for preset hooks
+        """
+        self.hookname = hookname
+        self.hookdir = hookdir
+        self.hookfile = os.path.join(self.hookdir, self.hookname)
+
+        if default_hookpath is None:
+            self.default_hookpath = DEFAULT_HOOK_PATH
+        else:
+            self.default_hookpath = default_hookpath
+
+        self._check_hook_type()
+        self._check_hook_not_exists(self.hookfile)
+
+        if not default and content is None:
+            raise HookError("Cannot create hookfile {0} without content. "
+                            "If using a builtin hook pass default=True"
+                            .format(self.hookname))
+
+        if os.path.isfile(self.hookfile):
+            raise HookError("Hook with name {0} already exists. "
+                            "Did you forget to remove() it before recreating?"
+                            .format(self.hookname))
+
+        if default:
+            self.default_hookfile = os.path.join(self.default_hookpath,
+                                                 self.hookname)
+            self._check_hook_exists(self.default_hookfile)
+            # Symlinks change permission of source file, cannot use one here
+            shutil.copy(self.default_hookfile, self.hookfile)
+        else:
+            self.default_hookfile = None
+            with open(self.hookfile, 'w') as fh:
+                fh.write(content)
+
+        # Finally enable the hook
+        self.enable()
+
+    def __eq__(self, other):
+        try:
+            if self.hookname == other.hookname:
+                return True
+        except AttributeError:
+            pass
+
+        return False
+
+    def __ne__(self, other):
+        try:
+            if self.hookname != other.hookname:
+                return True
+        except AttributeError:
+            pass
+
+        return False
+
+    def __hash__(self):
+        return self.hookname.__hash__()
+
+    def __repr__(self):
+        return "<Hook '{0}'>".format(self.hookname)
+
+    def __str__(self):
+        return self.hookname
+
+    def _check_hook_exists(self, hookfile):
+        """Checks if the file pointed to by the current hook exists"""
+        if not os.path.isfile(hookfile) and not os.path.islink(hookfile):
+            raise HookError("Hook {0} doesn't exist.".format(hookfile))
+
+    def _check_hook_not_exists(self, hookfile):
+        """Checks if the file pointed to by the current hook doesn't exist"""
+        try:
+            self._check_hook_exists(hookfile)
+        except HookError:
+            return
+        else:
+            raise HookError("Hook {0} already exists.".format(hookfile))
+
+    def _check_hook_type(self):
+        """Check if the hookname is valid and if another hook with the same
+        name was already created.
+        """
+        for hooktype in ("on-launch", "on-add", "on-exit", "on-modify"):
+            if self.hookname.startswith(hooktype):
+                break
+        else:
+            stderr.write("WARNING: {0} is not a valid hook type. "
+                         "It will not be triggered\n".format(self.hookname))
+
+    def _remove_file(self, file):
+        try:
+            os.remove(file)
+        except OSError as e:
+            if e.errno == 2:
+                raise HookError("Hook with name {0} was not found on "
+                                "hooks/ folder".format(file))
+            else:
+                raise
+
+    def _delete(self):
+        """Remove the hook from disk
+
+        Don't call this method directly. Use Hooks.remove(hook) instead
+        """
+        self._remove_hookfile(self.hookfile)
+
+    def enable(self):
+        """Make hookfile executable to allow triggering
+        """
+        os.chmod(self.hookfile, stat.S_IREAD | stat.S_IWRITE | stat.S_IEXEC)
+
+    def disable(self):
+        """Remove hookfile executable bit to deny triggering
+        """
+        os.chmod(self.hookfile, stat.S_IREAD | stat.S_IWRITE)
+
+    def is_active(self):
+        """Check if hook is active by verifying the execute bit
+        """
+        return os.access(self.hookfile, os.X_OK)
+
+
+class LoggedHook(Hook):
+    """A variant of a Hook that allows checking that the hook was called, what
+    was received via STDIN and what was answered to STDOUT
+    """
+    def __init__(self, *args, **kwargs):
+        super(LoggedHook, self).__init__(*args, **kwargs)
+
+        # The wrapper will replace the hookfile
+        # The original file will be 'wrappedfile'
+
+        # NOTE If the prefix "original_" is changed here, update wrapper.sh
+        self.wrappedname = "original_" + self.hookname
+        self.wrappedfile = os.path.join(self.hookdir, self.wrappedname)
+
+        self.original_wrapper = os.path.join(self.default_hookpath,
+                                             "wrapper.sh")
+
+        self.hooklog_in = self.wrappedfile + ".log.in"
+        self.hooklog_out = self.wrappedfile + ".log.out"
+
+        # Cache is used to avoid parsing the logfiles everytime it's needed
+        self._cache = {}
+
+        # Setup wrapper pointing to the correct hook name
+        self._setup_wrapper()
+
+        # Finally enable all hooks
+        self.enable()
+
+    def __repr__(self):
+        return "<LoggedHook '{0}'>".format(self.hookname)
+
+    def _delete(self):
+        """Remove the hook from disk
+
+        Don't call this method directly. Use Task.hooks.remove(hook) instead
+        """
+        super(LoggedHook, self)._delete()
+        self._remove_file(self.wrappedfile)
+        self._remove_file(self.hooklog_in)
+        self._remove_file(self.hooklog_out)
+
+    def _setup_wrapper(self):
+        """Setup wrapper shell script to allow capturing input/output of hook
+        """
+        # Create empty hooklog to allow checking that hook executed
+        open(self.hooklog_in, 'w').close()
+        open(self.hooklog_out, 'w').close()
+
+        # Rename the original hook to the name that will be used by wrapper
+        self._check_hook_not_exists(self.wrappedfile)
+        os.rename(self.hookfile, self.wrappedfile)
+
+        # Symlinks change permission of source file, cannot use one here
+        shutil.copy(self.original_wrapper, self.hookfile)
+
+    def _get_log_stat(self):
+        """Return the most recent change timestamp and size of both logfiles
+        """
+        stdin = os.stat(self.hooklog_in)
+        stdout = os.stat(self.hooklog_out)
+
+        last_change = max((stdin.st_mtime, stdout.st_mtime))
+        return last_change, stdin.st_size, stdout.st_size
+
+    def _use_cache(self):
+        """Check if log files were changed since last check
+        """
+        try:
+            last_change = self._cache["last_change"]
+        except KeyError:
+            # No cache available
+            return False
+        else:
+            change = self._get_log_stat()
+
+            if last_change != change:
+                # Cache is outdated
+                return False
+            else:
+                # Cache is up to date
+                return True
+
+    def _parse_log(self):
+        """Parse the logs generated by the hook
+
+        It should look something like this:
+
+        ## STDIN file
+        % Called at 1414874711
+        {... JSON received by the hook ... }
+        {... more JSON ...}
+
+        ## STDOUT file
+        {... JSON emitted by the hook ... }
+        Logged messages
+        {... more JSON ...}
+        ! Exit code: 1
+        """
+        if self._use_cache():
+            return self._cache["log"]
+
+        log = {"calls": [],
+               "input": {
+                   "json": [],
+                   },
+               "output": {
+                   "json": [],
+                   "msgs": [],
+                   },
+               "exitcode": None,
+               }
+
+        with open(self.hooklog_in) as fh:
+            for i, line in enumerate(fh):
+                if line.startswith("%"):
+                    # Timestamp includes nanosecond resolution
+                    timestamp = line.split(" ")[-1]
+                    log["calls"].append(timestamp)
+                elif line.startswith("{"):
+                    log["input"]["json"].append(line)
+                else:
+                    raise IOError("Unexpected content on STDIN line {0}: {1}"
+                                  .format(i, line))
+
+        with open(self.hooklog_out) as fh:
+            for line in fh:
+                if line.startswith("!"):
+                    exitcode = int(line.split(" ")[-1])
+                    log["exitcode"] = exitcode
+                elif line.startswith("{"):
+                    log["output"]["json"].append(line)
+                else:
+                    log["output"]["msgs"].append(line)
+
+        self._cache["log"] = log
+
+        # Update last modification timestamp in cache
+        self._cache["last_change"] = self._get_log_stat()
+
+    def enable(self):
+        """Make hookfile executable to allow triggering
+        """
+        super(LoggedHook, self).enable()
+        os.chmod(self.wrappedfile, stat.S_IREAD | stat.S_IWRITE | stat.S_IEXEC)
+
+    def disable(self):
+        """Remove hookfile executable bit to deny triggering
+        """
+        super(LoggedHook, self).disable()
+        os.chmod(self.wrappedfile, stat.S_IREAD | stat.S_IWRITE)
+
+    def is_active(self):
+        """Check if hook is active by verifying the execute bit
+        """
+        parent_is_active = super(LoggedHook, self).disable()
+        return parent_is_active and os.access(self.wrappedfile, os.X_OK)
+
+    def get_logs(self):
+        """Return a dictionary containing the logs collected with the wrapper
+        in a python friendly format:
+        * JSON is parsed as python dictionaries
+        * timestamps are parsed as datetime objects
+        """
+        log = self._parse_log()
+        newlog = {}
+
+        json_decoder = json.JSONDecoder().decode
+
+        for k1 in log:
+            # Timestamps
+            if k1 == "calls":
+                timestamp = lambda x: datetime.fromtimestamp(int(x) / 1e9)
+                newlog[k1] = map(timestamp, log[k1])
+
+            elif k1 in ("input", "output"):
+                newlog[k1] = {}
+
+                for k2 in log[k1]:
+                    if k2 == "json":
+                        # JSON replies
+                        newlog[k1][k2] = map(json_decoder, log[k1][k2])
+                    else:
+                        # Messages and future fields
+                        newlog[k1][k2] = deepcopy(log[k1][k2])
+            else:
+                # exitcode and future fields
+                newlog[k1] = deepcopy(log[k1])
+
+        return newlog
+
+    def assert_triggered(self):
+        """Check if current hook file was triggered/used by taskwarrior
+        """
+        log = self._parse_log()
+
+        if log["calls"]:
+            return True
+        else:
+            return False
+
+    def assert_triggered_count(self, count):
+        """Check if current hook file was triggered/used by taskwarrior and
+        how many times.
+        """
+        log = self._parse_log()
+
+        if len(log["calls"]) == count:
+            return True
+        else:
+            return False
+
+    def assert_exitcode(self, exitcode):
+        """Check if current hook finished with the expected exit code
+        """
+        log = self._parse_log()
+
+        if log["exitcode"] == exitcode:
+            return True
+        else:
+            return False
+
+# vim: ai sts=4 et sw=4

test/basetest/task.py

@@ -1,140 +1,14 @@
 # -*- coding: utf-8 -*-
 
 import os
-from sys import stderr
 import tempfile
 import shutil
-import stat
 import atexit
 import unittest
-from .utils import run_cmd_wait, run_cmd_wait_nofail, which, binary_location
+from .utils import (run_cmd_wait, run_cmd_wait_nofail, which, binary_location,
-from .exceptions import CommandError, HookError
+                    )
-
+from .exceptions import CommandError
-
+from .hooks import Hooks
-class Hooks(object):
-    """Abstraction to help interact with hooks (add, remove, enable, disable)
-    during tests
-    """
-    def __init__(self, datadir):
-        self.hookdir = os.path.join(datadir, "hooks")
-        self._hooks = {}
-
-        # Check if the hooks dir already exists
-        if not os.path.isdir(self.hookdir):
-            os.mkdir(self.hookdir)
-
-    def __repr__(self):
-        enabled = []
-        disabled = []
-
-        for hook in self._hooks:
-            if self.isactive(hook):
-                enabled.append(hook)
-            else:
-                disabled.append(hook)
-
-        enabled = ", ".join(enabled) or None
-        disabled = ", ".join(disabled) or None
-
-        return "<Hooks: enabled: {0} | disabled: {1}>".format(enabled,
-                                                              disabled)
-
-    def get_hookfile(self, hookname):
-        """Return location of given hookname"""
-        return os.path.join(self.hookdir, hookname)
-
-    def check_exists(self, hookname):
-        """Checks if the file pointed to by hookfile exists"""
-
-        hookfile = self.get_hookfile(hookname)
-
-        if not os.path.isfile(hookfile):
-            raise HookError("Hook {0} doesn't exist.".format(hookfile))
-
-        return hookfile
-
-    def enable(self, hookname):
-        """Make hookfile executable to allow triggering
-        """
-        hookfile = self.check_exists(hookname)
-        os.chmod(hookfile, stat.S_IREAD | stat.S_IWRITE | stat.S_IEXEC)
-
-    def disable(self, hookname):
-        """Remove hookfile executable bit to deny triggering
-        """
-        hookfile = self.check_exists(hookname)
-        os.chmod(hookfile, stat.S_IREAD | stat.S_IWRITE)
-
-    def isactive(self, hookname):
-        """Check if hook is active by verifying the execute bit
-        """
-        hookfile = self.check_exists(hookname)
-        return os.access(hookfile, os.X_OK)
-
-    def add(self, hookname, content, overwrite=False):
-        """Register hook with name 'hookname' and given file content.
-
-        :param hookname: Should be a string starting with one of:
-            - on-launch
-            - on-add
-            - on-exit
-            - on-modify
-
-        :param content: Content of the file as a (multi-line) string
-        :param overwrite: What to do if a hook with same name already exists
-        """
-        for hooktype in ("on-launch", "on-add", "on-exit", "on-modify"):
-            if hookname.startswith(hooktype):
-                break
-        else:
-            stderr.write("WARNING: {0} is not a valid hook type. "
-                         "It will not be triggered\n".format(hookname))
-
-        if hookname in self._hooks and not overwrite:
-            raise HookError("Hook with name {0} already exists. "
-                            "Pass overwrite=True if intended or use "
-                            "hooks.remove() before.".format(hookname))
-        else:
-            self._hooks[hookname] = content
-
-        hookfile = self.get_hookfile(hookname)
-
-        # Create the hook on disk
-        with open(hookfile, 'w') as fh:
-            fh.write(content)
-
-        # Ensure it's executable
-        self.enable(hookname)
-
-    def remove(self, hookname):
-        """Remove the hook matching given hookname"""
-        try:
-            del self._hooks[hookname]
-        except KeyError:
-            raise HookError("Hook with name {0} in record".format(hookname))
-
-        try:
-            os.remove(self.get_hookfile(hookname))
-        except OSError as e:
-            if e.errno == 2:
-                raise HookError("Hook with name {0} was not found on hooks/ "
-                                "folder".format(hookname))
-            else:
-                raise
-
-    def clear(self):
-        """Remove all existing hooks and empty the hook registry
-        """
-        self._hooks = {}
-
-        # Remove any existing hooks
-        try:
-            shutil.rmtree(self.hookdir)
-        except OSError as e:
-            if e.errno != 2:
-                raise
-
-        os.mkdir(self.hookdir)
 
 
 class Task(object):
@@ -184,12 +58,23 @@ class Task(object):
         if self.taskd is not None:
             self.bind_taskd_server(self.taskd)
 
-        self.hooks = Hooks(self.datadir)
+        # Hooks disabled until requested
+        self.hooks = None
 
     def __repr__(self):
         txt = super(Task, self).__repr__()
         return "{0} running from {1}>".format(txt[:-1], self.datadir)
 
+    def __call__(self, *args, **kwargs):
+        "aka t = Task() ; t() which is now an alias to t.runSuccess()"
+        return self.runSuccess(*args, **kwargs)
+
+    def activate_hooks(self):
+        """Enable self.hooks functionality and activate hooks on config
+        """
+        self.config("hooks", "on")
+        self.hooks = Hooks(self.datadir)
+
     def reset_env(self):
         """Set a new environment derived from the one used to launch the test
         """
@@ -201,10 +86,6 @@ class Task(object):
         # As well as TASKRC
         self.env["TASKRC"] = self.taskrc
 
-    def __call__(self, *args, **kwargs):
-        "aka t = Task() ; t() which is now an alias to t.runSuccess()"
-        return self.runSuccess(*args, **kwargs)
-
     def bind_taskd_server(self, taskd):
         """Configure the present task client to talk to given taskd server
 

test/basetest/taskd.py

@@ -8,7 +8,7 @@ import atexit
 from time import sleep
 from subprocess import Popen
 from .utils import (find_unused_port, release_port, port_used, run_cmd_wait,
-                    which, parse_datafile, CURRENT_DIR, binary_location)
+                    which, parse_datafile, DEFAULT_CERT_PATH, binary_location)
 from .exceptions import CommandError
 
 try:
@@ -16,11 +16,6 @@ try:
 except ImportError:
     DEVNULL = open(os.devnull, 'w')
 
-# Directory relative to basetest module location
-DEFAULT_CERT_PATH = os.path.abspath(
-    os.path.join(CURRENT_DIR, "..", "test_certs")
-)
-
 
 class Taskd(object):
     """Manage a taskd instance

test/basetest/utils.py

@@ -26,6 +26,17 @@ BIN_PREFIX = os.path.abspath(
     os.path.join(CURRENT_DIR, "..", "..", "src")
 )
 
+# Default location of test certificates
+DEFAULT_CERT_PATH = os.path.abspath(
+    os.path.join(CURRENT_DIR, "..", "test_certs")
+)
+
+# Default location of test hooks
+DEFAULT_HOOK_PATH = os.path.abspath(
+    os.path.join(CURRENT_DIR, "..", "test_hooks")
+)
+
+
 # Environment flags to control skipping of task and taskd tests
 TASKW_SKIP = os.environ.get("TASKW_SKIP", False)
 TASKD_SKIP = os.environ.get("TASKD_SKIP", False)

test/test_hooks/on-add.dummy

@@ -0,0 +1,10 @@
+#!/bin/sh
+
+echo "on-add executed"
+
+while read TASK; do
+    echo "New task $TASK"
+    echo $TASK
+done
+
+exit 0

test/test_hooks/on-exit.dummy

@@ -0,0 +1,9 @@
+#!/bin/sh
+
+echo "on-exit executed"
+
+while read TASK; do
+    echo "New/modified task $TASK"
+done
+
+exit 0

test/test_hooks/on-launch.dummy

@@ -0,0 +1,5 @@
+#!/bin/sh
+
+echo "on-launch executed"
+
+exit 0

test/test_hooks/on-modify.dummy

@@ -0,0 +1,10 @@
+#!/bin/sh
+
+echo "on-modify executed"
+
+while read TASK MODTASK; do
+    echo "Existing task $TASK modified to $MODTASK"
+    echo $MODTASK
+done
+
+exit 0

test/test_hooks/wrapper.sh

@@ -0,0 +1,16 @@
+#!/bin/bash
+
+SELF=$(basename $0)
+ORIGINALHOOK="$(dirname $0)/original_${SELF}"
+IN="${NEWFILE}.log.in"
+OUT="${NEWFILE}.log.out"
+
+# Let it know that we were executed
+echo "% Called at $(date +%s%N)" >> ${OUT}
+
+$ORIGINALHOOK < <(tee -a ${IN}) > >(tee -a ${OUT})
+
+EXITCODE=$?
+echo "! Exit code: ${EXITCODE}" >> ${OUT}
+
+exit $EXITCODE