wazuh / wazuh-qa

Wazuh - Quality Assurance
GNU General Public License v2.0
61 stars 30 forks source link

LogCollector Test Fails for Windows Agents #4840

Open rafabailon opened 4 months ago

rafabailon commented 4 months ago

Description

During the tests of Release 4.8.0 - Alpha 2 - Integration tests I have detected an error in Windows Agent. The specific error is

PermissionError: [Errno 13] Permission denied: 'c:\\test'

The error has been detected in the LogCollector tests.

Pipeline Error
```bash 10:57:53 TASK [Launch windows pytests] ************************************************** 10:57:53 task path: /home/ec2-user/workspace/Test_integration/quality/tests/integration/test_integration.yaml:37 10:57:53 fatal: [ID2_B45823_Test_integration_windows_agent]: FAILED! => { 10:57:53 "ansible_async_watchdog_pid": 1516, 10:57:53 "ansible_job_id": "71624031561.408", 10:57:53 "changed": true, 10:57:53 "cmd": "powershell.exe -", 10:57:53 "delta": "0:19:50.318822", 10:57:53 "end": "2024-01-12 09:55:48.128232", 10:57:53 "failed_when_result": true, 10:57:53 "finished": 1, 10:57:53 "rc": 1, 10:57:53 "results_file": "C:\\Users\\Jenkins\\.ansible_async\\71624031561.408", 10:57:53 "start": "2024-01-12 09:35:57.809409", 10:57:53 "started": 1 10:57:53 } 10:57:53 10:57:53 MSG: 10:57:53 10:57:53 non-zero return code 10:57:54 Using module file /usr/local/lib/python3.7/site-packages/ansible/modules/windows/win_stat.ps1 10:57:54 Pipelining is enabled. 10:57:54 <172.31.13.5> ESTABLISH WINRM CONNECTION FOR USER: Jenkins on PORT 5986 TO 172.31.13.5 10:57:54 EXEC (via pipeline wrapper) 10:57:57 <172.31.13.5> FETCH "C:\tmp\Test_integration_B45823_20240112095642\pytest_plain_report.txt" TO "/home/ec2-user/workspace/Test_integration/windows_agent_tests_Test_integration_B45823_20240112095642.txt" ... 10:58:04 PLAY RECAP ********************************************************************* 10:58:04 ID2_B45823_Test_integration_windows_agent : ok=3 changed=3 unreachable=0 failed=1 skipped=8 rescued=0 ignored=0 10:58:04 10:58:04 Playbook run took 0 days, 0 hours, 22 minutes, 12 seconds 10:58:05 FATAL: command execution failed 10:58:05 hudson.AbortException: Ansible playbook execution failed 10:58:05 at org.jenkinsci.plugins.ansible.AnsiblePlaybookBuilder.perform(AnsiblePlaybookBuilder.java:262) 10:58:05 at org.jenkinsci.plugins.ansible.workflow.AnsiblePlaybookStep$AnsiblePlaybookExecution.run(AnsiblePlaybookStep.java:430) 10:58:05 at org.jenkinsci.plugins.ansible.workflow.AnsiblePlaybookStep$AnsiblePlaybookExecution.run(AnsiblePlaybookStep.java:351) 10:58:05 at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1$1.call(AbstractSynchronousNonBlockingStepExecution.java:47) 10:58:05 at hudson.security.ACL.impersonate2(ACL.java:449) 10:58:05 at hudson.security.ACL.impersonate(ACL.java:461) 10:58:05 at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1.run(AbstractSynchronousNonBlockingStepExecution.java:44) 10:58:05 at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) 10:58:05 at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) 10:58:05 at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 10:58:05 at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 10:58:05 at java.base/java.lang.Thread.run(Thread.java:829) 10:58:05 [Pipeline] echo 10:58:05 hudson.AbortException: Ansible playbook execution failed 10:58:05 10:58:05 [Pipeline] } 10:58:05 [Pipeline] // stage 10:58:05 [Pipeline] } 10:58:05 Failed in branch windows_agent ```
Error in the Logs
```bash =================================== ERRORS ==================================== _ ERROR at setup of test_ignore_multiple_regex[Log match - Two ignore tags - Match second tag-] _ new_file_path = 'c:\\test' @pytest.fixture(scope='function') def create_file(new_file_path): """Create an empty file. Args: new_file_path (str): File path to create. """ > write_file(new_file_path) conftest.py:1340: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ file_path = 'c:\\test', data = '' def write_file(file_path, data=''): > with open(file_path, 'w') as f: E PermissionError: [Errno 13] Permission denied: 'c:\\test' C:\Python311\Lib\site-packages\wazuh_testing\tools\file.py:177: PermissionError _ ERROR at setup of test_restrict_multiple_regex[No match - Two Restrict tags-] _ new_file_path = 'c:\\test' @pytest.fixture(scope='function') def create_file(new_file_path): """Create an empty file. Args: new_file_path (str): File path to create. """ > write_file(new_file_path) conftest.py:1340: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ file_path = 'c:\\test', data = '' def write_file(file_path, data=''): > with open(file_path, 'w') as f: E PermissionError: [Errno 13] Permission denied: 'c:\\test' C:\Python311\Lib\site-packages\wazuh_testing\tools\file.py:177: PermissionError - generated html file: file://C:\tmp\Test_integration_B45823_20240112095642\report.html - =========================== short test summary info =========================== ERROR test_logcollector/test_log_filter_options/test_ignore_regex.py::test_ignore_multiple_regex[Log match - Two ignore tags - Match second tag-] ERROR test_logcollector/test_log_filter_options/test_restrict_regex.py::test_restrict_multiple_regex[No match - Two Restrict tags-] = 135 passed, 356 skipped, 176 deselected, 35 xfailed, 5 xpassed, 2 errors in 1183.93s (0:19:43) = ```

