Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logcollector integration tests T0: reconnect_time option #1312

Merged
merged 11 commits into from
May 12, 2021
59 changes: 59 additions & 0 deletions deps/wazuh_testing/wazuh_testing/logcollector.py
Original file line number Diff line number Diff line change
Expand Up @@ -199,3 +199,62 @@ def callback_running_command(log_format, command, prefix=monitoring.LOG_COLLECTO
log_format_message = 'full command' if log_format == 'full_command' else 'command'
msg = fr"DEBUG: Running {log_format_message} '{command}'"
return monitoring.make_callback(pattern=msg, prefix=prefix, escape=escape)



def callback_running_command(log_format, command, prefix=monitoring.LOG_COLLECTOR_DETECTOR_PREFIX, escape=False):
"""Create a callback to detect "DEBUG: Running <log_format> '<command>'" debug line.

Args:
log_format (str): Log format of the command monitoring (full_command or command).
command (str): Command to be monitored.
prefix (str): Daemon that generates the log.
escape (bool): Flag to escape special characters in the pattern.

Returns:
callable: callback to detect this event.
"""
log_format_message = 'full command' if log_format == 'full_command' else 'command'
msg = fr"DEBUG: Running {log_format_message} '{command}'"
return monitoring.make_callback(pattern=msg, prefix=prefix, escape=escape)



def callback_event_log_service_down(location, severity='WARNING'):
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
return monitoring.make_callback(pattern=msg, prefix=prefix, escape=escape)
def callback_event_log_service_down(location, severity='WARNING'):
return monitoring.make_callback(pattern=msg, prefix=prefix, escape=escape)
def callback_event_log_service_down(location, severity='WARNING'):

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1

"""Create a callback to detect "DEBUG: Running <log_format> '<command>'" debug line.

Args:
log_format (str): Log format of the command monitoring (full_command or command).
command (str): Command to be monitored.
prefix (str): Daemon that generates the log.
escape (bool): Flag to escape special characters in the pattern.

Returns:
callable: callback to detect this event.
"""
log_format_message = f"{severity}: The eventlog service is down. Unable to collect logs from '{location}' channel."
print(f"{log_format_message}")
return monitoring.make_callback(pattern=log_format_message, prefix=monitoring.AGENT_DETECTOR_PREFIX)

def callback_trying_to_reconnect(location, reconnect_time):
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
print(f"{log_format_message}")
return monitoring.make_callback(pattern=log_format_message, prefix=monitoring.AGENT_DETECTOR_PREFIX)
def callback_trying_to_reconnect(location, reconnect_time):
return monitoring.make_callback(pattern=log_format_message, prefix=monitoring.AGENT_DETECTOR_PREFIX)
def callback_trying_to_reconnect(location, reconnect_time):

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1

"""Create a callback to detect "DEBUG: Running <log_format> '<command>'" debug line.

Args:
log_format (str): Log format of the command monitoring (full_command or command).
command (str): Command to be monitored.
prefix (str): Daemon that generates the log.
escape (bool): Flag to escape special characters in the pattern.

Returns:
callable: callback to detect this event.
"""
log_format_message = f"DEBUG: Trying to reconnect {location} channel in {reconnect_time} seconds."
print(f"{log_format_message}")
return monitoring.make_callback(pattern=log_format_message, prefix=monitoring.AGENT_DETECTOR_PREFIX)

def callback_reconnect_eventchannel(location):
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
print(f"{log_format_message}")
return monitoring.make_callback(pattern=log_format_message, prefix=monitoring.AGENT_DETECTOR_PREFIX)
def callback_reconnect_eventchannel(location):
return monitoring.make_callback(pattern=log_format_message, prefix=monitoring.AGENT_DETECTOR_PREFIX)
def callback_reconnect_eventchannel(location):

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1

"""

"""
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Something is missing here 🤔

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1

log_format_message = f"INFO: '{location}' channel has been reconnected succesfully."
return monitoring.make_callback(pattern=log_format_message, prefix=monitoring.AGENT_DETECTOR_PREFIX)
29 changes: 28 additions & 1 deletion deps/wazuh_testing/wazuh_testing/tools/services.py
Original file line number Diff line number Diff line change
Expand Up @@ -204,7 +204,7 @@ def check_daemon_status(daemon=None, running=True, timeout=10, extra_sockets=Non
# Finish main for loop if both daemon and socket checks are ok
break

time.sleep(timeout/3)
time.sleep(timeout / 3)
else:
raise TimeoutError(f"{'wazuh-service' if daemon is None else daemon} "
f"{'is not' if running else 'is'} running")
Expand Down Expand Up @@ -234,3 +234,30 @@ def check_if_process_is_running(process_name):
pass

return is_running


def control_event_log_service(control):
"""Control Windows event log service

Args:
control (str): Start or Stop
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
"""Control Windows event log service
Args:
control (str): Start or Stop
"""Control Windows event log service.
Args:
control (str): Start or Stop.

Raises section is missing here.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1

"""
for _ in range(10):
control_sc = 'disabled' if control == 'stop' else 'auto'

command = subprocess.run(f'sc config eventlog start= {control_sc}', stderr=subprocess.PIPE)
result = command.returncode
if result != 0:
raise ValueError(f'Event log service did not stop correctly')

command = subprocess.run(f"net {control} eventlog /y", stderr=subprocess.PIPE)
result = command.returncode
if result == 0:
break
else:
time.sleep(1)
else:
raise ValueError(f"Event log service did not stop correctly")

time.sleep(1)

29 changes: 29 additions & 0 deletions docs/tests/integration/test_logcollector/test_reconnect_time.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
# Test reconnect time

## Overview

Check if Wazuh Windows agent reconnect to Windows event log channels using the specified `reconnect_time`
option. These tests will disable Windows event log service and check that expected warning debugs are generated.
Then, system time is changed using `reconnect_time` value. After that, Wazuh should generate reconnect time debug log.

## Objective

- To confirm `reconnect_time` option works correctly.
- To confirm that Wazuh detect when Windows event log service is up.
- To confirm that Wazuh detect when Windows event log service is down.
- To confirm that Wazuh can reconnect to Windows event log service.

## General info

|Tier | Number of tests | Time spent |
|:--:|:--:|:--:|
| 0 | 9 | 1m4s |

## Expected behavior

- Fail if Wazuh agent does not reconnect to Windows event log at the time specified by `reconnect_time `
- Fail if Wazuh agent does not generate a debug message when Windows event log is down
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
- Fail if Wazuh agent does not reconnect to Windows event log at the time specified by `reconnect_time `
- Fail if Wazuh agent does not generate a debug message when Windows event log is down
- Fail if Wazuh agent does not reconnect to Windows event log at the time specified by `reconnect_time`.
- Fail if Wazuh agent does not generate a debug message when the Windows event log is down.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1


## Code documentation

::: tests.integration.test_logcollector.test_reconnect_time.test_reconnect_time
Original file line number Diff line number Diff line change
@@ -1,3 +1,3 @@
## Code documentation

::: tests.integration.test_vulnerability_detector.test_feeds.archlinux.test_extra_fields_archlinux_feed
::: tests.integration.test_vulnerability_detector.test_feeds.archlinux.test_extra_tags_archlinux_feed
Original file line number Diff line number Diff line change
@@ -1,3 +1,3 @@
## Code documentation

::: tests.integration.test_vulnerability_detector.test_feeds.archlinux.test_missing_fields_archlinux_feed
::: tests.integration.test_vulnerability_detector.test_feeds.archlinux.test_missing_tags_archlinux_feed
1 change: 1 addition & 0 deletions mkdocs.yml
Original file line number Diff line number Diff line change
Expand Up @@ -449,6 +449,7 @@ nav:
- Overview: tests/integration/test_logcollector/test_command_monitoring/index.md
- Test command execution: tests/integration/test_logcollector/test_command_monitoring/test_command_execution.md
- Test command execution freq: tests/integration/test_logcollector/test_command_monitoring/test_command_execution_freq.md
- Test reconnect time: tests/integration/test_logcollector/test_reconnect_time.md
- Logtest:
- tests/integration/test_logtest/index.md
- Test invalid token: tests/integration/test_logtest/test_invalid_token/test_invalid_session_token.md
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
- tags:
- test_reconnect_time
apply_to_modules:
- test_reconnect_time
sections:
- section: localfile
elements:
- location:
value: LOCATION
- log_format:
value: LOG_FORMAT
- reconnect_time:
value: RECONNECT_TIME
Original file line number Diff line number Diff line change
@@ -0,0 +1,123 @@
# Copyright (C) 2015-2021, Wazuh Inc.
# Created by Wazuh, Inc. <[email protected]>.
# This program is free software; you can redistribute it and/or modify it under the terms of GPLv2
import os
import pytest
from datetime import timedelta, datetime
import time
import sys
from wazuh_testing.tools.configuration import load_wazuh_configurations
from wazuh_testing import global_parameters, logger
from wazuh_testing.tools.time import TimeMachine
import wazuh_testing.logcollector as logcollector
from wazuh_testing.tools.time import time_to_seconds
import wazuh_testing.tools.services as services

if sys.platform != 'win32':
pytestmark = [pytest.mark.skip, pytest.mark.tier(level=0)]
else:
pytestmark = pytest.mark.tier(level=0)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
if sys.platform != 'win32':
pytestmark = [pytest.mark.skip, pytest.mark.tier(level=0)]
else:
pytestmark = pytest.mark.tier(level=0)
pytestmark = [pytest.mark.win32, pytest.mark.tier(level=0)]

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1


local_internal_options = {
'logcollector.remote_commands': 1,
'logcollector.debug': 2,
'monitord.rotate_log': 0
}

# Configuration
test_data_path = os.path.join(os.path.dirname(os.path.realpath(__file__)), 'data')
configurations_path = os.path.join(test_data_path, 'wazuh_reconnect_time.yaml')

timeout_callback_reconnect_time = 30

parameters = [
{'LOCATION': 'Application', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '5s'},
{'LOCATION': 'Security', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '5s'},
{'LOCATION': 'System', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '5s'},
{'LOCATION': 'Application', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '40m'},
{'LOCATION': 'Security', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '40m'},
{'LOCATION': 'System', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '40m'},
{'LOCATION': 'Application', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '20h'},
{'LOCATION': 'Security', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '20h'},
{'LOCATION': 'System', 'LOG_FORMAT': 'eventchannel', 'RECONNECT_TIME': '20h'},

]
metadata = [
{'location': 'Application', 'log_format': 'eventchannel', 'reconnect_time': '5s'},
{'location': 'Security', 'log_format': 'eventchannel', 'reconnect_time': '5s'},
{'location': 'System', 'log_format': 'eventchannel', 'reconnect_time': '5s'},
{'location': 'Application', 'log_format': 'eventchannel', 'reconnect_time': '40m'},
{'location': 'Security', 'log_format': 'eventchannel', 'reconnect_time': '40m'},
{'location': 'System', 'log_format': 'eventchannel', 'reconnect_time': '40m'},
{'location': 'Application', 'log_format': 'eventchannel', 'reconnect_time': '20h'},
{'location': 'Security', 'log_format': 'eventchannel', 'reconnect_time': '20h'},
{'location': 'System', 'log_format': 'eventchannel', 'reconnect_time': '20h'},
]
configurations = load_wazuh_configurations(configurations_path, __name__,
params=parameters,
metadata=metadata)
configuration_ids = [f"{x['LOCATION'], x['LOG_FORMAT'], x['RECONNECT_TIME']}" for x in parameters]


@pytest.fixture(scope="module", params=configurations, ids=configuration_ids)
def get_configuration(request):
"""Get configurations from the module."""
return request.param


@pytest.fixture(scope="module")
def get_local_internal_options():
"""Get configurations from the module."""
return local_internal_options


def test_reconnect_time(get_local_internal_options, configure_local_internal_options, get_configuration,
configure_environment, restart_logcollector):
"""Check if reconnect_time value works properly

Ensure correspond debug logs are generated when Windows event log service stop. Also, when event log service is
restarted, `wazuh-agent` should reconnect to it using reconnect_time value.
"""

config = get_configuration['metadata']

if time_to_seconds(config['reconnect_time']) >= timeout_callback_reconnect_time:
pytest.xfail("Expected fail: ")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Add more detail here explaining why the error is expected.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1


log_callback = logcollector.callback_eventchannel_analyzing(config['location'])
wazuh_log_monitor.start(timeout=global_parameters.default_timeout, callback=log_callback,
error_message=logcollector.GENERIC_CALLBACK_ERROR_ANALYZING_EVENTCHANNEL)

services.control_event_log_service('stop')

log_callback = logcollector.callback_event_log_service_down(config['location'])
wazuh_log_monitor.start(timeout=30, callback=log_callback,
error_message=logcollector.GENERIC_CALLBACK_ERROR_ANALYZING_EVENTCHANNEL)

log_callback = logcollector.callback_trying_to_reconnect(config['location'],
time_to_seconds(config['reconnect_time']))
wazuh_log_monitor.start(timeout=30, callback=log_callback,
error_message=logcollector.GENERIC_CALLBACK_ERROR_ANALYZING_EVENTCHANNEL)

services.control_event_log_service('start')

time.sleep(1)

if time_to_seconds(config['reconnect_time']) >= timeout_callback_reconnect_time:
before = str(datetime.now())
seconds_to_travel = time_to_seconds(config['reconnect_time']) / 2
TimeMachine.travel_to_future(timedelta(seconds=seconds_to_travel))
logger.debug(f"Changing the system clock from {before} to {datetime.now()}")

log_callback = logcollector.callback_reconnect_eventchannel(config['location'])

before = str(datetime.now())

if time_to_seconds(config['reconnect_time']) >= timeout_callback_reconnect_time:
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
if time_to_seconds(config['reconnect_time']) >= timeout_callback_reconnect_time:
if time_to_seconds(config['reconnect_time']) >= timeout_callback_reconnect_time:

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done 4d788e1

TimeMachine.travel_to_future(timedelta(seconds=(seconds_to_travel)))
logger.debug(f"Changing the system clock from {before} to {datetime.now()}")

wazuh_log_monitor.start(timeout=30, callback=log_callback,
error_message=logcollector.GENERIC_CALLBACK_ERROR_COMMAND_MONITORING)

TimeMachine.time_rollback()