From: Sam Hague Date: Mon, 21 May 2018 21:59:27 +0000 (-0400) Subject: exception checker with context X-Git-Tag: pre-potassium~786 X-Git-Url: https://git.opendaylight.org/gerrit/gitweb?p=integration%2Ftest.git;a=commitdiff_plain;h=a61e4492f0832dc60deede123dbe5e6cc8ee1c35 exception checker with context Change-Id: If1721f474abe532f947ef31aed14577aa916e7e0 Signed-off-by: Sam Hague --- diff --git a/csit/libraries/KarafKeywords.robot b/csit/libraries/KarafKeywords.robot index d562a0c5c9..cece9c4490 100644 --- a/csit/libraries/KarafKeywords.robot +++ b/csit/libraries/KarafKeywords.robot @@ -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 diff --git a/csit/libraries/OpenStackOperations.robot b/csit/libraries/OpenStackOperations.robot index 974440e551..0e7bd6c675 100644 --- a/csit/libraries/OpenStackOperations.robot +++ b/csit/libraries/OpenStackOperations.robot @@ -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 index 0000000000..d8a097b87b --- /dev/null +++ b/csit/libraries/netvirt/excepts.py @@ -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()