Fix 'test_feeds/test_missing_fields' tests in 4.2

[damarisg]

Issue information

Related issue
Closes #1531

When it comes to starting with the test fix, there is some information that can help you:

Module: Vulnerability Detector
Support Team:  "binary beasts"
Target: Manager   
OS: Linux

I add some information obtained while researched the logs that failed.

Case 1:

Type	Description
Test Path	test_feeds/msu/test_missing_fields_msu_feed
Consistent	yes
Test Execution	3/3 executions failed
Case	test_missing_fields_msu_feed
Cases Fails	7
Summary	On check_feed_imported_successfully method is called. The problem seems to be a Parser error when reading the file.
Error message	"Could not find the message: 'Microsoft Security Update' feed finished successfully"

Case 2:

Type	Description
Test Path	test_feeds/msu/test_missing_fields_msu_feed
Consistent	no
Test Execution	1/3 executions failed
Case	test_no_feed_changes
Cases Fails	1
Summary	When check_feed_imported_successfully is called. The problem seems to be a Parser error and it will be because there is a problem when imported a file.
Error message	"Could not find the message: 'Microsoft Security Update' feed finished successfully"

Case 3:

Type	Description
Test Path	test_feeds/redhat/test_missing_fields_redhat_feed
Consistent	no
Test Execution	2/3 executions failed
Cases Fails	27
Summary	It should to do research with more details because in the logs doesn't show any details.

In order to finish this issue the following tasks should be fulfilled:

• Research of fails.
• Apply Fix
• Full Green/ Full Yellow in test_feeds/redhat/test_missing_fields_redhat_feed for 3 times.
• Full Green/ Full Yellow in test_feeds/msu/test_missing_fields_msu_feed for 3 times.
• Documentation of any important change done for these tests or the used tools.

[mdengra]

2021-07-13

After multiple tests, it appears that these errors originate in the monitoring.py module of the QA framework, specifically in the QueueMonitor class, which is the one that finally checks if the related logs have been written.

These logs are written to the log file correctly, but the QueueMonitor class is not able to detect them when a large number of messages are written to the log file (log flooding). To verify this I have disabled the sca module, which generates a large number of logs and the tests involved have been running correctly.

I continue to perform checks to locate the specific source of the problem.

Test results after disabling the sca module:

Test Executions	Date	By	Status
test_missing_fields_msu_feed_local_r1.log	2021-07-13	Miguel	🟢
test_missing_fields_msu_feed_local_r2.log	2021-07-13	Miguel	🟢
test_missing_fields_msu_feed_local_r3.log	2021-07-13	Miguel	🟢
test_missing_fields_redhat_feed_local_r1.log	2021-07-13	Miguel	🟡
test_missing_fields_redhat_feed_local_r2.log	2021-07-13	Miguel	🟢
test_missing_fields_redhat_feed_local_r3.log	2021-07-13	Miguel	🟢

[damarisg]

This issue requires more research because when we execute it, we keep getting fails. We can see that this test is inconsistency.

Test Executions	Date	By	Status
Results1_MissingMSU.log	2021-07-13	Seyla	🟢
Results2_MissingMSU.log	2021-07-13	Seyla	🟢
Results3_MissingMSU.log	2021-07-13	Seyla	🟢
Results1_MissingRedhat.log	2021-07-13	Seyla	🔴
Results2_MissingRedhat.log	2021-07-13	Seyla	🔴
Results3.1_MissingRedhat.log	2021-07-13	Seyla	🔴

[pereyra-m]

Results for test_feeds/msu/test_missing_fields_msu_feed.py

Test Executions	Date	By	Status
centos_test_missing_fields_msu_feed_1.log	2021-07-13	Matias	🔴
centos_test_missing_fields_msu_feed_2.log	2021-07-13	Matias	🔴
centos_test_missing_fields_msu_feed_3.log	2021-07-13	Matias	🔴

[mdengra]

2021-07-14

I ran the tests again by recreating a new Vagrant box with a clean environment.

Test results with the default modules enabled in the ossec.conf:

