exception checker with context 35/72135/28
authorSam Hague <shague@redhat.com>
Mon, 21 May 2018 21:59:27 +0000 (17:59 -0400)
committerSam Hague <shague@redhat.com>
Fri, 25 May 2018 11:09:14 +0000 (11:09 +0000)
Change-Id: If1721f474abe532f947ef31aed14577aa916e7e0
Signed-off-by: Sam Hague <shague@redhat.com>
csit/libraries/KarafKeywords.robot
csit/libraries/OpenStackOperations.robot
csit/libraries/netvirt/excepts.py [new file with mode: 0644]

index d562a0c5c913b2842ec4f99959554b1eed4770a8..cece9c4490cc4594dbf90cc6d6f55239e0549004 100644 (file)
@@ -7,6 +7,7 @@ Documentation     Karaf library. General utility keywords for interacting with t
 ...               If this gets initialized, ClusterManagement gets initialized as well.
 Library           SSHLibrary
 Library           OperatingSystem
+Library           ${CURDIR}/netvirt/excepts.py
 Resource          ${CURDIR}/ClusterManagement.robot
 Resource          ${CURDIR}/SSHKeywords.robot
 Variables         ${CURDIR}/../variables/Variables.py
@@ -216,6 +217,39 @@ Set_Bgpcep_Log_Levels
     \    Execute_Controller_Karaf_Command_On_Background    log:set ${bgpcep_level} org.opendaylight.bgpcep    member_index=${index}
     \    Execute_Controller_Karaf_Command_On_Background    log:set ${protocol_level} org.opendaylight.protocol    member_index=${index}
 
+Get and Verify Exceptions
+    [Arguments]    ${lines}
+    [Documentation]    Get a list of exceptions from the given lines from a karaf log and then verify them against a
+    ...    an exception whitelist. Verify Exceptions is a python function that will return the list of unmatched
+    ...    exceptions in exlist and return the matched exceptions in matchlist. Both lists will be logged to aid
+    ...    with troubleshooting the exceptions.
+    ${exlist}    ${matchlist} =    Verify Exceptions    ${lines}
+    Collections.Log List    ${exlist}
+    Collections.Log List    ${matchlist}
+    [Return]    ${exlist}
+
+Get Karaf Log Lines From Test Start
+    [Arguments]    ${ip}    ${test_name}    ${cmd}    ${user}=${ODL_SYSTEM_USER}    ${password}=${ODL_SYSTEM_PASSWORD}    ${prompt}=${ODL_SYSTEM_PROMPT}
+    ...    ${log_file}=${KARAF_LOG}
+    [Documentation]    Scrapes all log messages that match regexp ${type} which fall after a point given by a log message that
+    ...    contains ${test_name}. This is useful if your test cases are marking karaf.log with a message indicating when
+    ...    that test case has started; such that you can easily pull out any extra log messsages to parse/log/etc in the
+    ...    test logic itself. For example, you can grab all ERRORS that occur during your test case.
+    ${output} =    Run Command On Controller    ${ip}    ${cmd}    ${user}    ${password}    ${prompt}
+    @{log_lines} =    Split String    ${output}    ${\n}
+    [Return]    ${log_lines}
+
+Fail If Exceptions Found During Test
+    [Arguments]    ${test_name}    ${log_file}=${KARAF_LOG}
+    [Documentation]    Create a failure if an Exception is found in the karaf.log that has not been whitelisted.
+    ...    Will work for single controller jobs as well as 3node cluster jobs
+    : FOR    ${i}    IN RANGE    1    ${NUM_ODL_SYSTEM} + 1
+    \    ${cmd} =    Set Variable    sed '1,/ROBOT MESSAGE: Starting test ${test_name}/d' ${log_file}
+    \    ${output} =    Get Karaf Log Lines From Test Start    ${ODL_SYSTEM_${i}_IP}    ${test_name}    ${cmd}
+    \    ${exlist} =    Get and Verify Exceptions    ${output}
+    \    ${listlength} =    BuiltIn.Get Length    ${exlist}
+    \    BuiltIn.Run Keyword If    ${listlength} != 0    BuiltIn.Fail    New exceptions found: ${listlength}
+
 Get Karaf Log Type From Test Start
     [Arguments]    ${ip}    ${test_name}    ${type}    ${user}=${ODL_SYSTEM_USER}    ${password}=${ODL_SYSTEM_PASSWORD}    ${prompt}=${ODL_SYSTEM_PROMPT}
     ...    ${log_file}=${KARAF_LOG}