Evidences

nbertoldo commented 4 months ago

Update

I have run locally on a Windows 11 agent the logcollector integration tests (test_logcollector/test_log_filter_options) without errors.

PS C:\Users\vagrant\wazuh-qa\tests\integration> python -m pytest -v --html=report.html .\test_logcollector\test_log_filter_options
============================= test session starts =============================
platform win32 -- Python 3.12.1, pytest-7.4.4, pluggy-1.3.0 -- C:\Users\vagrant\AppData\Local\Programs\Python\Python312\python.exe
cachedir: .pytest_cache
metadata: {'Python': '3.12.1', 'Platform': 'Windows-11-10.0.22621-SP0', 'Packages': {'pytest': '7.4.4', 'pluggy': '1.3.0'}, 'Plugins': {'html': '2.0.1', 'metadata': '3.0.0', 'testinfra': '10.0.0'}}
rootdir: C:\Users\vagrant\wazuh-qa\tests\integration
configfile: pytest.ini
plugins: html-2.0.1, metadata-3.0.0, testinfra-10.0.0
collecting ... collected 14 items

test_logcollector/test_log_filter_options/test_ignore_regex.py::test_ignore_multiple_regex[Log match - Two ignore tags - Match first tag-] PASSED [  7%]
test_logcollector/test_log_filter_options/test_ignore_regex.py::test_ignore_multiple_regex[Log match - Two ignore tags - Match both tags-] PASSED [ 14%]
test_logcollector/test_log_filter_options/test_ignore_regex.py::test_ignore_multiple_regex[Log match - Two ignore tags - Match second tag-] PASSED [ 21%]
test_logcollector/test_log_filter_options/test_ignore_regex.py::test_ignore_multiple_regex[No match - Two ignore tags-] PASSED [ 28%]
test_logcollector/test_log_filter_options/test_restrict_ignore_regex.py::test_restrict_ignore_regex_values[Matches with restrict tag - Ignore and restrict tags with PCRE2 regex-] PASSED [ 35%]
test_logcollector/test_log_filter_options/test_restrict_ignore_regex.py::test_restrict_ignore_regex_values[Matches with ignore tag - Ignore and restrict tags with osregex regex-] PASSED [ 42%]
test_logcollector/test_log_filter_options/test_restrict_ignore_regex.py::test_restrict_ignore_regex_values[Log match - Ignore and restrict tags with osmatch regex-] PASSED [ 50%]
test_logcollector/test_log_filter_options/test_restrict_ignore_regex.py::test_restrict_ignore_regex_values[Matches with restrict tag - Ignore and restrict tags with pcre2 and osregex regex-] PASSED [ 57%]
test_logcollector/test_log_filter_options/test_restrict_ignore_regex.py::test_restrict_ignore_regex_values[Matches with ignore tag - Ignore and restrict tags with pcre2 and osmatch regex-] PASSED [ 64%]
test_logcollector/test_log_filter_options/test_restrict_ignore_regex.py::test_restrict_ignore_regex_values[Log match - Ignore and restrict tags with osregex and osmatch regex-] PASSED [ 71%]
test_logcollector/test_log_filter_options/test_restrict_regex.py::test_restrict_multiple_regex[Log match - Two Restrict tags - Match first tag-] PASSED [ 78%]
test_logcollector/test_log_filter_options/test_restrict_regex.py::test_restrict_multiple_regex[Log match - Two Restrict tags - Match both tags-] PASSED [ 85%]
test_logcollector/test_log_filter_options/test_restrict_regex.py::test_restrict_multiple_regex[Log match - Two Restrict tags - Match second tag-] PASSED [ 92%]
test_logcollector/test_log_filter_options/test_restrict_regex.py::test_restrict_multiple_regex[No match - Two Restrict tags-] PASSED [100%]

