Merge ~sylvain-pineau/checkbox-support:run_watcher_systemd into checkbox-support:master

[Sylvain Pineau]

accessing syslog is not possible on UC18 and the same events can be found in systemd journal.

This MR updates the run watcher usb tool to rely on python3-systemd to still get the insert/remove events.

as part of this transition, the script now uses a class instead of globals.
log_watcher was only needed by this script so removed.

Tested on Desktop classic 18.04

[Maciej Kisielewski (kissiel)]

Code looks good. +1
And I love (+158/-480).

Total nitpick would be that some not perfect code got copied. Like string interpolation in logger calls and using .warning() when stuff is an error.

review: Approve

[Jonathan Cave (jocave)]

I'm testing this on a gen2c board and the device insertion is not being detected. Would like to check the appropriate messages and being generated and searched for.

review: Needs Information

[Sylvain Pineau (sylvain-pineau)]

Fixed Maciej's nitpicks

For info, the parts update is here: https://code.launchpad.net/~sylvain-pineau/checkbox/+git/checkbox-dev-parts/+merge/353699

review: Needs Resubmitting

[Jonathan Cave (jocave)]

My findings are that the code works perfectly *if* the systemd libraries used by the checkbox snap match the version of systemd that is running the system journal.

i.e. if the device is an Ubuntu Core 18 device then the checkbox snap must have been built on bionic and target core18. If the device is a Ubuntu Core 16 device the snap must have been built on xenial

Therefore I see no problem with the code, but I think we need firm plan on how we are going to test devices before landing this.

[Jonathan Cave (jocave)]

We are now in a position to build snaps for different series so I think we can land this.

review: Approve

diff --git a/checkbox_support/log_watcher.py b/checkbox_support/log_watcher.py
deleted file mode 100644
index 4ae2da5..0000000
--- a/checkbox_support/log_watcher.py
+++ /dev/null
@@ -1,276 +0,0 @@
-#!/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
index 9283db6..24653a5 100644
--- a/checkbox_support/scripts/run_watcher.py
+++ b/checkbox_support/scripts/run_watcher.py
@@ -1,219 +1,182 @@
 #!/usr/bin/env python3
-# Copyright 2015-2016 Canonical Ltd.
+# Copyright 2015-2018 Canonical Ltd.
 # All rights reserved.
 #
 # Written by:
 #   Taihsiang Ho <[e-mail]>
+#   Sylvain Pineau <[e-mail]>
 """
-application to use LogWatcher.
-
-this script use LogWatcher to define the actual behavior to watch log files by
-a customized callback.
+this script monitors the systemd journal to catch insert/removal USB events
 """
 import argparse
 import contextlib
-import sys
+import logging
 import os
 import re
+import select
 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
