def test_console_appender(self):
logger.add_logger_appender(logger.AppenderType.CONSOLE,
logger.LogLevel.WARNING,
path=self.log_file)
logger.verbose("test-verbose")
with open(self.log_file) as logfile:
logcontent = logfile.readlines()
# Levels are honored and Verbose should not be written.
self.assertEqual(0, len(logcontent))
logger.info("test-info")
with open(self.log_file) as logfile:
logcontent = logfile.readlines()
# Levels are honored and Info should not be written.
self.assertEqual(0, len(logcontent))
# As console has a mode of w, it'll always only have 1 line only.
logger.warn("test-warn")
with open(self.log_file) as logfile:
logcontent = logfile.readlines()
self.assertEqual(1, len(logcontent))
self.assertRegex(logcontent[0], r"(.*WARNING\s\w+\s*test-warn.*)")
logger.error("test-error")
with open(self.log_file) as logfile:
logcontent = logfile.readlines()
# Levels are honored and Info, Verbose should not be written.
self.assertEqual(1, len(logcontent))
self.assertRegex(logcontent[0], r"(.*ERROR\s\w+\s*test-error.*)")
def test_telemetry_logger_verify_maximum_recursion_depths_doesnt_happen(
self, *_):
logger.add_logger_appender(logger.AppenderType.FILE,
logger.LogLevel.INFO,
path="/dev/null")
logger.add_logger_appender(logger.AppenderType.TELEMETRY,
logger.LogLevel.WARNING,
path=add_log_event)
for i in range(MAX_NUMBER_OF_EVENTS):
logger.warn('Test Log - {0} - 1 - Warning'.format(i))
exception_caught = False
# #1035 was caused due to too many files being written in an error condition. Adding even one more here broke
# the camels back earlier - It would go into an infinite recursion as telemetry would call log, which in turn
# would call telemetry, and so on.
# The description of the fix is given in the comments @ azurelinuxagent.common.logger.Logger#log.write_log.
try:
for i in range(10):
logger.warn('Test Log - {0} - 2 - Warning'.format(i))
except RuntimeError:
exception_caught = True
self.assertFalse(
exception_caught,
msg="Caught a Runtime Error. This should not have been raised.")
def test_telemetry_logger_add_log_event(self, mock_lib_dir, *_):
mock_lib_dir.return_value = self.lib_dir
__event_logger__.event_dir = self.event_dir
prefix = "YoloLogger"
logger.add_logger_appender(logger.AppenderType.TELEMETRY,
logger.LogLevel.WARNING,
path=add_log_event)
logger.set_prefix(prefix)
logger.warn('Test Log - Warning')
event_files = os.listdir(__event_logger__.event_dir)
self.assertEqual(1, len(event_files))
log_file_event = os.path.join(__event_logger__.event_dir,
event_files[0])
try:
with open(log_file_event) as logfile:
logcontent = logfile.read()
# Checking the contents of the event file.
self.assertIn("Test Log - Warning", logcontent)
except Exception as e:
self.assertFalse(
True,
"The log file looks like it isn't correctly setup for this test. Take a look. " # pylint: disable=redundant-unittest-assert
"{0}".format(e))
def test_telemetry_appender(self, mock_add_log_event, *_):
logger.add_logger_appender(logger.AppenderType.TELEMETRY, logger.LogLevel.WARNING, path=add_log_event)
logger.verbose("test-verbose")
logger.info("test-info")
logger.warn("test-warn")
logger.error("test-error")
self.assertEqual(2, mock_add_log_event.call_count)
def test_stdout_appender(self, mock_sys_stdout):
logger.add_logger_appender(logger.AppenderType.STDOUT, logger.LogLevel.ERROR)
logger.verbose("test-verbose")
logger.info("test-info")
logger.warn("test-warn")
logger.error("test-error")
# Validating only test-error gets logged and not others.
self.assertEqual(1, mock_sys_stdout.call_count)
def test_telemetry_logger_check_all_file_logs_written_when_events_gt_MAX_NUMBER_OF_EVENTS(
self, mock_lib_dir, *_):
mock_lib_dir.return_value = self.lib_dir
__event_logger__.event_dir = self.event_dir
no_of_log_statements = MAX_NUMBER_OF_EVENTS + 100
exception_caught = False
prefix = "YoloLogger"
logger.add_logger_appender(logger.AppenderType.FILE,
logger.LogLevel.INFO,
path=self.log_file)
logger.add_logger_appender(logger.AppenderType.TELEMETRY,
logger.LogLevel.WARNING,
path=add_log_event)
logger.set_prefix(prefix)
# Calling logger.warn no_of_log_statements times would cause the telemetry appender to writing
# 1000 events into the events dir, and then drop the remaining events. It should not generate the RuntimeError
try:
for i in range(0, no_of_log_statements):
logger.warn('Test Log - {0} - 1 - Warning'.format(i))
except RuntimeError:
exception_caught = True
self.assertFalse(
exception_caught,
msg="Caught a Runtime Error. This should not have been raised.")
self.assertEqual(MAX_NUMBER_OF_EVENTS,
len(os.listdir(__event_logger__.event_dir)))
try:
with open(self.log_file) as logfile:
logcontent = logfile.readlines()
# Checking the last log entry.
# Subtracting 1 as range is exclusive of the upper bound
self.assertIn(
"WARNING {1} Test Log - {0} - 1 - Warning".format(
no_of_log_statements - 1, prefix), logcontent[-1])
# Checking the 1001st log entry. We know that 1001st entry would generate a PERIODIC message of too many
# events, which should be captured in the log file as well.
self.assertRegex(
logcontent[1001],
r"(.*WARNING\s*{0}\s*\[PERIODIC\]\s*Too many files under:.*{1}, "
r"current count\:\s*\d+,\s*removing oldest\s*.*)".format(
prefix, self.event_dir))
except Exception as e:
self.assertFalse(
True,
"The log file looks like it isn't correctly setup for this test. " # pylint: disable=redundant-unittest-assert
"Take a look. {0}".format(e))
def test_file_appender(self):
logger.add_logger_appender(logger.AppenderType.FILE, logger.LogLevel.INFO, path=self.log_file)
logger.verbose("test-verbose")
logger.info("test-info")
logger.warn("test-warn")
logger.error("test-error")
with open(self.log_file) as logfile:
logcontent = logfile.readlines()
# Levels are honored and Verbose should not be written.
self.assertEqual(3, len(logcontent))
self.assertRegex(logcontent[0], r"(.*INFO\s*test-info.*)")
self.assertRegex(logcontent[1], r"(.*WARNING\s*test-warn.*)")
self.assertRegex(logcontent[2], r"(.*ERROR\s*test-error.*)")
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")
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 __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")
logger.add_logger_appender(logger.AppenderType.CONSOLE,
level,
path="/dev/console")
#Init event reporter
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):
"""
Initialize agent running environment.
"""
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.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")
logger.add_logger_appender(logger.AppenderType.CONSOLE, level,
path="/dev/console")
#Init event reporter
event_dir = os.path.join(conf.get_lib_dir(), "events")
event.init_event_logger(event_dir)
event.enable_unhandled_err_dump("WALA")
def test_nested_logger(self, mock_file_write, mock_console_write,
mock_telem_write, mock_stdout_write):
"""
The purpose of this test is to see if the logger gets correctly created when passed it another logger and also
if the appender correctly gets the messages logged. This is how the ExtHandlerInstance logger works.
I initialize the default logger(logger), then create a new logger(lg) from it, and then log using logger & lg.
See if both logs are flowing through or not.
"""
parent_prefix = "ParentLogger"
child_prefix = "ChildLogger"
logger.add_logger_appender(logger.AppenderType.FILE,
logger.LogLevel.INFO,
path=self.log_file)
logger.add_logger_appender(logger.AppenderType.TELEMETRY,
logger.LogLevel.WARNING,
path=add_log_event)
logger.add_logger_appender(logger.AppenderType.CONSOLE,
logger.LogLevel.WARNING,
path="/dev/null")
logger.add_logger_appender(logger.AppenderType.STDOUT,
logger.LogLevel.WARNING)
logger.set_prefix(parent_prefix)
lg = logger.Logger(logger.DEFAULT_LOGGER, child_prefix)
lg.error("Test Log")
self.assertEqual(1, mock_file_write.call_count)
self.assertEqual(1, mock_console_write.call_count)
self.assertEqual(1, mock_telem_write.call_count)
self.assertEqual(1, mock_stdout_write.call_count)
self.assertIn(child_prefix, mock_file_write.call_args[0][1])
self.assertIn(child_prefix, mock_console_write.call_args[0][1])
self.assertIn(child_prefix, mock_telem_write.call_args[0][1])
self.assertIn(child_prefix, mock_stdout_write.call_args[0][1])
logger.error("Test Log")
self.assertEqual(2, mock_file_write.call_count)
self.assertEqual(2, mock_console_write.call_count)
self.assertEqual(2, mock_telem_write.call_count)
self.assertEqual(2, mock_stdout_write.call_count)
self.assertIn(parent_prefix, mock_file_write.call_args[0][1])
self.assertIn(parent_prefix, mock_console_write.call_args[0][1])
self.assertIn(parent_prefix, mock_telem_write.call_args[0][1])
self.assertIn(parent_prefix, mock_stdout_write.call_args[0][1])
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")
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
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")
#Import mock module for Python2 and Python3
try:
from unittest.mock import Mock, patch, MagicMock, DEFAULT, call
except ImportError:
from mock import Mock, patch, MagicMock, DEFAULT, call
test_dir = os.path.dirname(os.path.abspath(__file__))
data_dir = os.path.join(test_dir, "data")
debug = False
if os.environ.get('DEBUG') == '1':
debug = True
#Enable verbose logger to stdout
if debug:
logger.add_logger_appender(logger.AppenderType.STDOUT,
logger.LogLevel.VERBOSE)
class AgentTestCase(unittest.TestCase):
def setUp(self):
prefix = "{0}_".format(self.__class__.__name__)
self.tmp_dir = tempfile.mkdtemp(prefix=prefix)
self.test_file = 'test_file'
conf.get_autoupdate_enabled = Mock(return_value=True)
conf.get_lib_dir = Mock(return_value=self.tmp_dir)
ext_log_dir = os.path.join(self.tmp_dir, "azure")
conf.get_ext_log_dir = Mock(return_value=ext_log_dir)
conf.get_agent_pid_file_path = Mock(return_value=os.path.join(self.tmp_dir, "waagent.pid"))
def tearDown(self):
if not debug and self.tmp_dir is not None:
shutil.rmtree(self.tmp_dir)
# Import mock module for Python2 and Python3
from bin.waagent2 import Agent
except ImportError:
from mock import Mock, patch, MagicMock, ANY, DEFAULT, call, PropertyMock
test_dir = os.path.dirname(os.path.abspath(__file__))
data_dir = os.path.join(test_dir, "data")
debug = False
if os.environ.get('DEBUG') == '1':
debug = True
# Enable verbose logger to stdout
if debug:
logger.add_logger_appender(logger.AppenderType.STDOUT,
logger.LogLevel.VERBOSE)
_MAX_LENGTH = 120
_MAX_LENGTH_SAFE_REPR = 80
# Mock sleep to reduce test execution time
_SLEEP = time.sleep
def mock_sleep(sec=0.01):
"""
Mocks the time.sleep method to reduce unit test time
:param sec: Time to replace the sleep call with, default = 0.01sec
"""
_SLEEP(sec)
def __add_console_appender(self, level):
logger.add_logger_appender(logger.AppenderType.CONSOLE,
level,
path="/dev/console")