def test_log_verifier_add_call_seq3(
self, simple_str_arg: str, capsys: pytest.CaptureFixture[str],
caplog: pytest.CaptureFixture[str]) -> None:
"""Test log_verifier add_call_seq method.
Args:
simple_str_arg: string to use in the message
capsys: pytest fixture to capture print output
caplog: pytest fixture to capture log output
"""
t_logger = logging.getLogger('call_seq3')
log_ver = LogVer(log_name='call_seq3')
log_ver.add_call_seq(name='alpha',
seq=('test_log_verifier.py::TestLogVerBasic'
'.test_log_verifier_add_call_seq3'))
esc_thread_str = re.escape(f'{threading.current_thread()}')
add_msg = (f'{esc_thread_str} '
f'{simple_str_arg} '
f'{log_ver.get_call_seq(name="alpha")}')
log_ver.add_msg(log_msg=add_msg)
log_msg = (f'{threading.current_thread()} '
f'{simple_str_arg} '
f'{get_formatted_call_sequence(depth=1)}')
t_logger.debug(log_msg)
log_ver.print_match_results(
log_results := log_ver.get_match_results(caplog))
log_ver.verify_log_results(log_results)
expected_result = '\n'
expected_result += '**********************************\n'
expected_result += '* number expected log records: 1 *\n'
expected_result += '* number expected unmatched : 0 *\n'
expected_result += '* number actual log records : 1 *\n'
expected_result += '* number actual unmatched : 0 *\n'
expected_result += '* number matched records : 1 *\n'
expected_result += '**********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched expected records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched actual records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* matched records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += f"('call_seq3', 10, '{log_msg}')\n"
captured = capsys.readouterr().out
assert captured == expected_result
def test_log_verifier_example4(self, capsys: pytest.CaptureFixture[str],
caplog: pytest.CaptureFixture[str]) -> None:
"""Test log_verifier example4.
Args:
capsys: pytest fixture to capture print output
caplog: pytest fixture to capture log output
"""
# two log messages expected, two logged, one different
# logged
t_logger = logging.getLogger('example_4')
log_ver = LogVer(log_name='example_4')
log_msg1 = 'hello'
log_ver.add_msg(log_msg=log_msg1)
log_msg2a = 'goodbye'
log_ver.add_msg(log_msg=log_msg2a)
log_msg2b = 'see you soon'
t_logger.debug(log_msg1)
t_logger.debug(log_msg2b)
log_ver.print_match_results(
log_results := log_ver.get_match_results(caplog))
with pytest.raises(UnmatchedExpectedMessages):
log_ver.verify_log_results(log_results)
expected_result = '\n'
expected_result += '**********************************\n'
expected_result += '* number expected log records: 2 *\n'
expected_result += '* number expected unmatched : 1 *\n'
expected_result += '* number actual log records : 2 *\n'
expected_result += '* number actual unmatched : 1 *\n'
expected_result += '* number matched records : 1 *\n'
expected_result += '**********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched expected records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += "('example_4', 10, 'goodbye')\n"
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched actual records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += "('example_4', 10, 'see you soon')\n"
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* matched records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += "('example_4', 10, 'hello')\n"
captured = capsys.readouterr().out
assert captured == expected_result
def test_log_verifier_add_call_seq(
self, simple_str_arg: str, capsys: pytest.CaptureFixture[str],
caplog: pytest.CaptureFixture[str]) -> None:
"""Test log_verifier add_call_seq method.
Args:
simple_str_arg: string to use in the message
capsys: pytest fixture to capture print output
caplog: pytest fixture to capture log output
"""
t_logger = logging.getLogger('call_seq')
log_ver = LogVer(log_name='call_seq')
log_ver.add_call_seq(name='alpha', seq=simple_str_arg)
log_ver.add_msg(log_msg=log_ver.get_call_seq('alpha'))
t_logger.debug(f'{simple_str_arg}:{123}')
log_ver.print_match_results(
log_results := log_ver.get_match_results(caplog))
log_ver.verify_log_results(log_results)
expected_result = '\n'
expected_result += '**********************************\n'
expected_result += '* number expected log records: 1 *\n'
expected_result += '* number expected unmatched : 0 *\n'
expected_result += '* number actual log records : 1 *\n'
expected_result += '* number actual unmatched : 0 *\n'
expected_result += '* number matched records : 1 *\n'
expected_result += '**********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched expected records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched actual records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* matched records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += f"('call_seq', 10, '{simple_str_arg}:{123}')\n"
captured = capsys.readouterr().out
assert captured == expected_result
def test_log_verifier_example1(self, capsys: pytest.CaptureFixture[str],
caplog: pytest.CaptureFixture[str]) -> None:
"""Test log_verifier example1.
Args:
capsys: pytest fixture to capture print output
caplog: pytest fixture to capture log output
"""
# one message expected, one message logged
t_logger = logging.getLogger('example_1')
log_ver = LogVer(log_name='example_1')
log_msg = 'hello'
log_ver.add_msg(log_msg=log_msg)
t_logger.debug(log_msg)
log_results = log_ver.get_match_results(caplog)
log_ver.print_match_results(log_results)
log_ver.verify_log_results(log_results)
expected_result = '\n'
expected_result += '**********************************\n'
expected_result += '* number expected log records: 1 *\n'
expected_result += '* number expected unmatched : 0 *\n'
expected_result += '* number actual log records : 1 *\n'
expected_result += '* number actual unmatched : 0 *\n'
expected_result += '* number matched records : 1 *\n'
expected_result += '**********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched expected records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched actual records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* matched records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += "('example_1', 10, 'hello')\n"
captured = capsys.readouterr().out
assert captured == expected_result
def test_log_verifier_time_match(
self, capsys: pytest.CaptureFixture[str],
caplog: pytest.CaptureFixture[str]) -> None:
"""Test log_verifier time match.
Args:
capsys: pytest fixture to capture print output
caplog: pytest fixture to capture log output
"""
t_logger = logging.getLogger('time_match')
log_ver = LogVer(log_name='time_match')
fmt_str = '%d %b %Y %H:%M:%S'
match_str = get_datetime_match_string(fmt_str)
time_str = datetime.datetime.now().strftime(fmt_str)
exp_msg = f'the date and time is: {match_str}'
act_msg = f'the date and time is: {time_str}'
log_ver.add_msg(log_msg=exp_msg, log_name='time_match')
t_logger.debug(act_msg)
log_ver.print_match_results(
log_results := log_ver.get_match_results(caplog))
log_ver.verify_log_results(log_results)
expected_result = '\n'
expected_result += '**********************************\n'
expected_result += '* number expected log records: 1 *\n'
expected_result += '* number expected unmatched : 0 *\n'
expected_result += '* number actual log records : 1 *\n'
expected_result += '* number actual unmatched : 0 *\n'
expected_result += '* number matched records : 1 *\n'
expected_result += '**********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched expected records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched actual records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* matched records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
log_msg = f'the date and time is: {time_str}'
expected_result += f"('time_match', 10, '{log_msg}')\n"
captured = capsys.readouterr().out
assert captured == expected_result
def test_msgs_timeout(self, timeout_arg: float,
caplog: pytest.CaptureFixture[str]) -> None:
"""test_msgs_timeout.
Args:
timeout_arg: number of seconds to use for timeout value
on get_msg request
caplog: pytest fixture to capture log output
"""
def f1() -> None:
"""Beta f1 function."""
f1_log_msg = 'f1 beta entered'
log_ver.add_msg(f1_log_msg)
logger.debug(f1_log_msg)
f1_to_low = f1_timeout
f1_to_high = f1_timeout * 1.1
f1_stop_watch = StopWatch()
f1_log_msg = 'f1 beta starting timeout -1'
log_ver.add_msg(f1_log_msg)
logger.debug(f1_log_msg)
f1_stop_watch.start_clock(clock_iter=1)
msgs.get_msg('beta', timeout=-1)
assert f1_to_low <= f1_stop_watch.duration() <= f1_to_high
f1_log_msg = 'f1 beta starting timeout 0'
log_ver.add_msg(f1_log_msg)
logger.debug(f1_log_msg)
f1_stop_watch.start_clock(clock_iter=2)
msgs.get_msg('beta', timeout=0)
assert f1_to_low <= f1_stop_watch.duration() <= f1_to_high
f1_log_msg = 'f1 beta starting timeout None'
log_ver.add_msg(f1_log_msg)
logger.debug(f1_log_msg)
f1_stop_watch.start_clock(clock_iter=3)
msgs.get_msg('beta', timeout=None)
assert f1_to_low <= f1_stop_watch.duration() <= f1_to_high
f1_log_msg = 'f1 beta exiting'
log_ver.add_msg(f1_log_msg)
logger.debug(f1_log_msg)
logger.debug('mainline entered')
msgs = Msgs()
ml_stop_watch = StopWatch()
log_ver = LogVer(log_name='test_msgs')
alpha_call_seq = 'test_msgs.py::TestMsgsErrors.test_msgs_timeout'
log_ver.add_call_seq(name='alpha', seq=alpha_call_seq)
log_msg = 'mainline entered'
log_ver.add_msg(log_name='test_msgs',
log_level=logging.DEBUG,
log_msg=log_msg)
f1_timeout = 5
f1_thread = threading.Thread(target=f1)
# we expect to get this log message in the following code
thread_info = re.escape(f'{threading.current_thread()}')
log_msg = (f'Thread {thread_info} '
f'timed out on get_msg for recipient: beta '
f'{log_ver.get_call_seq("alpha")}')
log_ver.add_msg(log_name='scottbrian_utils.msgs',
log_level=logging.DEBUG,
log_msg=log_msg)
# we will try -1 as a timeout value in the section below, and
# we also use the -1 value to do the default value
if timeout_arg == 0.0: # if do default timeout
############################################################
# get_msg timeout with default
############################################################
to_low = Msgs.GET_CMD_TIMEOUT
to_high = Msgs.GET_CMD_TIMEOUT * 1.1
ml_stop_watch.start_clock(clock_iter=1)
with pytest.raises(GetMsgTimedOut):
_ = msgs.get_msg('beta')
assert to_low <= ml_stop_watch.duration() <= to_high
f1_thread.start()
log_msg = 'mainline starting timeout loop'
log_ver.add_msg(log_msg)
logger.debug(log_msg)
for idx in range(2, 5): # 2, 3, 4
log_msg = f'mainline starting timeout loop {idx}'
log_ver.add_msg(log_msg)
logger.debug(log_msg)
ml_stop_watch.start_clock(clock_iter=idx)
ml_stop_watch.pause(seconds=f1_timeout, clock_iter=idx)
log_msg = f'mainline duration {ml_stop_watch.duration()}'
log_ver.add_msg(log_msg)
logger.debug(log_msg)
msgs.queue_msg('beta')
else:
############################################################
# get_msg timeout with timeout_arg
############################################################
to_low = timeout_arg
to_high = timeout_arg * 1.2
log_msg = f'mainline starting timeout {timeout_arg}'
log_ver.add_msg(log_msg)
logger.debug(log_msg)
ml_stop_watch.start_clock(clock_iter=1)
with pytest.raises(GetMsgTimedOut):
_ = msgs.get_msg('beta', timeout_arg)
assert to_low <= ml_stop_watch.duration() <= to_high
match_results = log_ver.get_match_results(caplog=caplog)
log_ver.print_match_results(match_results)
log_ver.verify_log_results(match_results)
logger.debug('mainline exiting')
def test_log_verifier_combos(self, num_exp_msgs1: int, num_exp_msgs2: int,
num_exp_msgs3: int, num_act_msgs1: int,
num_act_msgs2: int, num_act_msgs3: int,
capsys: pytest.CaptureFixture[str],
caplog: pytest.CaptureFixture[str]) -> None:
"""Test log_verifier combos.
Args:
num_exp_msgs1: number of expected messages for msg1
num_exp_msgs2: number of expected messages for msg2
num_exp_msgs3: number of expected messages for msg3
num_act_msgs1: number of actual messages for msg1
num_act_msgs2: number of actual messages for msg2
num_act_msgs3: number of actual messages for msg3
capsys: pytest fixture to capture print output
caplog: pytest fixture to capture log output
"""
t_logger = logging.getLogger('combos')
log_ver = LogVer(log_name='combos')
total_num_exp_msgs = 0
total_num_act_msgs = 0
total_num_exp_unmatched = 0
total_num_act_unmatched = 0
total_num_matched = 0
exp_unmatched_msgs = []
act_unmatched_msgs = []
matched_msgs = []
msg_table = [(num_exp_msgs1, num_act_msgs1, 'msg one'),
(num_exp_msgs2, num_act_msgs2, 'msg two'),
(num_exp_msgs3, num_act_msgs3, 'msg three')]
for num_exp, num_act, the_msg in msg_table:
total_num_exp_msgs += num_exp
total_num_act_msgs += num_act
num_exp_unmatched = max(0, num_exp - num_act)
total_num_exp_unmatched += num_exp_unmatched
num_act_unmatched = max(0, num_act - num_exp)
total_num_act_unmatched += num_act_unmatched
num_matched_msgs = num_exp - num_exp_unmatched
total_num_matched += num_matched_msgs
for _ in range(num_exp):
log_ver.add_msg(log_msg=the_msg)
for _ in range(num_act):
t_logger.debug(the_msg)
for _ in range(num_exp_unmatched):
exp_unmatched_msgs.append(the_msg)
for _ in range(num_act_unmatched):
act_unmatched_msgs.append(the_msg)
for _ in range(num_matched_msgs):
matched_msgs.append(the_msg)
max_of_totals = max(total_num_exp_msgs, total_num_act_msgs,
total_num_exp_unmatched, total_num_act_unmatched,
total_num_matched)
len_max_total = len(str(max_of_totals))
asterisks = '*********************************' + '*' * len_max_total
num_exp_space = len_max_total - len(str(total_num_exp_msgs))
num_exp_unm_space = len_max_total - len(str(total_num_exp_unmatched))
num_act_space = len_max_total - len(str(total_num_act_msgs))
num_act_unm_space = len_max_total - len(str(total_num_act_unmatched))
num_matched_space = len_max_total - len(str(total_num_matched))
log_ver.print_match_results(
log_results := log_ver.get_match_results(caplog))
if total_num_exp_unmatched:
with pytest.raises(UnmatchedExpectedMessages):
log_ver.verify_log_results(log_results)
elif total_num_act_unmatched:
with pytest.raises(UnmatchedActualMessages):
log_ver.verify_log_results(log_results)
else:
log_ver.verify_log_results(log_results)
expected_result = '\n'
expected_result += asterisks + '\n'
expected_result += ('* number expected log records: ' +
' ' * num_exp_space + f'{total_num_exp_msgs} *\n')
expected_result += ('* number expected unmatched : ' +
' ' * num_exp_unm_space +
f'{total_num_exp_unmatched} *\n')
expected_result += ('* number actual log records : ' +
' ' * num_act_space + f'{total_num_act_msgs} *\n')
expected_result += ('* number actual unmatched : ' +
' ' * num_act_unm_space +
f'{total_num_act_unmatched} *\n')
expected_result += ('* number matched records : ' +
' ' * num_matched_space +
f'{total_num_matched} *\n')
expected_result += asterisks + '\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched expected records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
for msg in exp_unmatched_msgs:
expected_result += f"('combos', 10, '{msg}')\n"
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched actual records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
for msg in act_unmatched_msgs:
expected_result += f"('combos', 10, '{msg}')\n"
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* matched records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
for msg in matched_msgs:
expected_result += f"('combos', 10, '{msg}')\n"
captured = capsys.readouterr().out
assert captured == expected_result
def test_log_verifier_no_log(self, log_enabled_arg: bool,
capsys: pytest.CaptureFixture[str],
caplog: pytest.CaptureFixture[str]) -> None:
"""Test log_verifier with logging disabled and enabled.
Args:
log_enabled_arg: fixture to indicate whether log is enabled
capsys: pytest fixture to capture print output
caplog: pytest fixture to capture log output
"""
t_logger = logging.getLogger('no_log')
log_ver = LogVer(log_name='no_log')
if log_enabled_arg:
t_logger.setLevel(logging.DEBUG)
else:
t_logger.setLevel(logging.INFO)
log_msg = f'the log_enabled_arg is: {log_enabled_arg}'
log_ver.add_msg(log_msg=log_msg)
t_logger.debug(log_msg)
log_ver.print_match_results(
log_results := log_ver.get_match_results(caplog))
if log_enabled_arg:
log_ver.verify_log_results(log_results)
else:
with pytest.raises(UnmatchedExpectedMessages):
log_ver.verify_log_results(log_results)
expected_result = '\n'
expected_result += '**********************************\n'
expected_result += '* number expected log records: 1 *\n'
if log_enabled_arg:
expected_result += '* number expected unmatched : 0 *\n'
expected_result += '* number actual log records : 1 *\n'
else:
expected_result += '* number expected unmatched : 1 *\n'
expected_result += '* number actual log records : 0 *\n'
expected_result += '* number actual unmatched : 0 *\n'
if log_enabled_arg:
expected_result += '* number matched records : 1 *\n'
else:
expected_result += '* number matched records : 0 *\n'
expected_result += '**********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched expected records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
if not log_enabled_arg:
expected_result += ("('no_log', "
"10, 'the log_enabled_arg is: False')\n")
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched actual records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* matched records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
if log_enabled_arg:
expected_result += ("('no_log', "
"10, 'the log_enabled_arg is: True')\n")
captured = capsys.readouterr().out
assert captured == expected_result
def test_log_verifier_example5(self, capsys: pytest.CaptureFixture[str],
caplog: pytest.CaptureFixture[str]) -> None:
"""Test log_verifier example5 for add_msg.
Args:
capsys: pytest fixture to capture print output
caplog: pytest fixture to capture log output
"""
# add two log messages, each different level
t_logger = logging.getLogger('add_msg')
log_ver = LogVer('add_msg')
log_msg1 = 'hello'
log_msg2 = 'goodbye'
log_ver.add_msg(log_msg=log_msg1)
log_ver.add_msg(log_msg=log_msg2, log_level=logging.ERROR)
t_logger.debug(log_msg1)
t_logger.error(log_msg2)
match_results = log_ver.get_match_results(caplog=caplog)
log_ver.print_match_results(match_results)
log_ver.verify_log_results(match_results)
expected_result = '\n'
expected_result += '**********************************\n'
expected_result += '* number expected log records: 2 *\n'
expected_result += '* number expected unmatched : 0 *\n'
expected_result += '* number actual log records : 2 *\n'
expected_result += '* number actual unmatched : 0 *\n'
expected_result += '* number matched records : 2 *\n'
expected_result += '**********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched expected records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* unmatched actual records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += '\n'
expected_result += '*********************************\n'
expected_result += '* matched records *\n'
expected_result += '* (logger name, level, message) *\n'
expected_result += '*********************************\n'
expected_result += "('add_msg', 10, 'hello')\n"
expected_result += "('add_msg', 40, 'goodbye')\n"
captured = capsys.readouterr().out
assert captured == expected_result