@@ -244,7 +278,7 @@ Get Karaf Log Events From Test Start
     : FOR    ${i}    IN RANGE    1    ${NUM_ODL_SYSTEM} + 1
     \    Get Karaf Log Types From Test Start    ${ODL_SYSTEM_${i}_IP}    ${test_name}    ${log_types}
 
-Fail If Exceptions Found During Test
+Fail If Exceptions Found During Test Deprecated
     [Arguments]    ${test_name}    ${exceptions_white_list}=${EMPTY}
     [Documentation]    Create a failure if an Exception is found in the karaf.log. Will work for single controller jobs
     ...    as well as 3node cluster jobs
index 974440e5510d618fcac04583ee1e3afd406dc6bc..0e7bd6c67528dd0e733d6aac22a77aa06257c090 100644 (file)
@@ -544,8 +544,7 @@ Get Test Teardown Debugs
     [Arguments]    ${test_name}=${SUITE_NAME}.${TEST_NAME}
     OpenStackOperations.Get OvsDebugInfo
     BuiltIn.Run Keyword And Ignore Error    DataModels.Get Model Dump    ${HA_PROXY_IP}    ${netvirt_data_models}
-    KarafKeywords.Get Karaf Log Events From Test Start    ${test_name}
-    Run Keyword If    "${FAIL_ON_EXCEPTIONS}"=="True"    Fail If Exceptions Found During Test    ${test_name}    ${NETVIRT_EXCEPTIONS_WHITELIST}
+    Run Keyword If    "${FAIL_ON_EXCEPTIONS}"=="True"    KarafKeywords.Fail If Exceptions Found During Test    ${test_name}
 
 Get Test Teardown Debugs For SFC
     [Arguments]    ${test_name}=${TEST_NAME}