Test Executions	Date	By	Status
test_missing_fields_msu_feed_local_r1.log	2021-07-14	Miguel	🔴
test_missing_fields_msu_feed_local_r2.log	2021-07-14	Miguel	🔴
test_missing_fields_msu_feed_local_r3.log	2021-07-14	Miguel	🔴
test_missing_fields_redhat_feed_local_r1.log	2021-07-14	Miguel	🔴
test_missing_fields_redhat_feed_local_r2.log	2021-07-14	Miguel	🟢
test_missing_fields_redhat_feed_local_r3.log	2021-07-14	Miguel	🟢

Test results after disabling the sca module:

Test Executions	Date	By	Status
test_missing_fields_msu_feed_local_no_sca_r1.log	2021-07-14	Miguel	🟡
test_missing_fields_msu_feed_local_no_sca_r2.log	2021-07-14	Miguel	🟢
test_missing_fields_msu_feed_local_no_sca_r3.log	2021-07-14	Miguel	🟢
test_missing_fields_redhat_feed_local_no_sca_r1.log	2021-07-14	Miguel	🟢
test_missing_fields_redhat_feed_local_no_sca_r2.log	2021-07-14	Miguel	🟢
test_missing_fields_redhat_feed_local_no_sca_r3.log	2021-07-14	Miguel	🟢

Error details

Here you can see the instant when the test fails (test run using pytest -sv options):

test_vulnerability_detector/test_feeds/msu/test_missing_fields_msu_feed.py::test_invalid_msu_feed[MSU_configuration-missing: restart_required] 2021/07/14 08:22:34 wazuh-modulesd[60743] debug_op.c:70 at _log(): DEBUG: Logging module auto-initialized
2021/07/14 08:22:34 wazuh-modulesd[60743] main.c:76 at main(): DEBUG: Wazuh home directory: /var/ossec
2021/07/14 08:22:34 wazuh-modulesd[60743] wmodules-osquery-monitor.c:78 at wm_osquery_monitor_read(): DEBUG: Logpath read: /var/log/osquery/osqueryd.results.log
2021/07/14 08:22:34 wazuh-modulesd[60743] wmodules-osquery-monitor.c:84 at wm_osquery_monitor_read(): DEBUG: configPath read: /etc/osquery/osquery.conf
2021/07/14 08:22:34 wazuh-modulesd[60743] wmodules-vuln-detector.c:609 at wm_vuldet_read_provider(): DEBUG: Added msu feed. Interval: 3600s | Multi path: '/home/vagrant/wazuh-qa/tests/integration/test_vulnerability_detector/test_feeds/msu/../../data/feeds/custom_msu.json$' | Multi url: 'none' | Update since: 0 | Timeout: 300s
2021-07-14 08:22:54,456 - wazuh_testing - ERROR - Could not find the message: 'Microsoft Security Update' feed finished successfully
2021-07-14 08:22:54,456 - wazuh_testing - ERROR - Results accumulated: 0
2021-07-14 08:22:54,456 - wazuh_testing - ERROR - Results expected: 1
FAILED2021-07-14T08:22:56.1626250976

The use case starts running at 08:22:34:
2021/07/14 08:22:34 wazuh-modulesd[60743] main.c:76 at main(): DEBUG: Wazuh home directory: /var/ossec

And ends at 08:22:54 due to timeout (20s):
2021-07-14 08:22:54,456 - wazuh_testing - ERROR - Could not find the message: 'Microsoft Security Update' feed finished successfully

However, by analyzing the ossec.log file, you can see that the message mentioned by the error has been written:
2021/07/14 08:22:34 wazuh-modulesd:vulnerability-detector[60743] wm_vuln_detector.c:4077 at wm_vuldet_check_feed(): INFO: (5430): The update of the 'Microsoft Security Update' feed finished successfully.

This behavior does not occur if modules that write a large number of messages to the log file, such as the sca module, are disabled.

[pereyra-m]

Results for test_feeds/msu/test_missing_fields_msu_feed.py
Now, the following modules were turned off: sca, syscollector and rootcheck

