Merge ~kissiel/checkbox-support:import-watchers into checkbox-support:master

[Maciej Kisielewski]

This MR imports run_watcher that is used in usb tests to checkbox_support.

And removes x flag from the scripts, as it now should be available 'globally' after installing, or including in a snap, checkbox-support.

The entry point is checkbox-support-run_watcher - I left the underscore, and I'm treating checkbox-support part as a prefix.

[Jonathan Cave (jocave)]

Yes please, stops us needing to import it in to each provider that wants to define its own usb tests.

review: Approve

[Paul Larson (pwlars)]

You may want to take a look at https://pypi.python.org/pypi/inotify but don't use pyinotify

[Maciej Kisielewski (kissiel)]

w00t, let's land it

diff --git a/checkbox_support/log_watcher.py b/checkbox_support/log_watcher.py
new file mode 100644
index 0000000..4ae2da5
--- /dev/null
+++ b/checkbox_support/log_watcher.py
@@ -0,0 +1,276 @@
+#!/usr/bin/env python3
+"""
+Real-time log files watcher supporting log rotation.
+
+Works with Python >= 2.6 and >= 3.2, on both POSIX and Windows.
+
+
+License: MIT
+
+Original work Copyright (c) Giampaolo Rodola' <g.rodola [AT] gmail [DOT] com>
+Modified work Copyright (c) 2015-2016: Taihsiang Ho <[e-mail]>
+
+Permission is hereby granted, free of charge, to any person obtaining a copy of
+this software and associated documentation files (the "Software"), to deal in
+the Software without restriction, including without limitation the rights to
+use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies
+of the Software, and to permit persons to whom the Software is furnished to do
+so, subject to the following conditions:
+
+The above copyright notice and this permission notice shall be included in all
+copies or substantial portions of the Software.
+
+THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+SOFTWARE.
+"""
+import os
+import time
+import errno
+import stat
+
+
+class LogWatcher(object):
+
+    """
+    Looks for changes in all files of a directory.
+
+    This is useful for watching log file changes in real-time.
+    It also supports files rotation.
+
+    Example:
+
+    >>> def callback(filename, lines):
+    ...     print(filename, lines)
+    ...
+    >>> lw = LogWatcher("/var/log/", callback)
+    >>> lw.loop()
+    """
+
+    def __init__(self, folder: str, callback: 'Callable[[str], List[str]]',
+                 extensions: "List[str]"=None, logfile: str=None,
+                 tail_lines: int=0,
+                 sizehint: int=1048576):
+        """
+        Initialize a new log watcher.
+
+        :param folder: str
+            the folder to watch
+
+        :param callback: callback
+            a function which is called every time one of the file being
+            watched is updated;
+            this is called with "filename" and "lines" arguments.
+
+        :param extensions: list
+            only watch files with these extensions
+
+        :param logfile: str
+            only watch this file. if this var exists,
+            it will override extention list above.
+
+        :param tail_lines: int
+            read last N lines from files being watched before starting
+
+        :param sizehint: int
+            passed to file.readlines(), represents an
+            approximation of the maximum number of bytes to read from
+            a file on every ieration (as opposed to load the entire
+            file in memory until EOF is reached). Defaults to 1MB.
+        """
+        self.folder = os.path.realpath(folder)
+        self.extensions = extensions
+        self.logfile = logfile
+        self._files_map = {}
+        self._callback = callback
+        self._sizehint = sizehint
+        assert os.path.isdir(self.folder), self.folder
+        assert callable(callback), repr(callback)
+        self.update_files()
+        for id, file in self._files_map.items():
+            file.seek(os.path.getsize(file.name))  # EOF
+            if tail_lines:
+                try:
+                    lines = self.tail(file.name, tail_lines)
+                except IOError as err:
+                    if err.errno != errno.ENOENT:
+                        raise
+                else:
+                    if lines:
+                        self._callback(file.name, lines)
+
+    def __enter__(self):
+        return self
+
+    def __exit__(self, *args):
+        self.close()
+
+    def __del__(self):
+        self.close()
+
+    def loop(self, interval=0.1, blocking=True):
+        """Start a busy loop checking for file changes every *interval*
+        seconds. If *blocking* is False make one loop then return.
+        """
+        # May be overridden in order to use pyinotify lib and block
+        # until the directory being watched is updated.
+        # Note that directly calling readlines() as we do is faster
+        # than first checking file's last modification times.
+        while True:
+            self.update_files()
+            for fid, file in list(self._files_map.items()):
+                self.readlines(file)
+            if not blocking:
+                return
+            time.sleep(interval)
+
+    def log(self, line):
+        """Log when a file is un/watched"""
+        print(line)
+
+    def listdir(self):
+        """List directory and filter files by extension.
+        You may want to override this to add extra logic or globbing
+        support.
+        """
+        ls = os.listdir(self.folder)
+        if self.extensions:
+            ls = [x for x in ls if os.path.splitext(x)[1][1:]
+                  in self.extensions]
+        if self.logfile in ls:
+            ls = [self.logfile]
+
+        return ls
+
+    @classmethod
+    def open(cls, file):
+        """Wrapper around open().
+        By default files are opened in binary mode and readlines()
+        will return bytes on both Python 2 and 3.
+        This means callback() will deal with a list of bytes.
+        Can be overridden in order to deal with unicode strings
+        instead, like this:
+
+          import codecs, locale
+          return codecs.open(file, 'r', encoding=locale.getpreferredencoding(),
+                             errors='ignore')
+        """
+        return open(file, 'rb')
+
+    @classmethod
+    def tail(cls, fname, window):
+        """Read last N lines from file fname."""
+        if window <= 0:
+            raise ValueError('invalid window value %r' % window)
+        with cls.open(fname) as f:
+            buffer_size = 1024
+            # True if open() was overridden and file was opened in text
+            # mode. In that case readlines() will return unicode strings
+            # instead of bytes.
+            encoded = getattr(f, 'encoding', False)
+            CR = '\n' if encoded else b'\n'
+            data = '' if encoded else b''
+            f.seek(0, os.SEEK_END)
+            fsize = f.tell()
+            block = -1
+            exit = False
+            while not exit:
+                step = (block * buffer_size)
+                if abs(step) >= fsize:
+                    f.seek(0)
+                    newdata = f.read(buffer_size - (abs(step) - fsize))
+                    exit = True
+                else:
+                    f.seek(step, os.SEEK_END)
+                    newdata = f.read(buffer_size)
+                data = newdata + data
+                if data.count(CR) >= window:
+                    break
+                else:
+                    block -= 1
+            return data.splitlines()[-window:]
+
+    def update_files(self):
+        ls = []
+        for name in self.listdir():
+            absname = os.path.realpath(os.path.join(self.folder, name))
+            try:
+                st = os.stat(absname)
+            except EnvironmentError as err:
+                if err.errno != errno.ENOENT:
+                    raise
+            else:
+                if not stat.S_ISREG(st.st_mode):
+                    continue
+                fid = self.get_file_id(st)
+                ls.append((fid, absname))
+
+        # check existent files
+        for fid, file in list(self._files_map.items()):
+            try:
+                st = os.stat(file.name)
+            except EnvironmentError as err:
+                if err.errno == errno.ENOENT:
+                    self.unwatch(file, fid)
+                else:
+                    raise
+            else:
+                if fid != self.get_file_id(st):
+                    # same name but different file (rotation); reload it.
+                    self.unwatch(file, fid)
+                    self.watch(file.name)
+
+        # add new ones
+        for fid, fname in ls:
+            if fid not in self._files_map:
+                self.watch(fname)
+
+    def readlines(self, file):
+        """
+        Read file lines.
+
+        Since last access until EOF is reached and invoke callback.
+        """
+        while True:
+            lines = file.readlines(self._sizehint)
+            if not lines:
+                break
+            self._callback(file.name, lines)
+
+    def watch(self, fname):
+        try:
+            file = self.open(fname)
+            fid = self.get_file_id(os.stat(fname))
+        except EnvironmentError as err:
+            if err.errno != errno.ENOENT:
+                raise
+        else:
+            self.log("watching logfile %s" % fname)
+            self._files_map[fid] = file
+
+    def unwatch(self, file, fid):
+        # File no longer exists. If it has been renamed try to read it
+        # for the last time in case we're dealing with a rotating log
+        # file.
+        self.log("un-watching logfile %s" % file.name)
+        del self._files_map[fid]
+        with file:
+            lines = self.readlines(file)
+            if lines:
+                self._callback(file.name, lines)
+
+    @staticmethod
+    def get_file_id(st):
+        if os.name == 'posix':
+            return "%xg%x" % (st.st_dev, st.st_ino)
+        else:
+            return "%f" % st.st_ctime
+
+    def close(self):
+        for id, file in self._files_map.items():
+            file.close()
+        self._files_map.clear()
diff --git a/checkbox_support/scripts/run_watcher.py b/checkbox_support/scripts/run_watcher.py
new file mode 100644
index 0000000..50f2db1
--- /dev/null
+++ b/checkbox_support/scripts/run_watcher.py
@@ -0,0 +1,231 @@
+#!/usr/bin/env python3
+# Copyright 2015-2016 Canonical Ltd.
+# All rights reserved.
+#
+# Written by:
+#   Taihsiang Ho <[e-mail]>
+"""
+application to use LogWatcher.
+
+this script use LogWatcher to define the actual behavior to watch log files by
+a customized callback.
+"""
+import argparse
+import contextlib
+import sys
+import os
+import re
+import signal
+import logging
+from checkbox_support.log_watcher import LogWatcher
+
+global ARGS
+USB_INSERT_TIMEOUT = 30  # sec
+
+# {log_string_1:status_1, log_string_2:status_2 ...}
+FLAG_DETECTION = {"device": {
+                  "new high-speed USB device number": False,
+                  "new SuperSpeed USB device number": False
+                  },
+                  "driver": {
+                      "using ehci_hcd": False,
+                      "using xhci_hcd": False
+                      },
+                  "insertion": {
+                      "USB Mass Storage device detected": False
+                      },
+                  "removal": {
+                      "USB disconnect, device number": False
+                      }
+                  }
+
+
+MOUNTED_PARTITION_CANDIDATES = None
+MOUNTED_PARTITION = None
+
+logging.basicConfig(level=logging.WARNING)
+
+
+######################################################
+# run the log watcher
+######################################################
+
+
+def callback(filename, lines):
+    """
+    a callback function for LogWatcher.
+
+    customized callback to define the actual behavior about how to watch and
+    what to watch of the log files.
+
+    :param filename: str, a text filename. usually be a log file.
+    :param lines: list, contents the elements as string to tell what to watch.
+    """
+    for line in lines:
+        line_str = str(line)
+        refresh_detection(line_str)
+        get_partition_info(line_str)
+        report_detection()
+
+
+def detect_str(line, str_2_detect):
+    """detect the string in the line."""
+    if str_2_detect in line:
+        return True
+    return False
+
+
+def detect_partition(line):
+    """
+    detect device and partition info from lines.
+
+    :param line:
+        str, line string from log file
+
+    :return :
+        a list denoting [device, partition1, partition2 ...]
+        from syslog
+    """
+    # looking for string like
+    # sdb: sdb1
+    pattern = "sd.+sd.+"
+    match = re.search(pattern, line)
+    if match:
+        # remove the trailing \n and quote
+        match_string = match.group()[:-3]
+        # will looks like
+        # ['sdb', ' sdb1']
+        match_list = match_string.split(":")
+        return match_list
+
+
+def get_partition_info(line_str):
+    """get partition info."""
+    global MOUNTED_PARTITION_CANDIDATES, MOUNTED_PARTITION
+    MOUNTED_PARTITION_CANDIDIATES = detect_partition(line_str)
+    if (MOUNTED_PARTITION_CANDIDIATES and
+       len(MOUNTED_PARTITION_CANDIDIATES) == 2):
+        # hard code because I expect
+        # FLAG_MOUNT_DEVICE_CANDIDIATES is something like ['sdb', ' sdb1']
+        # This should be smarter if the device has multiple partitions.
+        MOUNTED_PARTITION = MOUNTED_PARTITION_CANDIDIATES[1].strip()
+
+
+def refresh_detection(line_str):
+    """
+    refresh values of the dictionary FLAG_DETECTION.
+
+    :param line_str: str of the scanned log lines.
+    """
+    global FLAG_DETECTION
+    for key in FLAG_DETECTION.keys():
+        for sub_key in FLAG_DETECTION[key].keys():
+            if detect_str(line_str, sub_key):
+                FLAG_DETECTION[key][sub_key] = True
+
+
+def report_detection():
+    """report detection status."""
+    # insertion detection
+    if (
+        ARGS.testcase == "insertion" and
+        FLAG_DETECTION["insertion"]["USB Mass Storage device detected"] and
+        MOUNTED_PARTITION
+    ):
+        device = ""
+        driver = ""
+        for key in FLAG_DETECTION["device"]:
+            if FLAG_DETECTION["device"][key]:
+                device = key
+        for key in FLAG_DETECTION["driver"]:
+            if FLAG_DETECTION["driver"][key]:
+                driver = key
+        logging.info("%s was inserted %s controller" % (device, driver))
+        logging.info("usable partition: %s" % MOUNTED_PARTITION)
+
+        # judge the detection by the expection
+        if (
+            ARGS.usb_type == 'usb2' and
+            device == "new high-speed USB device number"
+        ):
+            print("USB2 insertion test passed.")
+            write_usb_info()
+            sys.exit()
+        if (
+            ARGS.usb_type == 'usb3' and
+            device == "new SuperSpeed USB device number"
+        ):
+            print("USB3 insertion test passed.")
+            write_usb_info()
+            sys.exit()
+
+    # removal detection
+    if (
+        ARGS.testcase == "removal" and
+        FLAG_DETECTION["removal"]["USB disconnect, device number"]
+    ):
+        logging.info("An USB mass storage was removed.")
+        remove_usb_info()
+        sys.exit()
+
+
+def write_usb_info():
+    """
+    reserve detected usb storage info.
+
+    write the info we got in this script to $PLAINBOX_SESSION_SHARE
+    so the other jobs, e.g. read/write test, could know more information,
+    for example the partition it want to try to mount.
+    """
+    plainbox_session_share = os.environ.get('PLAINBOX_SESSION_SHARE')
+    if not plainbox_session_share:
+        logging.warning("no env var PLAINBOX_SESSION_SHARE")
+        sys.exit(1)
+
+    if MOUNTED_PARTITION:
+        logging.info(
+            "cache file usb_insert_info is at: %s" % plainbox_session_share)
+        file_to_share = open(
+            os.path.join(plainbox_session_share, "usb_insert_info"), "w")
+        file_to_share.write(MOUNTED_PARTITION + "\n")
+        file_to_share.close()
+
+
+def remove_usb_info():
+    """remove usb strage info from  $PLAINBOX_SESSION_SHARE."""
+    plainbox_session_share = os.environ.get('PLAINBOX_SESSION_SHARE')
+    if not plainbox_session_share:
+        logging.warning("no env var PLAINBOX_SESSION_SHARE")
+        sys.exit(1)
+        file_to_share = os.path.join(plainbox_session_share, "usb_insert_info")
+        with contextlib.suppress(FileNotFoundError):
+            os.remove(file_to_share)
+
+
+def no_usb_timeout(signum, frame):
+    """
+    define timeout feature.
+
+    timeout and return failure if there is no usb insertion is detected
+    after USB_INSERT_TIMEOUT secs
+    """
+    logging.info("no USB storage insertion was detected from /var/log/syslog")
+    sys.exit(1)
+
+def main():
+    # access the parser
+    parser = argparse.ArgumentParser()
+    parser.add_argument('testcase',
+                        choices=['insertion', 'removal'],
+                        help=("insertion or removal"))
+    parser.add_argument('usb_type',
+                        choices=['usb2', 'usb3'],
+                        help=("usb2 or usb3"))
+    global ARGS
+    ARGS = parser.parse_args()
+
+    # set up the log watcher
+    watcher = LogWatcher("/var/log", callback, logfile="syslog")
+    signal.signal(signal.SIGALRM, no_usb_timeout)
+    signal.alarm(USB_INSERT_TIMEOUT)
+    watcher.loop()
diff --git a/setup.py b/setup.py
index e835917..00f655e 100755
--- a/setup.py
+++ b/setup.py
@@ -75,5 +75,8 @@ setup(
             ("bto=checkbox_support.parsers.image_info:parse_bto_attachment"
              "_output"),
         ],
+        'console_scripts': [
+            "checkbox-support-run_watcher=checkbox_support.scripts.run_watcher:main",
+        ],
     },
 )