Fix LogAnalyzer to force load regular expressions from common files

[ppikh]

Signed-off-by: Petro Pikh [email protected]

Description of PR

Fix LogAnalyzer to force load regular expressions from common files

Looks like commit #3235 caused issue that LA has empty list of match errors expressions.

Summary: Fix LogAnalyzer to force load regular expressions from common files
Fixes # (issue)

Type of change

• Bug fix
• Testbed and Framework(new/improvement)
• Test case(new/improvement)

Back port request

• 201911

Approach

What is the motivation for this PR?

LogAnalyzer did not work, this PR is fix for LA

How did you do it?

See code

How did you verify/test it?

Executed tests which using LA, checked that LA failed in case when we have errors in logs

Any platform specific information?

Supported testbed topology if it's a new test case?

Documentation

[wangxin]

It is better to run "load_common_config" in lines 55-56 while creating analyzer?

And line 33-35 should be removed.

[ppikh]

Hi, @wangxin If add "load_common_config" into line 55-56 - self.match_regex will be empty after line 57.
"load_common_config" - should be called after "parallel_run"

[wangxin]

@ppikh I tested below patch, it works from my side. Can you try that?

diff --git a/tests/common/plugins/loganalyzer/__init__.py b/tests/common/plugins/loganalyzer/__init__.py
index 32015d16f7..9f80fb3901 100644
--- a/tests/common/plugins/loganalyzer/__init__.py
+++ b/tests/common/plugins/loganalyzer/__init__.py
@@ -30,18 +30,13 @@ def analyzer_add_marker(analyzers, node=None, results=None):
     loganalyzer = analyzers[node.hostname]
     logging.info("Add start marker into DUT syslog for host {}".format(node.hostname))
     marker = loganalyzer.init()
-    logging.info("Load config and analyze log for host {}".format(node.hostname))
-    # Read existed common regular expressions located with legacy loganalyzer module
-    loganalyzer.load_common_config()
     results[node.hostname] = marker
 
-
 @reset_ansible_local_tmp
 def analyze_logs(analyzers, markers, node=None, results=None):
     dut_analyzer = analyzers[node.hostname]
     dut_analyzer.analyze(markers[node.hostname])
 
-
 @pytest.fixture(autouse=True)
 def loganalyzer(duthosts, request):
     if request.config.getoption("--disable_loganalyzer") or "disable_loganalyzer" in request.keywords:
@@ -53,7 +48,10 @@ def loganalyzer(duthosts, request):
     analyzers = {}
     parallel_run(analyzer_logrotate, [], {}, duthosts, timeout=120)
     for duthost in duthosts:
-        analyzers[duthost.hostname] = LogAnalyzer(ansible_host=duthost, marker_prefix=request.node.name)
+        analyzer = LogAnalyzer(ansible_host=duthost, marker_prefix=request.node.name)
+        analyzer.load_common_config()
+        analyzers[duthost.hostname] = analyzer
+
     markers = parallel_run(analyzer_add_marker, [analyzers], {}, duthosts, timeout=120)
 
     yield analyzers
@@ -63,4 +61,3 @@ def loganalyzer(duthosts, request):
         return
     logging.info("Starting to analyse on all DUTs")
     parallel_run(analyze_logs, [analyzers, markers], {}, duthosts, timeout=120)

[ppikh]

Hi @wangxin
I did fixes, it works.
Thanks

[wangxin]

/azp run

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[liat-grozovik]

/azp run Azure.sonic-mgmt

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[roy-sror]

Force loading regular expression from the common files

[wangxin]

/azp run

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[ppikh]

Hi @wangxin @roysr-nv @liat-grozovik
Checkers after this change will never pass due to errors in logs:

LogAnalyzerError: {'match_messages': {'/tmp/syslog.vlab-01.2022-03-21-05:27:42': ["Mar 21 05:27:36.714638 vlab-01 ERR teamd#tlm_teamd: :- get_dump: Can't get dump for LAG 'PortChannel999'. Skipping\n"]}, 'total': {'expected_match': 0, 'expected_missing_match': 0, 'match': 1}, 'match_files': {'/tmp/syslog.vlab-01.2022-03-21-05:27:42': {'expected_match': 0, 'match': 1}}, 'expect_messages': {'/tmp/syslog.vlab-01.2022-03-21-05:27:42': []}, 'unused_expected_regexp': []}