Test Executions	Date	By	Status
test_missing_fields_msu_feed_modules_off_1.log	2021-07-14	Matias	🟢
test_missing_fields_msu_feed_modules_off_2.log	2021-07-14	Matias	🟢
test_missing_fields_msu_feed_modules_off_3.log	2021-07-14	Matias	🟢

Results for test_feeds/redhat/test_missing_fields_redhat_feed.py
Now, the following modules were turned off: sca, syscollector and rootcheck.
These tests have XFAIL

Test Executions	Date	By	Status
test_missing_fields_redhat_feed_modules_off_1.log	2021-07-14	Matias	🟢
test_missing_fields_redhat_feed_modules_off_2.log	2021-07-14	Matias	🟢
test_missing_fields_redhat_feed_modules_off_3.log	2021-07-14	Matias	🟢

[damarisg]

Results when disabling modules: sca, syscollector and rootcheck.

Test Executions	Date	By	Status
MissingFieldMsu1.log	2021-07-14	Seyla	🟡
MissingField2.log	2021-07-14	Seyla	🟢
MissingField3.log	2021-07-14	Seyla	🟢
MissingFieldRedHat2.log	2021-07-14	Seyla	🟡
MissingFieldRedHat3.log	2021-07-14	Seyla	🟢
MissingFieldRedHat1.log	2021-07-14	Seyla	🟢

Reference	Status
🟢	Pass without warnings
🟡	Pass with Warnings

[mdengra]

2021-07-22

Used Wazuh-QA branch: 1531-full-yellow-vuln-det
Test results with the default settings in the ossec.conf:

Case 1, 2

Test Executions	Date	By	Status
test_missing_fields_msu_feed_local_r1.log	2021-07-22	Miguel	🟡
test_missing_fields_msu_feed_local_r2.log	2021-07-22	Miguel	🟡
test_missing_fields_msu_feed_local_r3.log	2021-07-22	Miguel	🟡

Case 3

Test Executions	Date	By	Status
test_missing_fields_redhat_feed_local_r1.log	2021-07-22	Miguel	🟡
test_missing_fields_redhat_feed_local_r2.log	2021-07-22	Miguel	🔴
test_missing_fields_redhat_feed_local_r3.log	2021-07-22	Miguel	🔴

Note that the same use case (first case) fails in the two first runs:

FAILED test_vulnerability_detector/test_feeds/redhat/test_missing_fields_redhat_feed.py::test_invalid_redhat_feed[REDHAT_configuration-missing: generator]

[mdengra]

Same scenario as in the issue: #1548

The problem is related to the issue: #1602, in which FileMonitor does not detect a message written to the log file under certain scenarios.

In the test_invalid_syntax_redhat_feed.py test, even disabling all possible modules before launching the test does not prevent it from falling in the first use case.

The cause of the failure is the large number of messages generated by enabling the internal option wazuh_modules.debug=2, which is required by multiple vulnerability detector tests. When this option is enabled and the manager is restarted, the log file takes up 1MB, this added to the messages generated by the test itself makes FileMonitor unable to process them, causing the error.

[damarisg]

Closed by #1605 and #1633.

Test Results after to merge.

Test Executions	Test	Date	By	Status
YellowMissingFieldRedhat.log	test_feeds/redhat/test_missing_fields_redhat_feed	2021-07-25	Seyla	🟡
YellowMissingFieldRedhat2.log)	test_feeds/redhat/test_missing_fields_redhat_feed	2021-07-25	Seyla	🟡
YellowMissingFieldRedhat3.log	test_feeds/redhat/test_missing_fields_redhat_feed	2021-07-25	Seyla	🟡
YellowMissingFieldMSU.log	test_feeds/msu/test_missing_fields_msu_feed	2021-07-25	Seyla	🟡
YellowMissingFieldMSU2.log	test_feeds/msu/test_missing_fields_msu_feed	2021-07-25	Seyla	🟡
YellowMissingFieldMSU3.log	test_feeds/msu/test_missing_fields_msu_feed	2021-07-25	Seyla	🟡