============================== warnings summary ===============================
test_logcollector/test_log_filter_options/test_ignore_regex.py: 20 warnings
test_logcollector/test_log_filter_options/test_restrict_ignore_regex.py: 30 warnings
test_logcollector/test_log_filter_options/test_restrict_regex.py: 20 warnings
  C:\Users\vagrant\AppData\Local\Programs\Python\Python312\Lib\site-packages\wazuh_testing\tools\configuration.py:334: DeprecationWarning: Testing an element's truth value will raise an exception in future versions.  Use specific 'len(elem)' or 'elem is not None' test instead.
    if not section_conf:

test_logcollector/test_log_filter_options/test_ignore_regex.py: 4 warnings
test_logcollector/test_log_filter_options/test_restrict_ignore_regex.py: 6 warnings
test_logcollector/test_log_filter_options/test_restrict_regex.py: 4 warnings
  C:\Users\vagrant\wazuh-qa\tests\integration\conftest.py:461: DeprecationWarning: datetime.datetime.utcnow() is deprecated and scheduled for removal in a future version. Use timezone-aware objects to represent datetimes in UTC: datetime.datetime.now(datetime.UTC).
    cells.insert(1, html.td(datetime.utcnow(), class_='col-time'))

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
- generated html file: file://C:\Users\vagrant\wazuh-qa\tests\integration\report.html -
================= 14 passed, 84 warnings in 232.89s (0:03:52) =================

HTML report: report.zip

nbertoldo commented 4 months ago

A further analysis was made and it is observed that in both cases the error occurs when the script tries to create the file c:\\test.

new_file_path = 'c:\\test'

    @pytest.fixture(scope='function')
    def create_file(new_file_path):
        """Create an empty file.

        Args:
            new_file_path (str): File path to create.
        """
>       write_file(new_file_path)

conftest.py:1340: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

file_path = 'c:\\test', data = ''

    def write_file(file_path, data=''):
>       with open(file_path, 'w') as f:
E       PermissionError: [Errno 13] Permission denied: 'c:\\test'