LogAnalyzerError: {'match_messages': {'/tmp/syslog.vlab-01.2022-03-21-05:04:08': ['Mar 21 05:03:41.679273 vlab-01 ERR sonic_yang: Data Loading Failed:Leafref "../../LOOPBACK_INTERFACE_LIST/name" of value "Loopback0" points to a non-existing leaf.\n', 'Mar 21 05:03:41.742485 vlab-01 ERR sonic_yang: Data Loading Failed:Leafref "../../LOOPBACK_INTERFACE_LIST/name" of value "Loopback0" points to a non-existing leaf.\n']}, 'total': {'expected_match': 0, 'expected_missing_match': 0, 'match': 2}, 'match_files': {'/tmp/syslog.vlab-01.2022-03-21-05:04:08': {'expected_match': 0, 'match': 2}}, 'expect_messages': {'/tmp/syslog.vlab-01.2022-03-21-05:04:08': []}, 'unused_expected_regexp': []}

LogAnalyzerError: {'match_messages': {'/tmp/syslog.vlab-01.2022-03-21-04:42:01': ['Mar 21 04:40:11.071343 vlab-01 ERR syncd#syncd: :- translateVidToRid: unable to get RID for VID oid:0x5c0000000006c9\n']}, 'total': {'expected_match': 0, 'expected_missing_match': 0, 'match': 1}, 'match_files': {'/tmp/syslog.vlab-01.2022-03-21-04:42:01': {'expected_match': 0, 'match': 1}}, 'expect_messages': {'/tmp/syslog.vlab-01.2022-03-21-04:42:01': []}, 'unused_expected_regexp': []}

Can someone merge this commit?

[wangxin]

Because loganalyzer was broken for a long time, many error logs sneaked in. We should have this PR merged anyway because PR test failures were caused by error logs sneaked in recently. Extra efforts are needed to address those error logs. We should not blame loganalyzer for the surfaced new test errors after this PR is merged.

[liuh-80]

@ppikh, seems this PR break some UT, here is one of my test PR: https://github.com/Azure/sonic-buildimage/pull/10329/checks?check_run_id=5656011837

Issue seems related with change in tests/common/plugins/loganalyzer/init.py

[ppikh]

Hi @liuh-80
It did not break.
Your tests failed due to errors in logs:

LogAnalyzerError: {'match_messages': {'/tmp/syslog.vlab-01.2022-03-23-06:31:04': ["Mar 23 06:30:48.077089 vlab-01 ERR teamd#tlm_teamd: :- get_dump: Can't get dump for LAG 'PortChannel999'. Skipping\n"]}, 'total': {'expected_match': 0, 'expected_missing_match': 0, 'match': 1}, 'match_files': {'/tmp/syslog.vlab-01.2022-03-23-06:31:04': {'expected_match': 0, 'match': 1}}, 'expect_messages': {'/tmp/syslog.vlab-01.2022-03-23-06:31:04': []}, 'unused_expected_regexp': []}

[wen587]

Hi I met similiar issue. https://dev.azure.com/mssonic/build/_build/results?buildId=83555&view=logs&j=7ecf62ce-878c-5860-615d-9d0f5ab291f1&t=50051680-b4c8-5a0e-b7f9-3520ce72ee4a&l=1860

ERR sonic_yang: Data Loading Failed:All Keys are not parsed in TACPLUS#012dict_keys(['global'])\n"] I met this failure before during my local test, it is because configDB contains empty table which result the test does not pass yang validation.
However, previous generic_config_updater/test_aaa.py tests will also validate yang each time. So previous passing test, such as test_aaa_tc4_remove PASSED, means there is no empty table during the testing environment, otherwise it will fail anyway.
So it confused me that why the testing environment was changed unexpected during the test somehow.

[liuh-80]

@ppikh, seems this PR break some UT, here is one of my test PR: https://github.com/Azure/sonic-buildimage/pull/10329/checks?check_run_id=5656011837

Issue seems related with change in tests/common/plugins/loganalyzer/init.py

Thanks, I check the UT source code and found the UT failed by design, https://github.com/Azure/sonic-mgmt/blob/2333bbcc25ef419580e744fe2c5d79463f5c9afc/tests/pc/test_po_update.py

Seems the UT not failed before, because the log analyzer not catch the message before this change.

I'm not author of this UT and there seems other UT also failed. I will wait for the UT fixed.

[wen587]

Hi I met similiar issue. https://dev.azure.com/mssonic/build/_build/results?buildId=83555&view=logs&j=7ecf62ce-878c-5860-615d-9d0f5ab291f1&t=50051680-b4c8-5a0e-b7f9-3520ce72ee4a&l=1860

