def test_it_should_not_delete_event_files_except_current_one_if_service_stopped_midway(
self):
event_list = []
telemetry_handler = MagicMock(autospec=True)
telemetry_handler.stopped = MagicMock(return_value=False)
telemetry_handler.enqueue_event = MagicMock(
side_effect=ServiceStoppedError("Telemetry service stopped"),
wraps=event_list.append)
no_of_extensions = 3
# self._WELL_FORMED_FILES has 3 event files, i.e. total files for 3 extensions = 3 * 3 = 9
# But since we delete the file that we were processing last, expected count = 8
expected_event_file_count = 8
with self._create_extension_telemetry_processor(
telemetry_handler) as extension_telemetry_processor:
ext_names = self._create_random_extension_events_dir_with_events(
no_of_extensions, self._WELL_FORMED_FILES)
extension_telemetry_processor.run()
self.assertEqual(0, len(event_list),
"No events should have been enqueued")
total_file_count = 0
for ext_name in ext_names:
event_dir = os.path.join(conf.get_ext_log_dir(), ext_name,
EVENTS_DIRECTORY)
file_count = len(os.listdir(event_dir))
self.assertGreater(file_count, 0,
"Some event files should still be there")
total_file_count += file_count
self.assertEqual(expected_event_file_count, total_file_count,
"Expected File count doesn't match")
def _create_random_extension_events_dir_with_events(
no_of_extensions, events_path, no_of_chars=10):
if os.path.isdir(events_path):
# If its a directory, get all files from that directory
test_events_paths = glob.glob(os.path.join(events_path, "*"))
else:
test_events_paths = [events_path]
extension_names = {}
for i in range(no_of_extensions): # pylint: disable=unused-variable
ext_name = "Microsoft.OSTCExtensions.{0}".format(''.join(
random.sample(string.ascii_letters, no_of_chars)))
no_of_good_events = 0
for test_events_file_path in test_events_paths:
if not os.path.exists(
test_events_file_path) or not os.path.isfile(
test_events_file_path):
continue
no_of_good_events += TestExtensionTelemetryHandler._parse_file_and_count_good_events(
test_events_file_path)
events_dir = os.path.join(conf.get_ext_log_dir(), ext_name,
EVENTS_DIRECTORY)
fileutil.mkdir(events_dir)
shutil.copy(test_events_file_path, events_dir)
extension_names[ext_name] = no_of_good_events
return extension_names
def test_it_should_only_process_the_newer_events(self):
max_events = 5
no_of_extension = 2
test_guid = str(uuid.uuid4())
with self._create_extension_telemetry_processor() as extension_telemetry_processor:
with patch.object(extension_telemetry_processor, "_MAX_NUMBER_OF_EVENTS_PER_EXTENSION_PER_PERIOD", max_events):
ext_names_with_count = self._create_random_extension_events_dir_with_events(no_of_extension, self._WELL_FORMED_FILES)
for ext_name in ext_names_with_count.keys():
self._replace_in_file(
os.path.join(conf.get_ext_log_dir(), ext_name, EVENTS_DIRECTORY, "9999999999.json"),
replace_from='"{0}": ""'.format(ExtensionEventSchema.OperationId),
replace_to='"{0}": "{1}"'.format(ExtensionEventSchema.OperationId, test_guid))
extension_telemetry_processor.run()
telemetry_events = self._get_handlers_with_version(extension_telemetry_processor.event_list)
self._assert_handler_data_in_event_list(telemetry_events, ext_names_with_count,
expected_count=max_events)
self._assert_param_in_events(extension_telemetry_processor.event_list,
param_key=GuestAgentGenericLogsSchema.Context1,
param_value="This is the latest event", min_count=no_of_extension*max_events)
self._assert_param_in_events(extension_telemetry_processor.event_list,
param_key=GuestAgentGenericLogsSchema.Context3, param_value=test_guid,
min_count=no_of_extension*max_events)
def _ensure_extension_telemetry_state_configured_properly(protocol):
for name, path in list_agent_lib_directory(skip_agent_package=True):
try:
handler_instance = ExtHandlersHandler.get_ext_handler_instance_from_path(
name=name, path=path, protocol=protocol)
except Exception:
# Ignore errors if any
continue
try:
if handler_instance is not None:
# Recreate the HandlerEnvironment for existing extensions on startup.
# This is to ensure that existing extensions can start using the telemetry pipeline if they support
# it and also ensures that the extensions are not sending out telemetry if the Agent has to disable the feature.
handler_instance.create_handler_env()
except Exception as e: # pylint: disable=C0103
logger.warn(
"Unable to re-create HandlerEnvironment file on service startup. Error: {0}"
.format(ustr(e)))
continue
try:
if not is_extension_telemetry_pipeline_enabled():
# If extension telemetry pipeline is disabled, ensure we delete all existing extension events directory
# because the agent will not be listening on those events.
extension_event_dirs = glob.glob(
os.path.join(conf.get_ext_log_dir(), "*",
EVENTS_DIRECTORY))
for ext_dir in extension_event_dirs:
shutil.rmtree(ext_dir, ignore_errors=True)
except Exception as e: # pylint: disable=C0103
logger.warn(
"Error when trying to delete existing Extension events directory. Error: {0}"
.format(ustr(e)))
def test_it_should_skip_large_files_greater_than_max_file_size_and_report_event(self):
max_file_size = 10000
no_of_extensions = 5
with patch("azurelinuxagent.ga.collect_telemetry_events.add_log_event") as mock_event:
with patch("azurelinuxagent.ga.collect_telemetry_events._ProcessExtensionEvents._EXTENSION_EVENT_FILE_MAX_SIZE",
max_file_size):
handler_name_with_count, _ = self._setup_and_assert_tests_for_max_sizes(no_of_extensions, expected_count=0)
pattern = r'Skipping file:\s*{0}/(?P<name>.+?)/{1}.+'.format(conf.get_ext_log_dir(), EVENTS_DIRECTORY)
self._assert_event_reported(mock_event, handler_name_with_count, pattern)
def __init__(self, verbose, conf_file_path=None):
"""
Initialize agent running environment.
"""
self.conf_file_path = conf_file_path
self.osutil = get_osutil()
# Init stdout log
level = logger.LogLevel.VERBOSE if verbose else logger.LogLevel.INFO
logger.add_logger_appender(logger.AppenderType.STDOUT, level)
# Init config
conf_file_path = self.conf_file_path \
if self.conf_file_path is not None \
else self.osutil.get_agent_conf_file_path()
conf.load_conf_from_file(conf_file_path)
# Init log
verbose = verbose or conf.get_logs_verbose()
level = logger.LogLevel.VERBOSE if verbose else logger.LogLevel.INFO
logger.add_logger_appender(logger.AppenderType.FILE,
level,
path=conf.get_agent_log_file())
# echo the log to /dev/console if the machine will be provisioned
if conf.get_logs_console() and not ProvisionHandler.is_provisioned():
self.__add_console_appender(level)
if event.send_logs_to_telemetry():
logger.add_logger_appender(logger.AppenderType.TELEMETRY,
logger.LogLevel.WARNING,
path=event.add_log_event)
ext_log_dir = conf.get_ext_log_dir()
try:
if os.path.isfile(ext_log_dir):
raise Exception("{0} is a file".format(ext_log_dir))
if not os.path.isdir(ext_log_dir):
fileutil.mkdir(ext_log_dir, mode=0o755, owner="root")
except Exception as e:
logger.error("Exception occurred while creating extension "
"log directory {0}: {1}".format(ext_log_dir, e))
# Init event reporter
# Note that the reporter is not fully initialized here yet. Some telemetry fields are filled with data
# originating from the goal state or IMDS, which requires a WireProtocol instance. Once a protocol
# has been established, those fields must be explicitly initialized using
# initialize_event_logger_vminfo_common_parameters(). Any events created before that initialization
# will contain dummy values on those fields.
event.init_event_status(conf.get_lib_dir())
event_dir = os.path.join(conf.get_lib_dir(), event.EVENTS_DIRECTORY)
event.init_event_logger(event_dir)
event.enable_unhandled_err_dump("WALA")
def test_it_should_always_cleanup_files_on_good_and_bad_cases(self):
with self._create_extension_telemetry_processor(
) as extension_telemetry_processor:
extensions_with_count = self._create_random_extension_events_dir_with_events(
2, os.path.join(self._TEST_DATA_DIR, "large_messages"))
extensions_with_count.update(
self._create_random_extension_events_dir_with_events(
3, self._MALFORMED_FILES))
extensions_with_count.update(
self._create_random_extension_events_dir_with_events(
4, self._WELL_FORMED_FILES))
extensions_with_count.update(
self._create_random_extension_events_dir_with_events(
1, self._MIX_FILES))
# Create random files in the events directory for each extension just to ensure that we delete them later
for handler_name in extensions_with_count.keys():
file_name = os.path.join(
conf.get_ext_log_dir(), handler_name, EVENTS_DIRECTORY,
''.join(random.sample(string.ascii_letters, 10)))
with open(file_name, 'a') as random_file:
random_file.write('1*2*3' * 100)
extension_telemetry_processor.run()
telemetry_events = self._get_handlers_with_version(
extension_telemetry_processor.event_list)
self._assert_handler_data_in_event_list(telemetry_events,
extensions_with_count)
for handler_name in extensions_with_count.keys():
events_path = os.path.join(conf.get_ext_log_dir(),
handler_name, EVENTS_DIRECTORY)
self.assertTrue(os.path.exists(events_path),
"{0} dir doesn't exist".format(events_path))
self.assertEqual(
0, len(os.listdir(events_path)),
"There should be no files inside the events dir")
def __init__(self, verbose, conf_file_path=None):
"""
Initialize agent running environment.
"""
self.conf_file_path = conf_file_path
self.osutil = get_osutil()
#Init stdout log
level = logger.LogLevel.VERBOSE if verbose else logger.LogLevel.INFO
logger.add_logger_appender(logger.AppenderType.STDOUT, level)
#Init config
conf_file_path = self.conf_file_path \
if self.conf_file_path is not None \
else self.osutil.get_agent_conf_file_path()
conf.load_conf_from_file(conf_file_path)
#Init log
verbose = verbose or conf.get_logs_verbose()
level = logger.LogLevel.VERBOSE if verbose else logger.LogLevel.INFO
logger.add_logger_appender(logger.AppenderType.FILE,
level,
path="/var/log/waagent.log")
if conf.get_logs_console():
logger.add_logger_appender(logger.AppenderType.CONSOLE,
level,
path="/dev/console")
# See issue #1035
# logger.add_logger_appender(logger.AppenderType.TELEMETRY,
# logger.LogLevel.WARNING,
# path=event.add_log_event)
ext_log_dir = conf.get_ext_log_dir()
try:
if os.path.isfile(ext_log_dir):
raise Exception("{0} is a file".format(ext_log_dir))
if not os.path.isdir(ext_log_dir):
fileutil.mkdir(ext_log_dir, mode=0o755, owner="root")
except Exception as e:
logger.error("Exception occurred while creating extension "
"log directory {0}: {1}".format(ext_log_dir, e))
#Init event reporter
event.init_event_status(conf.get_lib_dir())
event_dir = os.path.join(conf.get_lib_dir(), "events")
event.init_event_logger(event_dir)
event.enable_unhandled_err_dump("WALA")
def __init__(self, verbose, conf_file_path=None):
"""
Initialize agent running environment.
"""
self.conf_file_path = conf_file_path
self.osutil = get_osutil()
#Init stdout log
level = logger.LogLevel.VERBOSE if verbose else logger.LogLevel.INFO
logger.add_logger_appender(logger.AppenderType.STDOUT, level)
#Init config
conf_file_path = self.conf_file_path \
if self.conf_file_path is not None \
else self.osutil.get_agent_conf_file_path()
conf.load_conf_from_file(conf_file_path)
#Init log
verbose = verbose or conf.get_logs_verbose()
level = logger.LogLevel.VERBOSE if verbose else logger.LogLevel.INFO
logger.add_logger_appender(logger.AppenderType.FILE, level,
path="/var/log/waagent.log")
if conf.get_logs_console():
logger.add_logger_appender(logger.AppenderType.CONSOLE, level,
path="/dev/console")
# See issue #1035
# logger.add_logger_appender(logger.AppenderType.TELEMETRY,
# logger.LogLevel.WARNING,
# path=event.add_log_event)
ext_log_dir = conf.get_ext_log_dir()
try:
if os.path.isfile(ext_log_dir):
raise Exception("{0} is a file".format(ext_log_dir))
if not os.path.isdir(ext_log_dir):
fileutil.mkdir(ext_log_dir, mode=0o755, owner="root")
except Exception as e:
logger.error(
"Exception occurred while creating extension "
"log directory {0}: {1}".format(ext_log_dir, e))
#Init event reporter
event.init_event_status(conf.get_lib_dir())
event_dir = os.path.join(conf.get_lib_dir(), "events")
event.init_event_logger(event_dir)
event.enable_unhandled_err_dump("WALA")
def _operation(self):
if self._send_telemetry_events_handler.stopped():
logger.warn(
"{0} service is not running, skipping current iteration".
format(self._send_telemetry_events_handler.get_thread_name()))
return
delete_all_event_files = True
extension_handler_with_event_dirs = []
try:
extension_handler_with_event_dirs = self._get_extension_events_dir_with_handler_name(
conf.get_ext_log_dir())
if not extension_handler_with_event_dirs:
logger.verbose("No Extension events directory exist")
return
for extension_handler_with_event_dir in extension_handler_with_event_dirs:
handler_name = extension_handler_with_event_dir[0]
handler_event_dir_path = extension_handler_with_event_dir[1]
self._capture_extension_events(handler_name,
handler_event_dir_path)
except ServiceStoppedError:
# Since the service stopped, we should not delete the extension files and retry sending them whenever
# the telemetry service comes back up
delete_all_event_files = False
except Exception as error:
msg = "Unknown error occurred when trying to collect extension events:{0}".format(
textutil.format_exception(error))
add_event(op=WALAEventOperation.ExtensionTelemetryEventProcessing,
message=msg,
is_success=False)
finally:
# Always ensure that the events directory are being deleted each run except when Telemetry Service is stopped,
# even if we run into an error and dont process them this run.
if delete_all_event_files:
self._ensure_all_events_directories_empty(
extension_handler_with_event_dirs)
def del_dirs(self, warnings, actions):
dirs = [conf.get_lib_dir(), conf.get_ext_log_dir()]
actions.append(DeprovisionAction(fileutil.rm_dirs, dirs))
def setUp(self):
AgentTestCase.setUp(self)
clear_singleton_instances(ProtocolUtil)
# Create the log directory if not exists
fileutil.mkdir(conf.get_ext_log_dir())
def get_log_dir(self):
return os.path.join(conf.get_ext_log_dir(), self.ext_handler.name)
import logging
import os
import subprocess
import time
import zipfile
from datetime import datetime
from heapq import heappush, heappop
from azurelinuxagent.common.conf import get_lib_dir, get_ext_log_dir, get_agent_log_file
from azurelinuxagent.common.future import ustr
from azurelinuxagent.common.logcollector_manifests import MANIFEST_NORMAL, MANIFEST_FULL
# Please note: be careful when adding agent dependencies in this module.
# This module uses its own logger and logs to its own file, not to the agent log.
_EXTENSION_LOG_DIR = get_ext_log_dir()
_AGENT_LIB_DIR = get_lib_dir()
_AGENT_LOG = get_agent_log_file()
_LOG_COLLECTOR_DIR = os.path.join(_AGENT_LIB_DIR, "logcollector")
_TRUNCATED_FILES_DIR = os.path.join(_LOG_COLLECTOR_DIR, "truncated")
OUTPUT_RESULTS_FILE_PATH = os.path.join(_LOG_COLLECTOR_DIR, "results.txt")
COMPRESSED_ARCHIVE_PATH = os.path.join(_LOG_COLLECTOR_DIR, "logs.zip")
_MUST_COLLECT_FILES = [
_AGENT_LOG,
os.path.join(_AGENT_LIB_DIR, "GoalState.*.xml"),
os.path.join(_AGENT_LIB_DIR, "ExtensionsConfig.*.xml"),
os.path.join(_AGENT_LIB_DIR, "HostingEnvironmentConfig.*.xml"),
os.path.join(_AGENT_LIB_DIR, "SharedConfig.*.xml"),
def get_log_dir(self):
return os.path.join(conf.get_ext_log_dir(), self.ext_handler.name)
def del_dirs(self, warnings, actions):
dirs = [conf.get_lib_dir(), conf.get_ext_log_dir()]
actions.append(DeprovisionAction(fileutil.rm_dirs, dirs))
def get_log_dir(self):
return os.path.join(conf.get_ext_log_dir(), self.ext_handler.name,
str(self.ext_handler.properties.version))
def get_log_dir(self):
return os.path.join(conf.get_ext_log_dir(), self.ext_handler.name,
self.ext_handler.properties.version)