C:\Python311\Lib\site-packages\wazuh_testing\tools\file.py:177: PermissionError

The "PermissionError: [Errno 13] Permission denied error" can occur for multiple reasons:

  1. Trying to open a file, but the specified path is a folder.
  2. Not having the necessary permissions to open a file.
  3. Trying to open a file that is already opened in another application.

It is probably due to the first option as the filepath does not contain the extension but we have not been able to reproduce the error locally. In addition, we checked the changes between versions of both the integration tests and logcollector and no relevant issues were detected. However, we can confirm that this is a test issue and not a product issue.

vikman90 commented 3 months ago

@nbertoldo @nmkoremblum @cborla we've confirmed there is an issue in the test. Can we get a fix?

nbertoldo commented 3 months ago

Considering that it was possible to run the tests locally several times without errors, I think it may be a problem with the environment. @wazuh/qa Is it possible to relaunch this test?

nbertoldo commented 3 months ago

Update

The test has been run again and the error occurs in another test case, so the failure is random.

Log error ```shell conftest.py:1330: in create_files_in_folder delete_path_recursively(folder_path) C:\Python311\Lib\site-packages\wazuh_testing\tools\file.py:244: in delete_path_recursively shutil.rmtree(path, onerror=on_write_error) C:\Python311\Lib\shutil.py:759: in rmtree return _rmtree_unsafe(path, onerror) C:\Python311\Lib\shutil.py:626: in _rmtree_unsafe onerror(os.rmdir, path, sys.exc_info()) C:\Python311\Lib\shutil.py:624: in _rmtree_unsafe os.rmdir(path) E OSError: [WinError 145] The directory is not empty: 'c:\\testfolder\\subfolder' -----------------------------Captured stdout setup------------------------------ The Wazuh service was stopped successfully. The Wazuh service is starting. The Wazuh service was started successfully. -----------------------------Captured stderr setup------------------------------ 2024-01-23 17:13:18,157 - wazuh_testing - DEBUG - Set local_internal_option to {'windows.debug': '2', 'agent.debug': '2'} 2024-01-23 17:13:18,158 - wazuh_testing - DEBUG - Restarting all daemon -------------------------------Captured log setup------------------------------- DEBUG wazuh_testing:conftest.py:694 Set local_internal_option to {'windows.debug': '2', 'agent.debug': '2'} DEBUG wazuh_testing:conftest.py:144 Restarting all daemon ----------------------------Captured stdout teardown---------------------------- The Wazuh service was stopped successfully. ----------------------------Captured stderr teardown---------------------------- 2024-01-23 17:13:23,396 - wazuh_testing - DEBUG - Stopping all daemons 2024-01-23 17:13:23,586 - wazuh_testing - DEBUG - Restore local_internal_option to {'syscheck.debug': '2\n', 'agent.debug': '2\n', 'monitord.rotate_log': '0\n', 'analysisd.debug': '2\n', 'wazuh_modules.debug': '2\n', 'wazuh_database.interval': '1\n', 'wazuh_db.commit_time': '2\n', 'wazuh_db.commit_time_max': '3\n', 'remoted.debug': '2\n'} -----------------------------Captured log teardown------------------------------ DEBUG wazuh_testing:conftest.py:156 Stopping all daemons DEBUG wazuh_testing:conftest.py:699 Restore local_internal_option to {'syscheck.debug': '2\n', 'agent.debug': '2\n', 'monitord.rotate_log': '0\n', 'analysisd.debug': '2\n', 'wazuh_modules.debug': '2\n', 'wazuh_database.interval': '1\n', 'wazuh_db.commit_time': '2\n', 'wazuh_db.commit_time_max': '3\n', 'remoted.debug': '2\n'} ```
nbertoldo commented 3 months ago

Update

In a new test run, the test result has been successful, which confirms the random behaviour of the test.

vikman90 commented 3 months ago

Let's add it to the @wazuh/devel-core1-div3's backlog. It's not a stopper.