+import sys
+from systemd import journal
+
+
+logger = logging.getLogger(__file__)
+logger.setLevel(logging.INFO)
+logger.addHandler(logging.StreamHandler(sys.stdout))
+
+
+class USBWatcher:
+
+    PART_RE = re.compile("sd\w+:.*(?P<part_name>sd\w+)")
+    USB_ACTION_TIMEOUT = 30  # sec
+    FLAG_DETECTION = {"device": {
+                      "new high-speed USB device number": False,
+                      "new SuperSpeed USB device number": False
                       },
-                  "removal": {
-                      "USB disconnect, 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
+
+    def __init__(self, args):
+        self.args = args
+        self.MOUNTED_PARTITION = None
+        signal.signal(signal.SIGALRM, self._no_usb_timeout)
+        signal.alarm(self.USB_ACTION_TIMEOUT)
+
+    def run(self):
+        j = journal.Reader()
+        j.seek_tail()
+        p = select.poll()
+        p.register(j, j.get_events())
+        if self.args.testcase == "insertion":
+            print("\n\nINSERT NOW\n\n", flush=True)
+        elif self.args.testcase == "removal":
+            print("\n\nREMOVE NOW\n\n", flush=True)
+        while p.poll():
+            if j.process() != journal.APPEND:
+                continue
+            self._callback([e['MESSAGE'] for e in j if e])
+
+    def _callback(self, lines):
+        for line in lines:
+            line_str = str(line)
+            self._refresh_detection(line_str)
+            self._get_partition_info(line_str)
+            self._report_detection()
+
+    def _get_partition_info(self, line_str):
+        """get partition info."""
+        # looking for string like "sdb: sdb1"
+        match = re.search(self.PART_RE, line_str)
+        if match:
+            self.MOUNTED_PARTITION = match.group('part_name')
+
+    def _refresh_detection(self, line_str):
+        """
+        refresh values of the dictionary FLAG_DETECTION.
+
+        :param line_str: str of the scanned log lines.
+        """
+        for key in self.FLAG_DETECTION.keys():
+            for sub_key in self.FLAG_DETECTION[key].keys():
+                if sub_key in line_str:
+                    self.FLAG_DETECTION[key][sub_key] = True
+
+    def _report_detection(self):
+        """report detection status."""
+        # insertion detection
         if (
-            ARGS.usb_type == 'usb2' and
-            device == "new high-speed USB device number"
+            self.args.testcase == "insertion" and
+            self.FLAG_DETECTION["insertion"]["USB Mass Storage device detected"] and
+            self.MOUNTED_PARTITION
         ):
-            print("USB2 insertion test passed.")
-            write_usb_info()
-            sys.exit()
+            device = ""
+            driver = ""
+            for key in self.FLAG_DETECTION["device"]:
+                if self.FLAG_DETECTION["device"][key]:
+                    device = key
+            for key in self.FLAG_DETECTION["driver"]:
+                if self.FLAG_DETECTION["driver"][key]:
+                    driver = key
+            logger.info("%s was inserted %s controller" % (device, driver))
+            logger.info("usable partition: %s" % self.MOUNTED_PARTITION)
+            # judge the detection by the expection
+            if (
+                self.args.usb_type == 'usb2' and
+                device == "new high-speed USB device number"
+            ):
+                logger.info("USB2 insertion test passed.")
+                self._write_usb_info()
+                sys.exit()
+            if (
+                self.args.usb_type == 'usb3' and
+                device == "new SuperSpeed USB device number"
+            ):
+                logger.info("USB3 insertion test passed.")
+                self._write_usb_info()
+                sys.exit()
+        # removal detection
         if (
-            ARGS.usb_type == 'usb3' and
-            device == "new SuperSpeed USB device number"
+            self.args.testcase == "removal" and
+            self.FLAG_DETECTION["removal"]["USB disconnect, device number"]
         ):
-            print("USB3 insertion test passed.")
-            write_usb_info()
+            logger.info("Removal test passed.")
+            self._remove_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")
+    def _write_usb_info(self):
+        """
+        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:
+            logger.error("no env var PLAINBOX_SESSION_SHARE")
+            sys.exit(1)
+        if self.MOUNTED_PARTITION:
+            logger.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(self.MOUNTED_PARTITION + "\n")
+            file_to_share.close()
+
+    def _remove_usb_info(self):
+        """remove usb strage info from $PLAINBOX_SESSION_SHARE."""
+        plainbox_session_share = os.environ.get('PLAINBOX_SESSION_SHARE')
+        if not plainbox_session_share:
+            logger.error("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(self, signum, frame):
+        """
+        define timeout feature.
+
+        timeout and return failure if there is no usb insertion/removal
+        detected after USB_ACTION_TIMEOUT secs
+        """
+        logger.error(
+            "no USB storage %s was reported in systemd journal"
+            % self.args.testcase)
         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'],
@@ -221,18 +184,9 @@ def main():
     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)
-    if ARGS.testcase == "insertion":
-        print("\n\nINSERT NOW\n\n", flush=True)
-    elif ARGS.testcase == "removal":
-        print("\n\nREMOVE NOW\n\n", flush=True)
-    watcher.loop()
+    args = parser.parse_args()
+    watcher = USBWatcher(args)
+    watcher.run()
 
 
 if __name__ == "__main__":