diff --git a/csit/libraries/netvirt/excepts.py b/csit/libraries/netvirt/excepts.py
new file mode 100644 (file)
index 0000000..d8a097b
--- /dev/null
@@ -0,0 +1,237 @@
+import collections
+import logging
+import re
+
+# Make sure to have unique matches in different lines
+# Order the list in alphabetical order based on the "issue" key
+_whitelist = [
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-972",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "Node was created by other transaction",
+         "Optimistic lock failed for path /(urn:opendaylight:inventory?revision=2013-08-19)nodes/node/node" +
+         "[{(urn:opendaylight:inventory?revision=2013-08-19)id=openflow",
+         "table/table[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=21}]/flow/flow" +
+         "[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=L3."
+         "Conflicting modification for path /(urn:opendaylight:inventory?revision=2013-08-19)nodes/node/node" +
+         "[{(urn:opendaylight:inventory?revision=2013-08-19)id=",
+         "table/table[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=21}]/flow/flow" +
+         "[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=L3.", ".21.", ".42."
+     ]},
+    # oxygen
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-972",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "Node was created by other transaction",
+         "OptimisticLockFailedException: Optimistic lock failed."
+         "Conflicting modification for path /(urn:opendaylight:inventory?revision=2013-08-19)nodes/node/node" +
+         "[{(urn:opendaylight:inventory?revision=2013-08-19)id=",
+         "table/table[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=21}]/flow/flow" +
+         "[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=L3.", ".21.", ".42."
+     ]},
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-1135",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "Node was created by other transaction",
+         "Optimistic lock failed for path /(urn:opendaylight:inventory?revision=2013-08-19)nodes/node/node" +
+         "[{(urn:opendaylight:inventory?revision=2013-08-19)id=openflow:",
+         "Conflicting modification for path /(urn:opendaylight:inventory?revision=2013-08-19)nodes/node/node" +
+         "[{(urn:opendaylight:inventory?revision=2013-08-19)id=openflow:",
+         "table/table[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=47}]/flow/flow" +
+         "[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=SNAT.", ".47."
+     ]},
+    # oxygen
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-1135",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "OptimisticLockFailedException: Optimistic lock failed."
+         "Conflicting modification for path /(urn:opendaylight:inventory?revision=2013-08-19)nodes/node/node" +
+         "[{(urn:opendaylight:inventory?revision=2013-08-19)id=openflow:",
+         "table/table[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=47}]/flow/flow" +
+         "[{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=SNAT.", ".47."
+     ]},
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-1136",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "Node was deleted by other transaction",
+         "Optimistic lock failed for path /(urn:opendaylight:netvirt:elan?revision=2015-06-02)elan-" +
+         "forwarding-tables/mac-table/mac-table[{(urn:opendaylight:netvirt:elan?revision=2015-06-02)" +
+         "elan-instance-name=",
+         "Conflicting modification for path /(urn:opendaylight:netvirt:elan?revision=2015-06-02)elan-" +
+         "forwarding-tables/mac-table/mac-table[{(urn:opendaylight:netvirt:elan?revision=2015-06-02)" +
+         "elan-instance-name="
+     ]},
+    # oxygen version of NETVIRT-1136
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-1136",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "Node was deleted by other transaction",
+         "OptimisticLockFailedException: Optimistic lock failed."
+         "Conflicting modification for path /(urn:opendaylight:netvirt:elan?revision=2015-06-02)elan-" +
+         "forwarding-tables/mac-table/mac-table[{(urn:opendaylight:netvirt:elan?revision=2015-06-02)" +
+         "elan-instance-name="
+     ]},
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-1260",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "Node was deleted by other transaction",
+         "Optimistic lock failed for path /(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)" +
+         "interfaces/interface/interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name=",
+         "Conflicting modification for path /(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)" +
+         "interfaces/interface/interface[{(urn:ietf:params:xml:ns:yang:ietf-interfaces?revision=2014-05-08)name="
+     ]},
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-1270",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "ConflictingModificationAppliedException: Node children was modified by other transaction",
+         "OptimisticLockFailedException",
+         "Conflicting modification for path /(urn:opendaylight:netvirt:l3vpn?revision=2013-09-11)" +
+         "vpn-instance-op-data/vpn-instance-op-data-entry/vpn-instance-op-data-entry" +
+         "[{(urn:opendaylight:netvirt:l3vpn?revision=2013-09-11)vrf-id="
+     ]},
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-1270",
+     "id": "ExecutionException",
+     "context": [
+         "OptimisticLockFailedException: Optimistic lock failed.",
+         "ConflictingModificationAppliedException: Node children was modified by other transaction",
+         "removeOrUpdateVpnToDpnList: Error removing from dpnToVpnList for vpn "
+     ]},
+    {"issue": "https://jira.opendaylight.org/browse/NETVIRT-1281",
+     "id": "OptimisticLockFailedException",
+     "context": [
+         "OptimisticLockFailedException: Optimistic lock failed.",
+         "ConflictingModificationAppliedException: Node children was modified by other transaction",
+         "Direct Exception (not failed Future) when executing job, won't even retry: JobEntry{key='VPNINTERFACE-"
+     ]},
+    {"issue": "https://jira.opendaylight.org/browse/NEUTRON-157",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "Node was deleted by other transaction",
+         "Optimistic lock failed for path /(urn:opendaylight:neutron?revision=2015-07-12)" +
+         "neutron/networks/network/network[{(urn:opendaylight:neutron?revision=2015-07-12)uuid=",
+         "Got OptimisticLockFailedException"
+     ]},
+    # oxygen
+    {"issue": "https://jira.opendaylight.org/browse/NEUTRON-157",
+     "id": "ConflictingModificationAppliedException",
+     "context": [
+         "Node was deleted by other transaction",
+         "OptimisticLockFailedException: Optimistic lock failed.",
+         "Got OptimisticLockFailedException",
+         "Conflicting modification for path /(urn:opendaylight:neutron?revision=2015-07-12)" +
+         "neutron/networks/network/network[{(urn:opendaylight:neutron?revision=2015-07-12)uuid=",
+     ]},
+    {"issue": "https://jira.opendaylight.org/browse/OPNFLWPLUG-917",
+     "id": "IllegalStateException",
+     "context": [
+         "java.lang.IllegalStateException: Deserializer for key: msgVersion: 4 objectClass: " +
+         "org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.oxm.rev150225.match.entries.grouping.MatchEntry " +
+         "msgType: 1 oxm_field: 33 experimenterID: null was not found " +
+         "- please verify that all needed deserializers ale loaded correctly"
+     ]}
+]
+
+_re_ts = re.compile(r"^[0-9]{4}(-[0-9]{2}){2}T([0-9]{2}:){2}[0-9]{2},[0-9]{3}")
+_re_ts_we = re.compile(r"^[0-9]{4}(-[0-9]{2}){2}T([0-9]{2}:){2}[0-9]{2},[0-9]{3}( \| ERROR \| | \| WARN  \| )")
+_re_ex = re.compile(r"(?i)exception")
+_ex_map = collections.OrderedDict()
+_ts_list = []
+_fail = []
+
+
+def get_exceptions(lines):
+    """
+    Create a map of exceptions that also has a list of warnings and errors preceeding
+    the exception to use as context.
+
+    The lines are parsed to create a list where all lines related to a timestamp
+    are aggregated. Timestamped lines with exception (case insensitive) are copied
+    to the exception map keyed to the index of the timestamp line. Each exception value
+    also has a 3 element list containing the last three WARN and ERROR lines.
+
+    :param list lines:
+    :return OrderedDict _ex_map: map of exceptions
+    """
+    global _ex_map
+    _ex_map = collections.OrderedDict()
+    global _ts_list
+    _ts_list = []
+    cur_list = []
+    warnerr_deq = collections.deque(maxlen=5)
+
+    for line in lines:
+        ts = _re_ts.search(line)
+
+        # Check if this is the start or continuation of a timestamp line
+        if ts:
+            cur_list = [line]
+            _ts_list.append(cur_list)
+            ts_we = _re_ts_we.search(line)
+            # Track WARN and ERROR lines
+            if ts_we:
+                warn_err_index = len(_ts_list) - 1
+                warnerr_deq.append(warn_err_index)
+        # Append to current timestamp line since this is not a timestamp line
+        else:
+            cur_list.append(line)
+
+        # Add the timestamp line to the exception map if it has an exception
+        ex = _re_ex.search(line)
+        if ex:
+            index = len(_ts_list) - 1
+            if index not in _ex_map:
+                _ex_map[index] = {"warnerr_list": list(warnerr_deq), 'lines': cur_list}
+                warnerr_deq.clear()  # reset the deque to only track new ERROR and WARN lines
+
+    return _ex_map
+
+
+def check_exceptions():
+    """
+    Return a list of exceptions that were not in the whitelist.
+
+    Each exception found is compared against all the patterns
+    in the whitelist.
+
+    :return list _fail: list of exceptions not in the whitelist
+    """
+    global _fail
+    _fail = []
+    _match = []
+    for ex_idx, ex in _ex_map.items():
+        ex_str = "__".join(ex.get("lines"))
+        for whitelist in _whitelist:
+            # skip the current whitelist exception if not in the current exception
+            if whitelist.get("id") not in ex_str:
+                continue
+            whitelist_contexts = whitelist.get("context")
+            num_context_matches = 0
+            for whitelist_context in whitelist_contexts:
+                for exwe_index in reversed(ex.get("warnerr_list")):
+                    exwe_str = "__".join(_ts_list[exwe_index])
+                    if whitelist_context in exwe_str:
+                        num_context_matches += 1
+                        break
+            # Mark this exception as a known issue if all the context's matched
+            if num_context_matches == len(whitelist_contexts):
+                ex["issue"] = whitelist.get("issue")
+                _match.append(ex)
+                logging.info("known exception was seen: {}".format(ex["issue"]))
+                break
+        # A new exception when it isn't marked with a known issue.
+        if "issue" not in ex:
+            _fail.append(ex)
+    return _fail, _match
+
+
+def verify_exceptions(lines):
+    """
+    Return a list of exceptions not in the whitelist for the given lines.
+
+    :param list lines: list of lines from a log
+    :return list, list: one list of exceptions not in the whitelist, and a second with matching issues
+    """
+    if not lines:
+        return
+    get_exceptions(lines)
+    return check_exceptions()