add search_journalctl module test

roles/openshift_health_checker/library/search_journalctl.py

@@ -1,13 +1,13 @@
 #!/usr/bin/python
 """Interface to journalctl"""
 
+from ansible.module_utils.basic import AnsibleModule
+
 from time import time
 import json
 import re
 import subprocess
 
-from ansible.module_utils.basic import AnsibleModule
-
 
 def _exit_json(module, errors, matched_expressions, msg):
     module.exit_json(
@@ -24,59 +24,107 @@ def _stamp_too_old(stamp, time_limit):
     return epoch - (time() - time_limit) < 0
 
 
-def find_matches(matcher, log_count_limit, time_limit_seconds):
-    """Receives a matcher dictionary and scans journalctl at the given systemd module
-    for log messages matching a given regular expression.
+def find_matches(log_input, matcher, log_count_limit, time_limit_seconds):
+    """Receives iterable input, a matcher dictionary and scans journalctl at the
+    given systemd module for log messages matching a given regular expression.
     Returns the matched log message (or None) and an error string if any."""
     try:
         regexp = re.compile(matcher["regexp"])
-    except ValueError as err:
+        start_regexp = re.compile(matcher["start_regexp"])
+    except re.error as err:
         return None, str(err)
 
     log_count = 0
+    matched = None
 
-    cmd = [
-        '/bin/journalctl',
-        '-ru', matcher["unit"],
-        '--output', 'json',
-    ]
+    for line in log_input:
+        log_count += 1
+        if log_count >= log_count_limit:
+            break
 
-    matched = None
-    start_regexp = re.compile(matcher["start_regexp"])
+        try:
+            obj = json.loads(line.rstrip())
 
-    try:
-        cmd_output = subprocess.Popen(list(cmd), stdout=subprocess.PIPE)
+            # don't need to look past the most recent service restart
+            if start_regexp.match(obj["MESSAGE"]):
+                break
 
-        for line in iter(cmd_output.stdout.readline, ''):
-            log_count += 1
-            if log_count >= log_count_limit:
+            if _stamp_too_old(obj["__REALTIME_TIMESTAMP"], time_limit_seconds):
                 break
 
-            try:
-                obj = json.loads(line.rstrip())
+            if regexp.match(obj["MESSAGE"]):
+                matched = line.rstrip()
+                break
+
+        except ValueError as err:
+            return None, str(err)
+
+    return matched, None
+
+
+def _ensure_matcher_fields(matcher):
+    required_fields = [
+        "start_regexp",
+        "regexp",
+        "unit",
+    ]
+    missing_fields = set(required_fields) - set([field for field in matcher])
+    if len(missing_fields):
+        raise InvalidMatcherException("Matcher missing required fields", list(missing_fields))
+
+
+def _get_log_matches(matchers, log_count_limit, time_limit_seconds):
+    matched_regexp = []
+    errors = []
+
+    for matcher in matchers:
+        try:
+            _ensure_matcher_fields(matcher)
+        except InvalidMatcherException as err:
+            errors.append(str(err))
+            continue
+
+        log_input, error = get_log_input(matcher)
+        if error:
+            errors.append(error)
+            continue
+
+        matched, error = find_matches(log_input, matcher, log_count_limit, time_limit_seconds)
+        if matched:
+            matched_regexp.append(matcher["regexp"])
+            continue
+
+        if error:
+            errors.append(error)
 
-                # don't need to look past the most recent service restart
-                if start_regexp.match(obj["MESSAGE"]):
-                    break
+    return matched_regexp, errors
 
-                if _stamp_too_old(obj["__REALTIME_TIMESTAMP"], time_limit_seconds):
-                    break
 
-                if regexp.match(obj["MESSAGE"]):
-                    matched = line.rstrip()
-                    break
+def get_log_input(matcher):
+    try:
+        cmd_output = subprocess.Popen(list([
+            '/bin/journalctl',
+            '-ru', matcher["unit"],
+            '--output', 'json',
+        ]), stdout=subprocess.PIPE)
 
-            except ValueError:
-                continue
+        return iter(cmd_output.stdout.readline, ''), None
 
-        return matched, False
     except subprocess.CalledProcessError as exc:
         err = '[rc {}] {}\n{}'.format(exc.returncode, ' '.join(exc.cmd), exc.output)
-        return None, err
+        return None, str(err)
+
     except OSError as exc:
         return None, str(exc)
 
 
+class InvalidMatcherException(Exception):
+    """Base exception class for missing or invalid matcher fields"""
+    def __init__(self, message, missing_fields=None):
+        Exception.__init__(self, message)
+        self.missing_fields = missing_fields
+
+
 def main():
     """Scans a given list of matchers for journalctl messages matching given patterns"""
     module = AnsibleModule(
@@ -90,19 +138,9 @@ def main():
 
     log_count_limit = module.params["log_count_limit"]
     log_matchers = module.params["log_matchers"]
-    matched_regexp = []
-    errors = []
     msg = ""
 
-    for matcher in log_matchers:
-        matched, error = find_matches(matcher, log_count_limit, time_limit_seconds)
-        if matched:
-            matched_regexp.append(matcher["regexp"])
-            continue
-
-        if error:
-            errors.append(error)
-
+    matched_regexp, errors = _get_log_matches(log_matchers, log_count_limit, time_limit_seconds)
     if not matched_regexp:
         msg = "No log messages matched any given expressions"
 

roles/openshift_health_checker/openshift_checks/etcd_traffic.py

@@ -28,7 +28,6 @@ def run(self, tmp, task_vars):
         log_matchers = [{
             "start_regexp": r"Starting Etcd Server",
             "regexp": r"etcd: sync duration of \d+\.\d+s, expected less than 1s",
-            "level": "warning",
             "unit": unit
         }]
 

roles/openshift_health_checker/test/search_journalctl_test.py

@@ -0,0 +1,192 @@
+import pytest
+import search_journalctl
+from time import time
+
+
+SAVED_TIMESTAMPS = list()
+
+
+def canned_search_journalctl(get_log_input=None):
+    """Create a Curator check object with canned get_log_input method"""
+    module = search_journalctl  # fails if a module is actually invoked
+    if get_log_input:
+        module.get_log_input = get_log_input
+    return module
+
+
+def get_timestamp_ms(modifier=0, saveto=None):
+    t = str(time() + modifier).split(".")[0] + "000000"
+    if type(saveto) is list:
+        saveto.append(t)
+    return t
+
+
+def create_test_log_object(stamp, msg):
+    return '{{"__REALTIME_TIMESTAMP": "{}", "MESSAGE": "{}"}}'.format(stamp, msg)
+
+
+@pytest.mark.parametrize('stamp,time_limit,is_too_old', [
+    ("1496341364241717", 60 * 60, True),
+    (time() * 1000000, 60 * 60, False),
+    (time() * 500000, 10, True),
+])
+def test_stamp_too_old(stamp, time_limit, is_too_old):
+    assert search_journalctl._stamp_too_old(stamp, time_limit) == is_too_old
+
+
+@pytest.mark.parametrize('matcher,missing_fields', [
+    (
+        {
+            "start_regexp": r"sample start regexp",
+            "regexp": r"sample regexp",
+        },
+        ["unit"],
+    ),
+    (
+        {
+            "regexp": r"sample regexp",
+        },
+        ["unit", "start_regexp"],
+    ),
+    (
+        {},
+        ["unit", "start_regexp", "regexp"],
+    ),
+])
+def test_ensure_matcher_fields(matcher, missing_fields):
+    with pytest.raises(search_journalctl.InvalidMatcherException) as e:
+        search_journalctl._ensure_matcher_fields(matcher)
+    assert set(missing_fields) == set(e.value.missing_fields)
+    assert "missing required fields" in str(e.value)
+
+
+@pytest.mark.parametrize('matchers,log_input,expected_matches,expected_errors', [
+    (
+        [
+            {
+                "start_regexp": r"Sample Logs Beginning",
+                "regexp": r"test log message",
+                "unit": "test",
+            },
+        ],
+        [
+            create_test_log_object(get_timestamp_ms(), "test log message"),
+            create_test_log_object(get_timestamp_ms(), "Sample Logs Beginning"),
+        ],
+        ["test log message"],
+        [],
+    ),
+    # test with invalid json in log input
+    (
+        [
+            {
+                "start_regexp": r"Sample Logs Beginning",
+                "regexp": r"test log message",
+                "unit": "test",
+            },
+        ],
+        [
+            '{__REALTIME_TIMESTAMP: ' + str(get_timestamp_ms()) + ', "MESSAGE": "test log message"}',
+        ],
+        [],
+        ["Expecting property name"],
+    ),
+    # test with invalid regexp
+    (
+        [
+            {
+                "start_regexp": r"Sample Logs Beginning",
+                "regexp": r"test [ log message",
+                "unit": "test",
+            },
+        ],
+        [
+            create_test_log_object(get_timestamp_ms(), "test log message"),
+            create_test_log_object(get_timestamp_ms(), "sample log message"),
+            create_test_log_object(get_timestamp_ms(), "fake log message"),
+            create_test_log_object(get_timestamp_ms(), "dummy log message"),
+            create_test_log_object(get_timestamp_ms(), "Sample Logs Beginning"),
+        ],
+        [],
+        ["unexpected end of regular expression"],
+    ),
+])
+def test_get_log_matches(matchers, log_input, expected_matches, expected_errors):
+    def get_log_input(matcher):
+        return log_input, None
+
+    module = canned_search_journalctl(get_log_input)
+    matched_regexp, errors = module._get_log_matches(matchers, 500, 60 * 60)
+
+    assert set(matched_regexp) == set(expected_matches)
+    for partial_err_msg in expected_errors:
+        for actual_err_msg in errors:
+            assert partial_err_msg in actual_err_msg
+
+
+@pytest.mark.parametrize('matcher,log_count_limit,time_limit,log_input,expected_match,expected_error', [
+    # test with matching log message, but out of bounds of log_count_limit
+    # expect zero matches and no errors
+    (
+        {
+            "start_regexp": r"Sample Logs Beginning",
+            "regexp": r"dummy log message",
+            "unit": "test",
+        },
+        3,
+        100 * 60 * 60,
+        [
+            create_test_log_object(get_timestamp_ms(), "test log message"),
+            create_test_log_object(get_timestamp_ms(), "sample log message"),
+            create_test_log_object(get_timestamp_ms(), "fake log message"),
+            create_test_log_object(get_timestamp_ms(), "dummy log message"),
+            create_test_log_object(get_timestamp_ms(), "Sample Logs Beginning"),
+        ],
+        None,
+        None,
+    ),
+    # test with matching log message, but with timestamp too old
+    # expect zero matches and no errors
+    (
+        {
+            "start_regexp": r"Sample Logs Beginning",
+            "regexp": r"dummy log message",
+            "unit": "test",
+        },
+        100,
+        10,
+        [
+            create_test_log_object(get_timestamp_ms(), "test log message"),
+            create_test_log_object(get_timestamp_ms(), "sample log message"),
+            create_test_log_object(get_timestamp_ms(), "fake log message"),
+            create_test_log_object(get_timestamp_ms(-1000), "dummy log message"),
+            create_test_log_object(get_timestamp_ms(-1000), "Sample Logs Beginning"),
+        ],
+        None,
+        None,
+    ),
+    # test with matching log message, and timestamp within time limit
+    (
+        {
+            "start_regexp": r"Sample Logs Beginning",
+            "regexp": r"dummy log message",
+            "unit": "test",
+        },
+        100,
+        1010,
+        [
+            create_test_log_object(get_timestamp_ms(), "test log message"),
+            create_test_log_object(get_timestamp_ms(), "sample log message"),
+            create_test_log_object(get_timestamp_ms(), "fake log message"),
+            create_test_log_object(get_timestamp_ms(-1000, SAVED_TIMESTAMPS), "dummy log message"),
+            create_test_log_object(get_timestamp_ms(-1000), "Sample Logs Beginning"),
+        ],
+        create_test_log_object(SAVED_TIMESTAMPS[-1], "dummy log message"),
+        None,
+    ),
+])
+def test_find_matches_skips_logs(matcher, log_count_limit, time_limit, log_input, expected_match, expected_error):
+    match, error = search_journalctl.find_matches(log_input, matcher, log_count_limit, time_limit)
+
+    assert match == expected_match
+    assert error == expected_error