Skip to content

Commit d43d714

Browse files
lukebaumanncopybara-github
authored andcommitted
Add a name parameter to the watchdog context manager.
The name is used in log messages to distinguish different watchdog instances and as the name of the watchdog thread. Changed some tests to use enter_context instead of context managers. PiperOrigin-RevId: 882781955
1 parent cd30e51 commit d43d714

3 files changed

Lines changed: 163 additions & 55 deletions

File tree

pathwaysutils/debug/watchdog.py

Lines changed: 19 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -43,12 +43,17 @@ def _log_thread_stack(thread: threading.Thread):
4343

4444

4545
@contextlib.contextmanager
46-
def watchdog(timeout: float, repeat: bool = True):
46+
def watchdog(
47+
name: str,
48+
timeout: float,
49+
repeat: bool = True,
50+
):
4751
"""Watchdog context manager.
4852
4953
Prints the stack trace of all threads after `timeout` seconds.
5054
5155
Args:
56+
name: The name of the watchdog, used in log messages.
5257
timeout: The timeout in seconds. If the timeout is reached, the stack trace
5358
of all threads will be printed.
5459
repeat: Whether to repeat the watchdog after the timeout. If False, the
@@ -63,7 +68,10 @@ def handler():
6368
count = 0
6469
while not event.wait(timeout):
6570
_logger.debug(
66-
"Watchdog thread dump every %s seconds. Count: %s", timeout, count
71+
"'%s' watchdog thread stack dump every %s seconds. Count: %s",
72+
name,
73+
timeout,
74+
count,
6775
)
6876
try:
6977
for thread in threading.enumerate():
@@ -73,17 +81,22 @@ def handler():
7381
_logger.debug("Error print traceback for thread: %s", thread.ident)
7482
finally:
7583
if not repeat:
76-
_logger.critical("Timeout from watchdog!")
84+
_logger.critical("Timeout from watchdog '%s'", name)
7785
os.abort()
7886

7987
count += 1
8088

81-
_logger.debug("Registering watchdog")
82-
watchdog_thread = threading.Thread(target=handler, name="watchdog")
89+
_logger.debug(
90+
"Registering '%s' watchdog with timeout %s seconds and repeat=%s",
91+
name,
92+
timeout,
93+
repeat,
94+
)
95+
watchdog_thread = threading.Thread(target=handler, name=name)
8396
watchdog_thread.start()
8497
try:
8598
yield
8699
finally:
87100
event.set()
88101
watchdog_thread.join()
89-
_logger.debug("Deregistering watchdog")
102+
_logger.debug("Deregistering '%s' watchdog", name)

pathwaysutils/test/debug/timing_test.py

Lines changed: 20 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -25,14 +25,16 @@
2525
class TimingTest(parameterized.TestCase):
2626

2727
def test_timer_context_manager(self):
28-
with mock.patch.object(
29-
time,
30-
"time",
31-
side_effect=[1, 8.9],
32-
autospec=True,
33-
):
34-
with timing.Timer("test_timer") as timer:
35-
pass
28+
self.enter_context(
29+
mock.patch.object(
30+
time,
31+
"time",
32+
side_effect=[1, 8.9],
33+
autospec=True,
34+
)
35+
)
36+
with timing.Timer("test_timer") as timer:
37+
pass
3638

3739
self.assertEqual(timer.name, "test_timer")
3840
self.assertEqual(timer.start, 1)
@@ -46,14 +48,16 @@ def test_timeit_log(self):
4648
def my_function():
4749
pass
4850

49-
with mock.patch.object(
50-
time,
51-
"time",
52-
side_effect=[1, 8.9, 0], # Third time is used for logging.
53-
autospec=True,
54-
):
55-
with self.assertLogs(timing._logger, logging.DEBUG) as log_output:
56-
my_function()
51+
self.enter_context(
52+
mock.patch.object(
53+
time,
54+
"time",
55+
side_effect=[1, 8.9, 0], # Third time is used for logging.
56+
autospec=True,
57+
)
58+
)
59+
with self.assertLogs(timing._logger, logging.DEBUG) as log_output:
60+
my_function()
5761

5862
self.assertEqual(
5963
log_output.output,

pathwaysutils/test/debug/watchdog_test.py

Lines changed: 124 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -16,79 +16,170 @@
1616
import logging
1717
import sys
1818
import threading
19+
import time
1920
import traceback
2021
from unittest import mock
2122

2223
from absl.testing import absltest
2324
from absl.testing import parameterized
2425
from pathwaysutils.debug import watchdog
2526

27+
2628
class WatchdogTest(parameterized.TestCase):
29+
30+
@parameterized.parameters([
31+
"test",
32+
"loop",
33+
"initialization",
34+
])
35+
def test_watchdog_name(self, watchdog_name):
36+
mock_thread_cls = self.enter_context(
37+
mock.patch.object(threading, "Thread", autospec=True)
38+
)
39+
40+
with watchdog.watchdog(name=watchdog_name, timeout=1):
41+
pass
42+
43+
mock_thread_cls.assert_called_once_with(name=watchdog_name, target=mock.ANY)
44+
2745
def test_watchdog_start_join(self):
28-
with (
29-
mock.patch.object(
30-
threading.Thread,
31-
"start",
32-
autospec=True,
33-
) as mock_start,
34-
mock.patch.object(threading.Thread, "join", autospec=True) as mock_join,
35-
):
36-
with watchdog.watchdog(timeout=1):
37-
mock_start.assert_called_once()
38-
mock_join.assert_not_called()
46+
mock_start = self.enter_context(
47+
mock.patch.object(threading.Thread, "start", autospec=True)
48+
)
49+
mock_join = self.enter_context(
50+
mock.patch.object(threading.Thread, "join", autospec=True)
51+
)
52+
53+
with watchdog.watchdog(name="test", timeout=1):
54+
mock_start.assert_called_once()
55+
mock_join.assert_not_called()
3956

4057
mock_start.assert_called_once()
4158
mock_join.assert_called_once()
4259

43-
@parameterized.named_parameters([
44-
(
45-
"thread 1",
46-
1,
47-
[
60+
@parameterized.named_parameters(
61+
dict(
62+
testcase_name="thread_1",
63+
thread_ident=1,
64+
expected_log_output=[
4865
"DEBUG:pathwaysutils.debug.watchdog:Thread: 1",
4966
"DEBUG:pathwaysutils.debug.watchdog:examplestack1",
5067
],
5168
),
52-
(
53-
"thread 2",
54-
2,
55-
[
69+
dict(
70+
testcase_name="thread_2",
71+
thread_ident=2,
72+
expected_log_output=[
5673
"DEBUG:pathwaysutils.debug.watchdog:Thread: 2",
5774
"DEBUG:pathwaysutils.debug.watchdog:examplestack2",
5875
],
5976
),
60-
(
61-
"thread 3",
62-
3,
63-
[
77+
dict(
78+
testcase_name="thread_3",
79+
thread_ident=3,
80+
expected_log_output=[
6481
"DEBUG:pathwaysutils.debug.watchdog:Thread: 3",
6582
"DEBUG:pathwaysutils.debug.watchdog:",
6683
],
6784
),
68-
])
85+
)
6986
def test_log_thread_strack_succes(self, thread_ident, expected_log_output):
70-
with (
87+
self.enter_context(
7188
mock.patch.object(
7289
sys,
7390
"_current_frames",
7491
return_value={1: ["example", "stack1"], 2: ["example", "stack2"]},
7592
autospec=True,
76-
),
93+
)
94+
)
95+
self.enter_context(
7796
mock.patch.object(
7897
traceback,
7998
"format_stack",
8099
side_effect=lambda stack_str_list: stack_str_list,
81100
autospec=True,
82-
),
83-
):
84-
mock_thread = mock.create_autospec(threading.Thread, instance=True)
85-
mock_thread.ident = thread_ident
101+
)
102+
)
103+
104+
mock_thread = mock.create_autospec(threading.Thread, instance=True)
105+
mock_thread.ident = thread_ident
86106

87-
with self.assertLogs(watchdog._logger, logging.DEBUG) as log_output:
88-
watchdog._log_thread_stack(mock_thread)
107+
with self.assertLogs(watchdog._logger, logging.DEBUG) as log_output:
108+
watchdog._log_thread_stack(mock_thread)
89109

90110
self.assertEqual(log_output.output, expected_log_output)
91111

112+
@parameterized.named_parameters(
113+
dict(
114+
testcase_name="test_logs_1",
115+
name_arg="test_logs_1",
116+
timeout=1,
117+
repeat=False,
118+
expected_log_messages=[
119+
(
120+
"Registering 'test_logs_1' watchdog with timeout 1 seconds"
121+
" and repeat=False"
122+
),
123+
"Deregistering 'test_logs_1' watchdog",
124+
],
125+
),
126+
dict(
127+
testcase_name="test_logs_2",
128+
name_arg="test_logs_2",
129+
timeout=2,
130+
repeat=True,
131+
expected_log_messages=[
132+
(
133+
"Registering 'test_logs_2' watchdog with timeout 2 seconds"
134+
" and repeat=True"
135+
),
136+
"Deregistering 'test_logs_2' watchdog",
137+
],
138+
),
139+
)
140+
def test_watchdog_logs(
141+
self,
142+
name_arg: str,
143+
timeout: float,
144+
repeat: bool,
145+
expected_log_messages: list[str],
146+
):
147+
# Test registration and deregistration logs
148+
with self.assertLogs(watchdog._logger, logging.DEBUG) as log_output:
149+
with watchdog.watchdog(name=name_arg, timeout=timeout, repeat=repeat):
150+
pass
151+
152+
output_messages = [record.getMessage() for record in log_output.records]
153+
self.assertEqual(output_messages, expected_log_messages)
154+
155+
def test_watchdog_timeout_logs(self):
156+
self.enter_context(
157+
mock.patch.object(
158+
threading,
159+
"enumerate",
160+
return_value=[],
161+
autospec=True,
162+
)
163+
)
164+
165+
# Test timeout log
166+
with self.assertLogs(watchdog._logger, logging.DEBUG) as log_output:
167+
with watchdog.watchdog(name="test_logs_timeout", timeout=0.01):
168+
time.sleep(0.02)
169+
170+
output_messages = [record.getMessage() for record in log_output.records]
171+
self.assertIn(
172+
"Registering 'test_logs_timeout' watchdog with timeout 0.01 seconds and"
173+
" repeat=True",
174+
output_messages,
175+
)
176+
177+
self.assertIn(
178+
"'test_logs_timeout' watchdog thread stack dump every 0.01 seconds."
179+
" Count: 0",
180+
output_messages,
181+
)
182+
92183

93184
if __name__ == "__main__":
94185
absltest.main()

0 commit comments

Comments
 (0)