ERR sonic_yang: Data Loading Failed:All Keys are not parsed in TACPLUS#012dict_keys(['global'])\n"] I met this failure before during my local test, it is because configDB contains empty table which result the test does not pass yang validation. However, previous generic_config_updater/test_aaa.py tests will also validate yang each time. So previous passing test, such as test_aaa_tc4_remove PASSED, means there is no empty table during the testing environment, otherwise it will fail anyway. So it confused me that why the testing environment was changed unexpected during the test somehow.

I did some research and found that the GCU will first sort the json_change to make sure it follows yang model rules. When some sorting doesn't comfort to the yang model rules, it will stop current sorting and just try other sorting method.
The log analyzer caught the ERR and fail immediately.
To fix GCU test, I can add disable log analyzer for GCU tests.

[liat-grozovik]

Ignoring the log is not the answer. Need to fix the original issue now that these are raised From: jingwenxie ***@***.***> Sent: Thursday, March 24, 2022 5:58 AM To: Azure/sonic-mgmt ***@***.***> Cc: Liat Grozovik ***@***.***>; Mention ***@***.***> Subject: Re: [Azure/sonic-mgmt] Fix LogAnalyzer to force load regular expressions from common files (PR #5193) Hi I met similiar issue. https://dev.azure.com/mssonic/build/_build/results?buildId=83555&view=logs&j=7ecf62ce-878c-5860-615d-9d0f5ab291f1&t=50051680-b4c8-5a0e-b7f9-3520ce72ee4a&l=1860<https://nam11.safelinks.protection.outlook.com/?url=https%3A%2F%2Fdev.azure.com%2Fmssonic%2Fbuild%2F_build%2Fresults%3FbuildId%3D83555%26view%3Dlogs%26j%3D7ecf62ce-878c-5860-615d-9d0f5ab291f1%26t%3D50051680-b4c8-5a0e-b7f9-3520ce72ee4a%26l%3D1860&data=04%7C01%7Cliatg%40nvidia.com%7Ccb47b67dd76647c06f9608da0d4a7bed%7C43083d15727340c1b7db39efd9ccc17a%7C0%7C0%7C637836910801383884%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000&sdata=u1sXVm4jfp649DBzce%2F1n4x%2BAypqLfzF2aYapvDTlBk%3D&reserved=0> ERR sonic_yang: Data Loading Failed:All Keys are not parsed in TACPLUS#012dict_keys(['global'])\n"] I met this failure before during my local test, it is because configDB contains empty table which result the test does not pass yang validation. However, previous generic_config_updater/test_aaa.py tests will also validate yang each time. So previous passing test, such as test_aaa_tc4_remove PASSED, means there is no empty table during the testing environment, otherwise it will fail anyway. So it confused me that why the testing environment was changed unexpected during the test somehow. I did some research and found that the GCU will first sort the json_change to make sure it follows yang model rules. When some sorting doesn't comfort to the yang model rules, it will stop current sorting and just try other sorting method. The log analyzer caught the ERR and fail immediately. To fix GCU test, I can add disable log analyzer for GCU tests. - Reply to this email directly, view it on GitHub<https://nam11.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2FAzure%2Fsonic-mgmt%2Fpull%2F5193%23issuecomment-1077042631&data=04%7C01%7Cliatg%40nvidia.com%7Ccb47b67dd76647c06f9608da0d4a7bed%7C43083d15727340c1b7db39efd9ccc17a%7C0%7C0%7C637836910801383884%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000&sdata=JmIrQPbsiwxkmiko6himYt4DV3rrJDhpwWQEtjRW9oE%3D&reserved=0>, or unsubscribe<https://nam11.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAKTABAYYRH57YOP24ZLIKPTVBPR4LANCNFSM5PAUWR7Q&data=04%7C01%7Cliatg%40nvidia.com%7Ccb47b67dd76647c06f9608da0d4a7bed%7C43083d15727340c1b7db39efd9ccc17a%7C0%7C0%7C637836910801383884%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000&sdata=bBc0BV1D99YKm1%2F9LsScqAwHzVx3EnCI1ngGYRKOk2U%3D&reserved=0>. You are receiving this because you were mentioned.Message ID: ***@***.******@***.***>>

[wen587]

Hi @liat-grozovik , for GCU test it is by design. As it will discard incorrect ordering and finally provide a correct ordering for JsonPatch. It is the previous incorrect ordering fail the log analyzer check. However, it doesn't fail because it will find a correct ordering and apply it.
I will discuss with GCU team to see if there is better way to handle it.